RAISE

Создадим функцию для подсчета количества строк в таблице, имя которой передается параметром.

=> 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)

Принцип работы. В отладке участвуют два сеанса. В первом выполняется код, который отправляет отладочные сообщения. А второй сеанс получает эти сообщения.

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)


Запись в таблицу: расширение DBLINK

Установим расширение.

=> 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 можно проверить, сколько времени прошло между вызовами.


Запись в файл: pg_file_write()

Установим расширение 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');

Запись в журнал планов запросов: auto_explain

Загрузим расширение в память текущего процесса:

=> 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 используют возможности, которые требуют прав суперпользователя. Как сделать так, чтобы эти функции были доступны обычным пользователям, рассматривается в теме, посвященной разграничению доступа.


Конец демонстрации.