Создадим функцию для подсчета количества строк в таблице, имя которой передается параметром.
=> 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-07-22 23:40:26.247629+03,long_running_function. Stage 1/3... NOTICE: student,2017-07-22 23:40:28.250867+03,long_running_function. Stage 2/3... NOTICE: student,2017-07-22 23:40:31.254073+03,long_running_function. Stage 3/3... NOTICE: student,2017-07-22 23:40:32.256308+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)
Смотрим в журнал сервера:
$ tail -n 20 /var/log/postgresql/postgresql-9.6-main.log | grep long_running_function
2017-07-22 23:40:32 MSK [15037-1] student@plpgsql_debug LOG: student,2017-07-22 23:40:32.296941+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-07-22 23:40:32 MSK [15037-3] student@plpgsql_debug STATEMENT: SELECT long_running_function_2();
2017-07-22 23:40:34 MSK [15037-4] student@plpgsql_debug LOG: student,2017-07-22 23:40:34.299189+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-07-22 23:40:34 MSK [15037-6] student@plpgsql_debug STATEMENT: SELECT long_running_function_2();
2017-07-22 23:40:37 MSK [15037-7] student@plpgsql_debug LOG: student,2017-07-22 23:40:37.303445+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-07-22 23:40:37 MSK [15037-9] student@plpgsql_debug STATEMENT: SELECT long_running_function_2();
2017-07-22 23:40:38 MSK [15037-10] student@plpgsql_debug LOG: student,2017-07-22 23:40:38.305757+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-07-22 23:40:38 MSK [15037-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 15037. Asynchronous notification "dbg" with payload "long_running_function. Stage 2/3..." received from server process with PID 15037. Asynchronous notification "dbg" with payload "long_running_function. Stage 3/3..." received from server process with PID 15037. Asynchronous notification "dbg" with payload "long_running_function. Done." received from server process with PID 15037.
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();
15037 | student | long_running_function. Stage 1/3...
=> \g
15037 | student | long_running_function. Stage 2/3...
=> \g
15037 | student | long_running_function. Stage 3/3...
=> \g
15037 | 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 остались.
Также нужно помнить об очистке таблице log; сделаем это перед запуском.
=> TRUNCATE log;
TRUNCATE TABLE
=> 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 | 23:40:58 | long_running_function. Stage 1/3... student | 23:41:00 | long_running_function. Stage 2/3... student | 23:41:03 | long_running_function. Stage 3/3... student | 23:41:04 | 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
Функция записывает отдельной строкой в файл журнала сообщение, переданное параметром вместе с информацией о том, кто и когда записал строку.
Создадим внешнюю таблицу logfile для чтения файла журнала.
Мы не будем рассматривать механизм работы со сторонними данными, это тема других курсов. Ограничимся коротким примером, показывающим, как связать csv-файл с таблицей при помощи расширения file_fdw.
=> CREATE EXTENSION file_fdw;
CREATE EXTENSION
=> CREATE SERVER logfile FOREIGN DATA WRAPPER file_fdw;
CREATE SERVER
=> CREATE FOREIGN TABLE logfile ( username text, ts timestamp, message text ) SERVER logfile OPTIONS ( filename '/var/lib/postgresql/9.6/main/pg_log/log.txt', format 'csv' );
CREATE FOREIGN TABLE
Создаем новый вариант 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
=> SELECT username, to_char(ts, 'HH24:MI:SS') as ts, message FROM logfile ORDER BY ts;
username | ts | message ----------+----------+------------------------------------- student | 23:41:05 | long_running_function. Stage 1/3... student | 23:41:07 | long_running_function. Stage 2/3... student | 23:41:10 | long_running_function. Stage 3/3... student | 23:41:11 | long_running_function. Done. (4 rows)
Как видим, записи в журнале появились.
Для простоты считаем, что трассировка включается установкой 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)
Информация о выполненных командах окажется в журнале сервера:
$ tail -n 10 /var/log/postgresql/postgresql-9.6-main.log | grep get_count
2017-07-22 23:41:11 MSK [15037-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)
$ tail -n 3 /var/log/postgresql/postgresql-9.6-main.log
2017-07-22 23:41:11 MSK [15037-15] student@plpgsql_debug LOG: duration: 1.611 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
-----------
2885
(1 row)
$ tail -n 9 /var/log/postgresql/postgresql-9.6-main.log
2017-07-22 23:41:11 MSK [15037-16] student@plpgsql_debug LOG: duration: 0.512 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-07-22 23:41:11 MSK [15037-17] student@plpgsql_debug CONTEXT: SQL statement "SELECT COUNT(*) FROM pg_proc"
PL/pgSQL function get_count(text) line 10 at EXECUTE
2017-07-22 23:41:11 MSK [15037-18] student@plpgsql_debug LOG: duration: 0.701 ms plan:
Query Text: SELECT get_count('pg_proc');
Result (cost=0.00..0.26 rows=1 width=8)
Теперь в журнале не только вызов функции, но и вложенный запрос. Вместе с планами выполнения.
Функции write_log и trace используют возможности, которые требуют прав суперпользователя. Как сделать так, чтобы эти функции были доступны обычным пользователям, рассматривается в теме, посвященной разграничению доступа.
Конец демонстрации.