ИНИЦИАЛИЗАЦИЯ PLPROFILER ~~~~~~~~~~~~~~~~~~~~~~~~ => SHOW shared_preload_libraries; shared_preload_libraries -------------------------------- plprofiler, pg_stat_statements (1 row) => CREATE EXTENSION plprofiler; CREATE EXTENSION plprofiler reset -d plpgsql_debug => SHOW plprofiler.enabled; plprofiler.enabled -------------------- on (1 row) ....................................................................... PLPGSQL_CHECK - ПРОВЕРКА ЗАВИСИМОСТЕЙ ОТ ОБЪЕКТОВ БД ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Установим расширение plpgsql_check: => CREATE EXTENSION plpgsql_check; CREATE EXTENSION ....................................................................... Создадим простую функцию для вывода отладочных сообщений: => CREATE OR REPLACE FUNCTION msg ( message text, destination text DEFAULT 'raise'::text ) RETURNS void AS $$ BEGIN CASE lower(destination) WHEN 'raise' THEN RAISE NOTICE '% % %', user, clock_timestamp(), message; WHEN 'table' THEN INSERT INTO log (username, ts, message) VALUES (user, clock_timestamp(), message); ELSE NULL; END CASE; END; $$ LANGUAGE plpgsql; CREATE FUNCTION Функция может выводить сообщения через RAISE NOTICE или записывать в таблицу log. ....................................................................... Проблема в том, что таблица log не существует. Но это не мешает создать функцию и вызывать её с параметром 'raise': => SELECT msg('Hello, World!'); NOTICE: student 2017-03-14 18:25:25.742448+03 Hello, World! msg ----- (1 row) В некоторых случаях, такая ситуация дает дополнительную гибкость, ведь объекты могут появляться уже после создания или даже во время выполнения функции (благодаря транзакционному DDL). ....................................................................... Но если схема объектов БД статична, то использование несуществующих объектов в функции скорее является ошибкой. Расширение plpgsql_check помогает такие ошибки обнаружить: => SELECT plpgsql_check_function('msg(text,text)'); plpgsql_check_function --------------------------------------------------------------------- error:42P01:7:SQL statement:relation "log" does not exist Query: INSERT INTO log (username, ts, message) -- ^ VALUES (user, clock_timestamp(), message) (4 rows) Такие проверки делают функцию plpgsql_check_function хорошим кандитатом на использование в unit-тестах. => \c plpgsql_debug You are now connected to database "plpgsql_debug" as user "student". ....................................................................... 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 ----------- 335 (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(2); RAISE NOTICE 'long_running_function. Done.'; END; $$ LANGUAGE plpgsql VOLATILE; CREATE FUNCTION ....................................................................... Мы получаем сообщения сразу, а не в конце работы функции. => 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 (message text) RETURNS void AS $$ BEGIN CASE current_setting('app.raise_level') WHEN 'NONE' THEN NULL; WHEN 'NOTICE' THEN RAISE NOTICE '% % %', user, clock_timestamp(), message; WHEN 'DEBUG' THEN RAISE DEBUG '% % %', user, clock_timestamp(), message; WHEN 'LOG' THEN RAISE LOG '% % %', user, clock_timestamp(), message; WHEN 'INFO' THEN RAISE INFO '% % %', user, clock_timestamp(), message; WHEN 'WARNING' THEN RAISE WARNING '% % %', user, clock_timestamp(), message; ELSE NULL; END CASE; END; $$ LANGUAGE plpgsql; CREATE FUNCTION ....................................................................... Выставим параметр конфигурации в NONE и переделаем функцию long_running_function на использование raise_msg: => SET app.raise_level TO 'NONE'; SET => CREATE OR REPLACE FUNCTION long_running_function_1 () 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(2); PERFORM raise_msg('long_running_function. Done.'); END; $$ LANGUAGE plpgsql VOLATILE; CREATE FUNCTION ....................................................................... Теперь в "обычной" жизни (app.raise_level = NONE) отладочные сообщения не будут выдаваться: => SELECT long_running_function_1(); long_running_function_1 ------------------------- (1 row) ....................................................................... Запуская функцию в отдельном сеансе, мы можем получить отладочные сообщения выставив app.raise_level в NOTICE: => SET app.raise_level TO 'NOTICE'; SET => SELECT long_running_function_1(); NOTICE: student 2017-03-14 18:25:39.882127+03 long_running_function. Stage 1/3... NOTICE: student 2017-03-14 18:25:41.884035+03 long_running_function. Stage 2/3... NOTICE: student 2017-03-14 18:25:44.887095+03 long_running_function. Stage 3/3... NOTICE: student 2017-03-14 18:25:46.889696+03 long_running_function. Done. long_running_function_1 ------------------------- (1 row) Важно, что для этого не нужно менять код приложения. ....................................................................... Если же мы хотим включить отладку в приложении с записью в журнал сервера, то переключаем app.raise_level в LOG: => SET app.raise_level TO 'LOG'; SET => SELECT long_running_function_1(); long_running_function_1 ------------------------- (1 row) ....................................................................... Смотрим в журнал сервера: $ tail -n 20 /var/log/postgresql/postgresql-9.6-main.log|grep long_running_function 2017-03-14 18:25:46.904 MSK [11318] student@plpgsql_debug LOG: student 2017-03-14 18:25:46.90397+03 long_running_function. Stage 1/3... SQL statement "SELECT raise_msg('long_running_function. Stage 1/3...')" PL/pgSQL function long_running_function_1() line 3 at PERFORM 2017-03-14 18:25:46.904 MSK [11318] student@plpgsql_debug STATEMENT: SELECT long_running_function_1(); 2017-03-14 18:25:48.906 MSK [11318] student@plpgsql_debug LOG: student 2017-03-14 18:25:48.906493+03 long_running_function. Stage 2/3... SQL statement "SELECT raise_msg('long_running_function. Stage 2/3...')" PL/pgSQL function long_running_function_1() line 6 at PERFORM 2017-03-14 18:25:48.906 MSK [11318] student@plpgsql_debug STATEMENT: SELECT long_running_function_1(); 2017-03-14 18:25:51.910 MSK [11318] student@plpgsql_debug LOG: student 2017-03-14 18:25:51.909974+03 long_running_function. Stage 3/3... SQL statement "SELECT raise_msg('long_running_function. Stage 3/3...')" PL/pgSQL function long_running_function_1() line 9 at PERFORM 2017-03-14 18:25:51.910 MSK [11318] student@plpgsql_debug STATEMENT: SELECT long_running_function_1(); 2017-03-14 18:25:53.912 MSK [11318] student@plpgsql_debug LOG: student 2017-03-14 18:25:53.91242+03 long_running_function. Done. SQL statement "SELECT raise_msg('long_running_function. Done.')" PL/pgSQL function long_running_function_1() line 12 at PERFORM 2017-03-14 18:25:53.912 MSK [11318] student@plpgsql_debug STATEMENT: SELECT long_running_function_1(); ....................................................................... Управляя параметрами app.raise_level, log_min_messages и client_min_messages можно добиться различного поведения отладочных сообщений. Позже мы посмотрим как устанавливать параметры конфигурации для всего приложения, отдельного сеанса или во время работы сеанса. ....................................................................... МЕЖПРОЦЕССНОЕ ВЗАИМОДЕЙСТВИЕ (IPC) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Принцип работы. В отладке участвуют два сеанса. В первом выполянется код, который отправляет отладочные сообщения. А второй сеанс получает эти сообщения. IPC: NOTIFY/LISTEN ~~~~~~~~~~~~~~~~~~ Первый сеанс отправляет сообщения командой NOTIFY, второй сеанс выполняет команду LISTEN для получения этих сообщений. Обе команды используют один и тот же канал 'dbg'. ....................................................................... => CREATE FUNCTION long_running_function_2 () 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(2); NOTIFY dbg, 'long_running_function. Done.'; END; $$ LANGUAGE plpgsql VOLATILE; CREATE FUNCTION ....................................................................... => SELECT long_running_function_2(); | => \i show_listen.sql | Output format is unaligned. | Tuples only is on. | Выполняем LISTEN с паузой в 2 секунды | LISTEN | | LISTEN | | LISTEN | | LISTEN | | LISTEN | Asynchronous notification "dbg" with payload "long_running_function. Stage 1/3..." received from server process with PID 11318. | Asynchronous notification "dbg" with payload "long_running_function. Stage 2/3..." received from server process with PID 11318. | Asynchronous notification "dbg" with payload "long_running_function. Stage 3/3..." received from server process with PID 11318. | Asynchronous notification "dbg" with payload "long_running_function. Done." received from server process with PID 11318. | Output format is aligned. | Tuples only is off. long_running_function_2 ------------------------- (1 row) Команды LISTEN и NOTIFY являются транзакционными. Отсюда две большие проблемы для использования их в отладке. Первая в том, что сообщения отправляются только при фиксации транзакции, а не сразу после выполнения NOTIFY. Поэтому невозможно следить за ходом процесса. ....................................................................... Вторая проблема в том, что если транзакция завершится неуспешно, то сообщения вообще не будут отправлены. => BEGIN; BEGIN => SELECT long_running_function_2(); long_running_function_2 ------------------------- (1 row) => ROLLBACK; ROLLBACK => LISTEN dbg; LISTEN По этим причинам LISTEN и NOTIFY не удобны для отладки. ....................................................................... IPC: РЕАЛИЗАЦИЯ DBMS_PIPE (ПРОЕКТ ORAFCE) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Установим расширение orafce: => CREATE EXTENSION orafce; CREATE EXTENSION И создаем две функции: * trace - аналог команды NOTIFY * listen_trace - аналог команды LISTEN ....................................................................... В trace передаем имя канала отладки и текст сообщения. К сообщению добавим текущее время: => CREATE OR REPLACE FUNCTION trace (channel text, payload text) RETURNS void AS $$ BEGIN PERFORM dbms_pipe.pack_message(payload); PERFORM dbms_pipe.pack_message( to_char(clock_timestamp(),'HH24:MI:SS')::text); PERFORM dbms_pipe.send_message(channel); END; $$ LANGUAGE plpgsql; CREATE FUNCTION ....................................................................... listen_trace слушает указанный канал и выводит через RAISE NOTICE полученные сообщения. Процесс продолжается до тех пор, пока не будет принято сообщение 'stop': => CREATE OR REPLACE FUNCTION listen_trace (channel text) RETURNS void AS $$ DECLARE payload text; ts text; BEGIN LOOP PERFORM dbms_pipe.receive_message(channel); payload := dbms_pipe.unpack_message_text(); ts := dbms_pipe.unpack_message_text(); RAISE NOTICE '%: %', ts, payload; EXIT WHEN lower(payload) = 'stop'; END LOOP; END; $$ LANGUAGE plpgsql; CREATE FUNCTION ....................................................................... Новый вариант long_running_function использует функцию trace: => CREATE FUNCTION long_running_function_3 () RETURNS VOID AS $$ BEGIN PERFORM trace('dbg', 'long_running_function. Stage 1/3...'); PERFORM pg_sleep(2); PERFORM trace('dbg', 'long_running_function. Stage 2/3...'); PERFORM pg_sleep(3); PERFORM trace('dbg', 'long_running_function. Stage 3/3...'); PERFORM pg_sleep(2); PERFORM trace('dbg', 'stop'); END; $$ LANGUAGE plpgsql VOLATILE; CREATE FUNCTION ....................................................................... В первом сеансе запускаем функцию listen_trace, которая начинает ждать сообщения в канал dbg: => SELECT listen_trace('dbg'); ....................................................................... А в другом сеансе запускаем long_running_function_3(): | => SELECT long_running_function_3(); NOTICE: 18:26:10: long_running_function. Stage 1/3... NOTICE: 18:26:12: long_running_function. Stage 2/3... NOTICE: 18:26:15: long_running_function. Stage 3/3... NOTICE: 18:26:17: stop listen_trace -------------- (1 row) | long_running_function_3 | ------------------------- | | (1 row) | Пока функция выполняется, мы можем следить за ходом процесса. ....................................................................... IPC: ПАРАМЕТР APPLICATION_NAME ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Первый сеанс меняет значение параметра application_name, по мере выполнения работы. Второй сеанс переодически опрашивает представление pg_stat_activity. ....................................................................... => CREATE FUNCTION long_running_function_4 () RETURNS VOID AS $$ BEGIN set local application_name = "long_running_function. Stage 1/3..."; PERFORM pg_sleep(2); set local application_name = "long_running_function. Stage 2/3..."; PERFORM pg_sleep(3); set local application_name = "long_running_function. Stage 3/3..."; PERFORM pg_sleep(2); set local application_name = "long_running_function. Done."; END; $$ LANGUAGE plpgsql VOLATILE; CREATE FUNCTION ....................................................................... => SELECT long_running_function_4(); | => \i show_pg_stat_activity.sql | select pid, usename, application_name, pg_sleep(2) | from pg_stat_activity | where datname = 'plpgsql_debug' | and pid <> pg_backend_pid(); | 11318 student long_running_function. Stage 1/3... | 11318 student long_running_function. Stage 2/3... | 11318 student long_running_function. Stage 2/3... | 11318 student long_running_function. Stage 3/3... | 11318 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. Функция открывает новый сеанс, выполняет вставку отдельной транзакцией и закрывает сеанс. Для записи в ts не следует использовать now(), которая внутри транзакции всегда возвращает одинаковое значение. => 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(1); PERFORM write_log('long_running_function. Stage 2/3...'); PERFORM pg_sleep(2); PERFORM write_log('long_running_function. Stage 3/3...'); PERFORM pg_sleep(3); 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 | 18:26:27 | long_running_function. Stage 1/3... student | 18:26:28 | long_running_function. Stage 2/3... student | 18:26:30 | long_running_function. Stage 3/3... student | 18:26:33 | long_running_function. Done. (4 rows) В таблице сохранились все вызовы write_log, по значениям ts можно проверить сколько времени прошло между вызовами. ....................................................................... ЗАПИСЬ В ТАБЛИЦУ: АВТОНОМНЫЕ ТРАНЗАКЦИИ (POSTGRES PRO ENTERPRISE) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Подключимся к Postgres Pro Enterprise: => \x Expanded display is on. => SELECT substr(pgpro_version(),1,20) as pgro_version, pgpro_edition(); -[ RECORD 1 ]-+--------------------- pgro_version | PostgresPro 9.6.2.1 pgpro_edition | enterprise => \x Expanded display is off. ....................................................................... Создаем такую же таблицу для записи сообщений: => CREATE TABLE log ( id serial, username text, ts timestamptz, message text ); CREATE TABLE ....................................................................... Ключевое слово AUTONOMOUS в определении функции говорит о том, что запись в таблицу log выполняется в автономной транзакции: => CREATE FUNCTION write_log (message text) RETURNS void AS $$ BEGIN AUTONOMOUS INSERT INTO log (username, ts, message) VALUES ( user, clock_timestamp(), write_log.message); END; $$ LANGUAGE plpgsql; CREATE FUNCTION ....................................................................... Такой же вариант long_running_function: => CREATE FUNCTION long_running_function_6 () RETURNS void AS $$ BEGIN PERFORM write_log('long_running_function. Stage 1/3...'); PERFORM pg_sleep(1); PERFORM write_log('long_running_function. Stage 2/3...'); PERFORM pg_sleep(2); PERFORM write_log('long_running_function. Stage 3/3...'); PERFORM pg_sleep(3); PERFORM write_log('long_running_function. Done.'); END; $$ LANGUAGE plpgsql; CREATE FUNCTION ....................................................................... Проверяем: => TRUNCATE log; TRUNCATE TABLE => 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 log ORDER BY id; username | ts | message ----------+----------+------------------------------------- postgres | 18:26:33 | long_running_function. Stage 1/3... postgres | 18:26:34 | long_running_function. Stage 2/3... postgres | 18:26:36 | long_running_function. Stage 3/3... postgres | 18:26:39 | long_running_function. Done. (4 rows) В таблице сохранились все вызовы write_log. ....................................................................... ЗАПИСЬ В ФАЙЛ: PG_FILE_WRITE() ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Установим расширение adminpack. => CREATE EXTENSION adminpack; CREATE EXTENSION Теперь создадим функцию для записи в файл. Файл должен располагаться внутри PGDATA, это ограничение pg_file_write(). Если файл журнала должен быть вне PGDATA, то функцию подобную pg_file_write() можно написать на любом недоверенном языке, например plperlU. В любом случае функция будет работать с файловой системой с правами пользователя запустившего экземпляр СУБД. Как правило это postgres. ....................................................................... Функция создается с указанием SECURITY DEFINER чтобы ей могли пользоваться не только суперпользователи. Сразу же отнимем право выполнения у PUBLIC. Имя пользователя получаем функцией session_user, т.к. user и current_user в SECURITY DEFINER функции вернут пользователя создавшего функцию, а не того, кто её вызывает. => 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 SECURITY DEFINER; CREATE FUNCTION => REVOKE EXECUTE ON FUNCTION write_file(text) FROM public; REVOKE ....................................................................... Создадим внешнюю таблицу log, для чтения файла журнала. => 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 ....................................................................... Доступ к функции и таблице выдаем через роль LOGGING. => CREATE ROLE logging NOLOGIN; CREATE ROLE => GRANT EXECUTE ON FUNCTION write_file(text) TO logging; GRANT => GRANT SELECT ON TABLE logfile TO logging; GRANT ....................................................................... Далее работать будем под ролью app, без прав суперпользователя. => \du app List of roles Role name | Attributes | Member of -----------+------------+----------- app | | {} => GRANT logging TO app; GRANT ROLE | => SELECT pl_profiler_collect_data(); | pl_profiler_collect_data | -------------------------- | 0 | (1 row) | | => \c - app localhost | You are now connected to database "plpgsql_debug" as user "app" on host "localhost" at port "5432". ....................................................................... Создаем новый вариант long_running_function. | => CREATE FUNCTION long_running_function_7 () RETURNS void | AS $$ | BEGIN | PERFORM write_file('long_running_function. Stage 1/3...'); | PERFORM pg_sleep(1); | | PERFORM write_file('long_running_function. Stage 2/3...'); | PERFORM pg_sleep(2); | | PERFORM write_file('long_running_function. Stage 3/3...'); | PERFORM pg_sleep(3); | | PERFORM write_file('long_running_function. Done.'); | END; | $$ LANGUAGE plpgsql; | CREATE FUNCTION ....................................................................... Для проверки запустим long_running_function_7 в отдельной транзакции, которую в конце откатим. | => BEGIN; | BEGIN | => SELECT long_running_function_7(); | long_running_function_7 | ------------------------- | | (1 row) | | => ROLLBACK; | ROLLBACK ....................................................................... | => SELECT username, to_char(ts, 'HH24:MI:SS') as ts, message | FROM logfile | ORDER BY ts; | username | ts | message | ----------+----------+------------------------------------- | app | 18:26:39 | long_running_function. Stage 1/3... | app | 18:26:40 | long_running_function. Stage 2/3... | app | 18:26:42 | long_running_function. Stage 3/3... | app | 18:26:45 | long_running_function. Done. | (4 rows) | Как видим, записи в журнале появились. ....................................................................... ЗАПИСЬ В ФАЙЛ: ДРУГИЕ ВАРИАНТЫ. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Для записи в файл можно использовать недоверенные языки, например PL/PerlU. В расширении orafce доступна реализация пакета UTL_FILE. ....................................................................... PL PROFILER ~~~~~~~~~~~ => SELECT pl_profiler_collect_data(); pl_profiler_collect_data -------------------------- 0 (1 row) | => SELECT pl_profiler_collect_data(); | pl_profiler_collect_data | -------------------------- | 0 | (1 row) | ....................................................................... plprofiler report --from-shared --name "Debug Tools Overview" --output "plprofiler_example.html" -d plpgsql_debug ....................................................................... ....................................................................... УСТАНОВКА ПАРАМЕТРОВ КОНФИГУРАЦИИ ДЛЯ ВКЛЮЧЕНИЯ ТРАССИРОВКИ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Сценарии включения трассировки: * Сценарий 1. Трассировка всех процессов * Сценарий 2. Трассировка всех процессов за интервал времени * Сценарий 3. Трассировка новых процессов * Сценарий 4. Трассировка администратором заданного процесса за интервал времени * Сценарий 5. Трассировка пользователем заданного процесса за интервал времени Первые два сценария достаточно очевидны, рассмотрим подробнее 3,4,5. Для простоты считаем, что трассировка включается установкой log_statement='all' ....................................................................... СЦЕНАРИЙ 3. ТРАССИРОВКА НОВЫХ ПРОЦЕССОВ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Обычный пользователь(не superuser) не может установить значение параметра log_statement: | => \c - app localhost | You are now connected to database "plpgsql_debug" as user "app". | => SHOW log_statement; | log_statement | --------------- | none | (1 row) | | => SET log_statement TO 'all'; | ERROR: permission denied to set parameter "log_statement" ....................................................................... Но администратор может выставить параметр для всех новых сеансов этого пользователя: => ALTER ROLE app SET log_statement TO 'all'; ALTER ROLE ....................................................................... | => \c - app localhost | You are now connected to database "plpgsql_debug" as user "app". | => SHOW log_statement; | log_statement | --------------- | all | (1 row) | ....................................................................... Опять же, пользователь не может отключить трассировку: | => SET log_statement TO 'none'; | ERROR: permission denied to set parameter "log_statement" ....................................................................... Для будущих сеансов это делает администратор: => ALTER ROLE app RESET log_statement; ALTER ROLE ....................................................................... СЦЕНАРИЙ 4. ТРАССИРОВКА АДМИНИСТРАТОРОМ ЗАДАННОГО ПРОЦЕССА ЗА ИНТЕРВАЛ ВРЕМЕНИ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Администратор может включить трассировку в отдельно взятом работающем сеансе. Для этого нужно обновить postgresql.conf и попросить перечитать конфигурацию только нужный серверный процесс. ....................................................................... Создадим функцию для отправки сигнала HUP заданному процессу: => CREATE EXTENSION plperl; CREATE EXTENSION => CREATE EXTENSION plperlu; CREATE EXTENSION => CREATE OR REPLACE FUNCTION pg_reload_conf(pid int) RETURNS text AS $$ my $pid = $_[0]; my $output = `kill -HUP $pid`; return($output); $$ LANGUAGE plperlu; CREATE FUNCTION => REVOKE EXECUTE ON FUNCTION pg_reload_conf(int) FROM public; REVOKE => GRANT EXECUTE ON FUNCTION pg_reload_conf(int) TO pg_signal_backend; GRANT Не рекомендуется создавать функции, начинающиеся на "PG_", но для данного примера это уместно. ....................................................................... Запомним PID серверного процесса. => SELECT pid AS pid FROM pg_stat_activity WHERE pid <> pg_backend_pid() \gset ....................................................................... Обновляем конфигурацию через alter system и отправим сигнал HUP процессу пользователя: => ALTER SYSTEM SET log_statement TO 'all'; ALTER SYSTEM => SELECT pg_reload_conf(:pid); pg_reload_conf ---------------- (1 row) ....................................................................... Проверяем в сеансе пользователя: | => SHOW log_statement; | log_statement | --------------- | all | (1 row) | ....................................................................... По окончании трассировки - восстанавливаем конфигурацию: => ALTER SYSTEM RESET log_statement; ALTER SYSTEM => SELECT pg_reload_conf(:pid); pg_reload_conf ---------------- (1 row) ....................................................................... СЦЕНАРИЙ 5. ТРАССИРОВКА ПОЛЬЗОВАТЕЛЕМ ЗАДАННОГО ПРОЦЕССА ЗА ИНТЕРВАЛ ВРЕМЕНИ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Может быть удобным добавить в приложение возможность включения трассировки самими пользователями. Например, по запросу из службы поддержки. Для этого суперпользователь может создать функцию и выдать право выполнения: => CREATE OR REPLACE FUNCTION user_set_config ( name text, setting text, islocal boolean ) RETURNS text AS $$ SELECT set_config(name,setting,islocal); $$ LANGUAGE sql SECURITY DEFINER; CREATE FUNCTION => REVOKE EXECUTE ON FUNCTION user_set_config(text,text,boolean) FROM public; REVOKE => GRANT EXECUTE ON FUNCTION user_set_config(text,text,boolean) TO app; GRANT ....................................................................... Теперь пользователь может сам включить трассировку: | => \c - app localhost | You are now connected to database "plpgsql_debug" as user "app". | => SELECT user_set_config('log_statement','all',false); | user_set_config | ----------------- | all | (1 row) | | => SHOW log_statement; | log_statement | --------------- | all | (1 row) | ....................................................................... ...выполнить ряд команд: | => SELECT get_count('pg_views'); | NOTICE: cmd: SELECT COUNT(*) FROM pg_views | get_count | ----------- | 118 | (1 row) | ....................................................................... ... и выключить трассировку: | => SELECT user_set_config('log_statement','none',false); | user_set_config | ----------------- | none | (1 row) | | => SHOW log_statement; | log_statement | --------------- | none | (1 row) | ....................................................................... Информация о выполненных командах окажется в журнале сервера: $ tail -n 10 /var/log/postgresql/postgresql-9.6-main.log|grep get_count 2017-03-14 18:27:17.760 MSK [12266] app@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 ----------- 68 (1 row) $ tail -n 3 /var/log/postgresql/postgresql-9.6-main.log 2017-03-14 18:27:17.815 MSK [11318] student@plpgsql_debug LOG: duration: 3.349 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 ----------- 3386 (1 row) $ tail -n 9 /var/log/postgresql/postgresql-9.6-main.log 2017-03-14 18:27:17.832 MSK [11318] student@plpgsql_debug LOG: duration: 0.346 ms plan: Query Text: SELECT COUNT(*) FROM pg_proc Aggregate (cost=132.62..132.63 rows=1 width=8) -> Seq Scan on pg_proc (cost=0.00..123.90 rows=3490 width=0) 2017-03-14 18:27:17.832 MSK [11318] student@plpgsql_debug CONTEXT: SQL statement "SELECT COUNT(*) FROM pg_proc" PL/pgSQL function get_count(text) line 10 at EXECUTE 2017-03-14 18:27:17.832 MSK [11318] student@plpgsql_debug LOG: duration: 0.696 ms plan: Query Text: SELECT get_count('pg_proc'); Result (cost=0.00..0.26 rows=1 width=8) SELECT из pg_proc в журнале. ....................................................................... PG_STAT_STATEMENTS ~~~~~~~~~~~~~~~~~~ Расширение было установлено в начале демонстрации. => \dx pg_stat_statements List of installed extensions Name | Version | Schema | Description --------------------+---------+--------+----------------------------------------------------------- pg_stat_statements | 1.4 | public | track execution statistics of all SQL statements executed (1 row) => SHOW shared_preload_libraries; shared_preload_libraries -------------------------------- plprofiler, pg_stat_statements (1 row) ....................................................................... Включено отслеживание вложенных команд: => SHOW pg_stat_statements.track; pg_stat_statements.track -------------------------- all (1 row) ....................................................................... Представление pg_stat_statements содержит подробную информацию о наиболее затратных запросах. 10 самых долгих запросов: => SELECT substr(query,1,50) AS query,calls, total_time, rows FROM pg_stat_statements WHERE dbid = (SELECT oid FROM pg_database WHERE datname = current_database()) ORDER BY total_time DESC LIMIT 10; query | calls | total_time | rows ----------------------------------------------------+-------+------------+------ SELECT pg_sleep(?) | 31 | 71069.595 | 31 SELECT long_running_function_1(); | 3 | 21026.449 | 3 SELECT long_running_function_2(); | 2 | 14014.598 | 2 select pid, usename, application_name, pg_sleep(?) | 5 | 10008.903 | 5 SELECT listen_trace(?); | 1 | 7018.819 | 1 SELECT dbms_pipe.receive_message(channel) | 4 | 7017.047 | 4 SELECT long_running_function(); | 1 | 7010.193 | 1 SELECT long_running_function_3(); | 1 | 7009.885 | 1 SELECT long_running_function_4(); | 1 | 7006.113 | 1 SELECT long_running_function_5(); | 1 | 6036.585 | 1 (10 rows) ....................................................................... Полная информация о запросе №1 из списка: => \x Expanded display is on. => SELECT * FROM pg_stat_statements WHERE dbid = (SELECT oid FROM pg_database WHERE datname = current_database()) ORDER BY total_time DESC LIMIT 1; -[ RECORD 1 ]-------+------------------- userid | 16385 dbid | 34402 queryid | 3240664890 query | SELECT pg_sleep(?) calls | 31 total_time | 71069.595 min_time | 1001.266 max_time | 3003.327 mean_time | 2292.56758064516 stddev_time | 520.446701298945 rows | 31 shared_blks_hit | 0 shared_blks_read | 0 shared_blks_dirtied | 0 shared_blks_written | 0 local_blks_hit | 0 local_blks_read | 0 local_blks_dirtied | 0 local_blks_written | 0 temp_blks_read | 0 temp_blks_written | 0 blk_read_time | 0 blk_write_time | 0 => \x Expanded display is off. .......................................................................