Создадим функцию для подсчета количества строк в таблице, имя которой передается параметром.
=> CREATE FUNCTION get_count (tabname text) RETURNS bigint AS $$ DECLARE cmd text; retval bigint; BEGIN cmd := 'SELECT COUNT(*) FROM ' || quote_ident(tabname); RAISE NOTICE 'cmd: %', cmd; EXECUTE cmd INTO retval; RETURN retval; END; $$ LANGUAGE plpgsql STABLE;
CREATE FUNCTION
Для динамического выполнения, текст команды лучше предварительно записывать в переменную. В случае ошибок, можно получить содержимое переменной.
=> SELECT get_count('pg_class');
NOTICE: cmd: SELECT COUNT(*) FROM pg_class
get_count
-----------
316
(1 row)
Строка, начинающаяся с 'NOTICE:', это наша отладочная строка.
RAISE можно использовать для отслеживания хода выполнения долгого запроса.
Предположим, что внутри функции четко выделяются три этапа выполнения И по ходу работы функции мы хотим понимать, где сейчас находимся.
=> CREATE OR REPLACE FUNCTION long_running_function () RETURNS VOID AS $$ BEGIN RAISE NOTICE 'long_running_function. Stage 1/3...'; PERFORM pg_sleep(2); RAISE NOTICE 'long_running_function. Stage 2/3...'; PERFORM pg_sleep(3); RAISE NOTICE 'long_running_function. Stage 3/3...'; PERFORM pg_sleep(1); RAISE NOTICE 'long_running_function. Done.'; END; $$ LANGUAGE plpgsql VOLATILE;
CREATE FUNCTION
Как видим, RAISE выдает сообщения сразу, а не в конце работы функции.
=> SELECT long_running_function();
NOTICE: long_running_function. Stage 1/3... NOTICE: long_running_function. Stage 2/3... NOTICE: long_running_function. Stage 3/3... NOTICE: long_running_function. Done. long_running_function ----------------------- (1 row)
Такой подход удобен, когда можно вызвать функцию в отдельном сеансе. Если же функция вызывается из приложения, то удобнее писать и смотреть в журнал сервера.
Доработаем функцию msg так, чтобы она выдавала сообщения с уровнем, установленным в пользовательском параметре app.raise_level:
=> CREATE OR REPLACE FUNCTION raise_msg (msg text) RETURNS void AS $$ BEGIN CASE current_setting('app.raise_level') WHEN 'NONE' THEN NULL; WHEN 'NOTICE' THEN RAISE NOTICE '%,%,%', user, clock_timestamp(), msg; WHEN 'DEBUG' THEN RAISE DEBUG '%,%,%', user, clock_timestamp(), msg; WHEN 'LOG' THEN RAISE LOG '%,%,%', user, clock_timestamp(), msg; WHEN 'INFO' THEN RAISE INFO '%,%,%', user, clock_timestamp(), msg; WHEN 'WARNING' THEN RAISE WARNING '%,%,%', user, clock_timestamp(), msg; ELSE NULL; END CASE; END; $$ LANGUAGE plpgsql;
CREATE FUNCTION
Предполагается, что параметр app.raise_level всегда установлен. Для этого его можно поместить в postgresql.conf.
Для целей примера, ограничимся установкой параметра прямо в сеансе и переделаем функцию long_running_function на использование raise_msg:
=> SET app.raise_level TO 'NONE';
SET
=> CREATE OR REPLACE FUNCTION long_running_function_2 () RETURNS VOID AS $$ BEGIN PERFORM raise_msg('long_running_function. Stage 1/3...'); PERFORM pg_sleep(2); PERFORM raise_msg('long_running_function. Stage 2/3...'); PERFORM pg_sleep(3); PERFORM raise_msg('long_running_function. Stage 3/3...'); PERFORM pg_sleep(1); PERFORM raise_msg('long_running_function. Done.'); END; $$ LANGUAGE plpgsql VOLATILE;
CREATE FUNCTION
Теперь в "обычной" жизни (app.raise_level = NONE) отладочные сообщения не будут выдаваться:
=> SELECT long_running_function_2();
long_running_function_2 ------------------------- (1 row)
Запуская функцию в отдельном сеансе, мы можем получить отладочные сообщения, выставив app.raise_level в NOTICE:
=> SET app.raise_level TO 'NOTICE';
SET
=> SELECT long_running_function_2();
NOTICE: student,2017-09-01 15:52:43.99756+03,long_running_function. Stage 1/3... NOTICE: student,2017-09-01 15:52:45.999871+03,long_running_function. Stage 2/3... NOTICE: student,2017-09-01 15:52:49.001513+03,long_running_function. Stage 3/3... NOTICE: student,2017-09-01 15:52:50.003807+03,long_running_function. Done. long_running_function_2 ------------------------- (1 row)
Если же мы хотим включить отладку в приложении с записью в журнал сервера, то переключаем app.raise_level в LOG:
=> SET app.raise_level TO 'LOG';
SET
=> SELECT long_running_function_2();
long_running_function_2 ------------------------- (1 row)
Смотрим в журнал сервера:
student$ tail -n 20 /var/log/postgresql/postgresql-9.6-main.log | grep long_running_function
2017-09-01 15:52:50 MSK [22566-1] student@plpgsql_debug LOG: student,2017-09-01 15:52:50.099504+03,long_running_function. Stage 1/3...
SQL statement "SELECT raise_msg('long_running_function. Stage 1/3...')"
PL/pgSQL function long_running_function_2() line 3 at PERFORM
2017-09-01 15:52:50 MSK [22566-3] student@plpgsql_debug STATEMENT: SELECT long_running_function_2();
2017-09-01 15:52:52 MSK [22566-4] student@plpgsql_debug LOG: student,2017-09-01 15:52:52.102837+03,long_running_function. Stage 2/3...
SQL statement "SELECT raise_msg('long_running_function. Stage 2/3...')"
PL/pgSQL function long_running_function_2() line 6 at PERFORM
2017-09-01 15:52:52 MSK [22566-6] student@plpgsql_debug STATEMENT: SELECT long_running_function_2();
2017-09-01 15:52:55 MSK [22566-7] student@plpgsql_debug LOG: student,2017-09-01 15:52:55.106172+03,long_running_function. Stage 3/3...
SQL statement "SELECT raise_msg('long_running_function. Stage 3/3...')"
PL/pgSQL function long_running_function_2() line 9 at PERFORM
2017-09-01 15:52:55 MSK [22566-9] student@plpgsql_debug STATEMENT: SELECT long_running_function_2();
2017-09-01 15:52:56 MSK [22566-10] student@plpgsql_debug LOG: student,2017-09-01 15:52:56.108497+03,long_running_function. Done.
SQL statement "SELECT raise_msg('long_running_function. Done.')"
PL/pgSQL function long_running_function_2() line 12 at PERFORM
2017-09-01 15:52:56 MSK [22566-12] student@plpgsql_debug STATEMENT: SELECT long_running_function_2();
Управляя параметрами app.raise_level, log_min_messages и client_min_messages, можно добиться различного поведения отладочных сообщений.
Важно, что для этого не нужно менять код приложения.
Принцип работы. В отладке участвуют два сеанса. В первом выполняется код, который отправляет отладочные сообщения. А второй сеанс получает эти сообщения.
IPC: notify/listen
Первый сеанс отправляет сообщения командой NOTIFY, второй сеанс выполняет команду LISTEN для получения этих сообщений. Обе команды используют один и тот же канал dbg.
=> CREATE FUNCTION long_running_function_3 () RETURNS VOID AS $$ BEGIN NOTIFY dbg, 'long_running_function. Stage 1/3...'; PERFORM pg_sleep(2); NOTIFY dbg, 'long_running_function. Stage 2/3...'; PERFORM pg_sleep(3); NOTIFY dbg, 'long_running_function. Stage 3/3...'; PERFORM pg_sleep(1); NOTIFY dbg, 'long_running_function. Done.'; END; $$ LANGUAGE plpgsql VOLATILE;
CREATE FUNCTION
В первом сеансе запускаем функцию:
=> SELECT long_running_function_3();
Во втором сеансе выполняем LISTEN с паузой в 2 секунды
=> LISTEN dbg;
LISTEN
=> LISTEN dbg;
LISTEN
=> LISTEN dbg;
LISTEN
=> LISTEN dbg;
LISTEN Asynchronous notification "dbg" with payload "long_running_function. Stage 1/3..." received from server process with PID 22566. Asynchronous notification "dbg" with payload "long_running_function. Stage 2/3..." received from server process with PID 22566. Asynchronous notification "dbg" with payload "long_running_function. Stage 3/3..." received from server process with PID 22566. Asynchronous notification "dbg" with payload "long_running_function. Done." received from server process with PID 22566.
long_running_function_3 ------------------------- (1 row)
Примечание. Команда сервера LISTEN выдает сообщения именно в таком формате.
Команды LISTEN и NOTIFY являются транзакционными. Отсюда две большие проблемы для их применения в отладке.
Первая в том, что сообщения отправляются только при фиксации транзакции, а не сразу после выполнения NOTIFY. Поэтому невозможно следить за ходом процесса.
Вторая проблема в том, что если транзакция завершится неуспешно, то сообщения вообще не будут отправлены.
=> BEGIN;
BEGIN
=> SELECT long_running_function_3();
long_running_function_3 ------------------------- (1 row)
=> ROLLBACK;
ROLLBACK
=> LISTEN dbg;
LISTEN
По этим причинам LISTEN и NOTIFY неудобны для отладки.
IPC: Параметр application_name
Первый сеанс меняет значение параметра application_name. Второй сеанс периодически опрашивает представление pg_stat_activity.
Новый вариант функции:
=> CREATE FUNCTION long_running_function_4 () RETURNS VOID AS $$ BEGIN SET LOCAL application_name TO "long_running_function. Stage 1/3..."; PERFORM pg_sleep(2); SET LOCAL application_name TO "long_running_function. Stage 2/3..."; PERFORM pg_sleep(3); SET LOCAL application_name TO "long_running_function. Stage 3/3..."; PERFORM pg_sleep(1); SET LOCAL application_name TO "long_running_function. Done."; END; $$ LANGUAGE plpgsql VOLATILE;
CREATE FUNCTION
Запускаем в первом сеансе:
=> SELECT long_running_function_4();
Во втором с паузой в 2 секунду обновляем строку из pg_stat_activity:
=> select pid, usename, application_name from pg_stat_activity where datname = 'plpgsql_debug' and pid <> pg_backend_pid();
22566 | student | long_running_function. Stage 1/3...
=> \g
22566 | student | long_running_function. Stage 2/3...
=> \g
22566 | student | long_running_function. Stage 3/3...
=> \g
22566 | student | psql
long_running_function_4 ------------------------- (1 row)
Установим расширение.
=> CREATE EXTENSION dblink;
CREATE EXTENSION
Создаем таблицу для записи сообщений.
В таблице полезно сохранять информацию о пользователе и времени вставки. Столбец id нужен для гарантированной сортировки результата в порядке добавления строк.
=> CREATE TABLE log ( id serial, username text, ts timestamptz, message text );
CREATE TABLE
Теперь создадим функцию для удобного добавления записей в таблицу log. Функция открывает новый сеанс, выполняет вставку отдельной транзакцией и закрывает сеанс.
=> CREATE FUNCTION write_log (message text) RETURNS void AS $$ DECLARE cmd text; BEGIN PERFORM dblink_connect('dbname=' || current_database()); cmd := 'INSERT INTO log (username, ts, message) VALUES (' || quote_literal(user) || ', ' || quote_literal(clock_timestamp()::text) || '::timestamp, ' || quote_literal(write_log.message) || ')'; PERFORM dblink_exec (cmd); PERFORM dblink_disconnect(); END; $$ LANGUAGE plpgsql;
CREATE FUNCTION
Создаем новый вариант long_running_function.
=> CREATE FUNCTION long_running_function_5 () RETURNS void AS $$ BEGIN PERFORM write_log('long_running_function. Stage 1/3...'); PERFORM pg_sleep(2); PERFORM write_log('long_running_function. Stage 2/3...'); PERFORM pg_sleep(3); PERFORM write_log('long_running_function. Stage 3/3...'); PERFORM pg_sleep(1); PERFORM write_log('long_running_function. Done.'); END; $$ LANGUAGE plpgsql;
CREATE FUNCTION
Для проверки запустим long_running_function_5 в отдельной транзакции, которую в конце откатим. Убедимся, что записи в таблице log остались.
=> BEGIN;
BEGIN
=> SELECT long_running_function_5();
long_running_function_5 ------------------------- (1 row)
=> ROLLBACK;
ROLLBACK
=> SELECT username, to_char(ts, 'HH24:MI:SS') as ts, message FROM log ORDER BY id;
username | ts | message ----------+----------+------------------------------------- student | 15:53:17 | long_running_function. Stage 1/3... student | 15:53:19 | long_running_function. Stage 2/3... student | 15:53:22 | long_running_function. Stage 3/3... student | 15:53:23 | long_running_function. Done. (4 rows)
В таблице сохранились все вызовы write_log, по значениям ts можно проверить, сколько времени прошло между вызовами.
Установим расширение adminpack.
=> CREATE EXTENSION adminpack;
CREATE EXTENSION
Теперь создадим функцию write_file, которая будет записывать отладочную информацию в файл. Файл должен располагаться внутри PGDATA, это ограничение pg_file_write().
Если файл журнала должен быть вне PGDATA, то функцию, подобную pg_file_write(), можно написать на любом недоверенном языке, например plperlU. В любом случае функция будет работать с файловой системой с правами пользователя, запустившего экземпляр СУБД. Как правило это postgres.
=> CREATE FUNCTION write_file (message text) RETURNS void AS $$ DECLARE filename CONSTANT text := '/var/lib/postgresql/9.6/main/pg_log/log.txt'; line text; BEGIN line := session_user || ',' || clock_timestamp()::text || ',' || write_file.message || chr(10); PERFORM pg_file_write(filename, line, true); END; $$ LANGUAGE plpgsql;
CREATE FUNCTION
Функция записывает отдельной строкой в файл журнала сообщение, переданное параметром вместе с информацией о том, кто и когда записал строку.
Создаем новый вариант long_running_function.
=> CREATE FUNCTION long_running_function_6 () RETURNS void AS $$ BEGIN PERFORM write_file('long_running_function. Stage 1/3...'); PERFORM pg_sleep(2); PERFORM write_file('long_running_function. Stage 2/3...'); PERFORM pg_sleep(3); PERFORM write_file('long_running_function. Stage 3/3...'); PERFORM pg_sleep(1); PERFORM write_file('long_running_function. Done.'); END; $$ LANGUAGE plpgsql;
CREATE FUNCTION
Для проверки запустим long_running_function_6 в отдельной транзакции, которую в конце откатим.
=> BEGIN;
BEGIN
=> SELECT long_running_function_6();
long_running_function_6 ------------------------- (1 row)
=> ROLLBACK;
ROLLBACK
postgres$ cat $PGDATA/pg_log/log.txt
student,2017-09-01 15:53:23.403694+03,long_running_function. Stage 1/3... student,2017-09-01 15:53:25.408346+03,long_running_function. Stage 2/3... student,2017-09-01 15:53:28.411403+03,long_running_function. Stage 3/3... student,2017-09-01 15:53:29.414015+03,long_running_function. Done.
Как видим, записи в журнале появились. Но нужно помнить, что по умолчанию доступ к файлу есть только у пользователя postgres операционной системы.
Для простоты считаем, что трассировка включается установкой log_statement='all'.
Сделаем простую функцию для включения/отключения трассировки:
=> CREATE OR REPLACE FUNCTION trace (mode text) RETURNS text AS $$ DECLARE retval text; BEGIN IF mode = 'ON' THEN SELECT set_config('log_statement', 'all', false) INTO retval; ELSIF mode = 'OFF' THEN SELECT set_config('log_statement', 'none', false) INTO retval; END IF; RETURN retval; END; $$ LANGUAGE plpgsql;
CREATE FUNCTION
Теперь мы можем включить трассировку:
=> SELECT trace('ON');
trace ------- all (1 row)
...выполнить команды:
=> SELECT get_count('pg_views');
NOTICE: cmd: SELECT COUNT(*) FROM pg_views
get_count
-----------
115
(1 row)
... и выключить трассировку:
=> SELECT trace('OFF');
trace ------- none (1 row)
Информация о выполненных командах окажется в журнале сервера:
student$ tail -n 10 /var/log/postgresql/postgresql-9.6-main.log | grep get_count
2017-09-01 15:53:29 MSK [22566-13] student@plpgsql_debug LOG: statement: SELECT get_count('pg_views');
Загрузим расширение в память текущего процесса:
=> LOAD 'auto_explain';
LOAD
Установим отслеживание всех команд:
=> SET auto_explain.log_min_duration = 0;
SET
Выполним функцию get_count, в журнал сервера попадет команда и план выполнения:
=> SELECT get_count('pg_tables');
NOTICE: cmd: SELECT COUNT(*) FROM pg_tables
get_count
-----------
63
(1 row)
student$ tail -n 3 /var/log/postgresql/postgresql-9.6-main.log
2017-09-01 15:53:29 MSK [22566-15] student@plpgsql_debug LOG: duration: 1.419 ms plan:
Query Text: SELECT get_count('pg_tables');
Result (cost=0.00..0.26 rows=1 width=8)
Но вложенный в функцию SELECT не попал в журнал.
Включим отслеживание вложенных команд и повторим запрос:
=> SET auto_explain.log_nested_statements = on;
SET
=> SELECT get_count('pg_proc');
NOTICE: cmd: SELECT COUNT(*) FROM pg_proc
get_count
-----------
2883
(1 row)
student$ tail -n 9 /var/log/postgresql/postgresql-9.6-main.log
2017-09-01 15:53:30 MSK [22566-16] student@plpgsql_debug LOG: duration: 0.984 ms plan:
Query Text: SELECT COUNT(*) FROM pg_proc
Aggregate (cost=94.37..94.38 rows=1 width=8)
-> Index Only Scan using pg_proc_oid_index on pg_proc (cost=0.28..87.21 rows=2862 width=0)
2017-09-01 15:53:30 MSK [22566-17] student@plpgsql_debug CONTEXT: SQL statement "SELECT COUNT(*) FROM pg_proc"
PL/pgSQL function get_count(text) line 10 at EXECUTE
2017-09-01 15:53:30 MSK [22566-18] student@plpgsql_debug LOG: duration: 1.559 ms plan:
Query Text: SELECT get_count('pg_proc');
Result (cost=0.00..0.26 rows=1 width=8)
Теперь в журнале не только вызов функции, но и вложенный запрос. Вместе с планами выполнения.
Функции write_log и trace используют возможности, которые требуют прав суперпользователя. Как сделать так, чтобы эти функции были доступны обычным пользователям, рассматривается в теме, посвященной разграничению доступа.
Конец демонстрации.