Showing posts with label logs. Show all posts
Showing posts with label logs. Show all posts

March 14, 2009

В ожидании 8.4 - pg_stat_statements

Перевод Waiting for 8.4 - pg_stat_statements с select * from depesz;

4 января Tom Lane применил патч от Takahiro Itagaki, добавляющий новый contrib модуль - pg_stat_statement:

Добавляет contrib/pg_stat_statements для сбора статистики выполнения запросов в рамках всего сервера.

Takahiro Itagaki

Для чего же это? На самом деле это поможет избавиться от некоторых трудностей таким проектам как pgFoouine или мой analyze.pgsql.logs.pl.

В данный момент, если вы хотите увидеть статистику запросов, вам надо логировать их, а затем использовать какое-либо ПО, которое разберёт лог, нормализует запросы и сформирует по ним сводные данные.

Теперь же часть с разбором лога больше не требуется [*].

Вот как это работает.

Во первых, вам потребуется изменить ваш postgresql.conf. Откройте его и найдите параметр shared_preload_libraries. Добавьте туда pg_stat_statements, следующим образом:

shared_preload_libraries = 'pg_stat_statements' # (change requires restart)

Как видно из комментария, изменения требуют перезапуска сервера. Но, перед этим добавим в .conf файл ещё несколько опций:

pg_stat_statements.max = 100
pg_stat_statements.track = top
pg_stat_statements.save = off

Для того чтобы это заработало нам надо добавить "pg_stat_statement" в опцию "custom_variable_classes", которая обычно пустая, но если она у вас уже определена, то просто дополните её вот так:

custom_variable_classes = 'depesz,pg_stat_statements' # list of custom variable class names

Затем можно перезапустить PostgreSQL..

Теперь отслеживание запросов включено, но для просмотра статистики нужно создать соответствующие функции и вью, выполнив pg_stat_statements.sql на любой базе данных:

# \i work/share/postgresql/contrib/pg_stat_statements.sql
SET
CREATE FUNCTION
CREATE FUNCTION
CREATE VIEW
GRANT
REVOKE

(конечно же путь моет быть другим).

Что же, посмотрим как это работает. Первым делом проверим (сразу после коннекта) пустую статистику:

# select * from pg_stat_statements;
userid | dbid | query | calls | total_time | rows
--------+------+-------+-------+------------+------
(0 rows)

И повторим последний запрос:

# select * from pg_stat_statements;
userid | dbid | query | calls | total_time | rows
--------+-------+-----------------------------------+-------+------------+------
10 | 16389 | select * from pg_stat_statements; | 1 | 0.000131 | 0
(1 row)

Вау! Работает.

Теперь очистим статистику (select pg_stat_statements_reset();) и выполним несколько тестов:

(pgdba@[local]:5840) 15:42:41 [pgdba]
# select 1 + 2;
?column?
———-
3
(1 row)

(depesz@[local]:5840) 15:40:39 [depesz]
# select 2 + 3;
?column?
———-
5
(1 row)

(depesz@[local]:5840) 15:43:13 [depesz]
# select count(*) from pg_class where relkind = ‘r’;
count
——-
50
(1 row)

Как же теперь выглядит наша статистика?

# select * from pg_stat_statements;
userid | dbid | query | calls | total_time | rows
--------+-------+----------------------------------------------------+-------+------------+------
16384 | 16388 | select count(*) from pg_class where relkind = 'r'; | 1 | 0.000271 | 1
10 | 16389 | select 1 + 2; | 1 | 1.9e-05 | 1
16384 | 16388 | select 2 + 3; | 1 | 2.2e-05 | 1
10 | 16389 | select pg_stat_statements_reset(); | 1 | 3.3e-05 | 1
(4 rows)

Здорово. И как это будет работать с prepared statements?

# select pg_stat_statements_reset();
pg_stat_statements_reset
--------------------------

(1 row)

# prepare x(int4, int4) as select $1 + $2;
PREPARE
# execute x(1,2);
?column?
----------
3
(1 row)

# execute x(2,3);
?column?
----------
5
(1 row)

(pgdba@[local]:5840) 15:45:54 [pgdba]
# prepare y(int4, int4) as select $1 + $2;
PREPARE

(pgdba@[local]:5840) 15:46:00 [pgdba]
# execute y(3,4);
?column?
———-
7
(1 row)

(pgdba@[local]:5840) 15:46:05 [pgdba]
# select * from pg_stat_statements;
userid | dbid | query | calls | total_time | rows
——–+——-+——————————————+——-+————+——
10 | 16389 | prepare y(int4, int4) as select $1 + $2; | 1 | 1.7e-05 | 1
10 | 16389 | select pg_stat_statements_reset(); | 1 | 3.4e-05 | 1
10 | 16389 | prepare x(int4, int4) as select $1 + $2; | 2 | 3.3e-05 | 2
(3 rows)

Интересно. Смотрится так как будто "prepare" был выполнен столько раз, сколько он был запущен. Не смотря на этот момент - выглядит хорошо.

И так, я настроил pg_stat_statements на хранение 100 различных запросов. Что же случится после сотого? Какой же будет уделён?

Эта простая команда добавит 100 разных запросов:

( echo "SELECT pg_stat_statements_reset();"; for a in $( seq 1 99 ); do echo "select $a;"; done ) | psql

# select count(*) from pg_stat_statements;
count
-------
100
(1 row)

Но "select count(*) from pg_stat_statements" будет также добавлен. Так что, что-то должно быть удалено. Или, может, count(*) не был добавлен к статистике? Давайте проверим:

# select * from pg_stat_statements order by query;
...

Вероятно, pg_stat_statements удаляет случайную запись с наименьшим количеством вызовов. Т.е. в ста записях вызванных по одному разу, мы не сможем найти ту, которая будет удалена, при появлении нового запроса. Но в общем, это не так уж и важно.

В заключении, я думаю, что польза от модуля будет намного больше, если он будет сохранять запросы без параметров (т.е. вместо "select 2 + 3" -> "select $1 + $2", как-то так), иначе, на реальных базах данных, буфер запросов будет заполняться слишком быстро, и не будет заметен факт того, что "select * from table where id = 3" и "select * from table where id = 23" практически одно и тоже [*].

Но, по крайней мере уже есть какой-то аналитический инструмент для небольших систем.

От автора перевода:

Вообще странно, по моему автор оригинала что-то путает, в документации по модулю всё выглядит намного лучше - факт того, что "select * from table where id = 3" и "select * from table where id = 23", будет учитываться, т.е. запросы нормализуются. Кроме того, автор почему-то не упомянул о такой важной вещи как "pg_stat_statements.track = all", отслеживании вложенных запросов, например, внутри функций.

UPD.
Я был не прав - Hubert описал всё верно, неточность в незаконченной документации к версии 8.4. Тут наш с ним небольшой диалог, где он представил объяснение и результаты тестов.

January 31, 2009

В ожидании 8.4 - auto-explain

Перевод Waiting for 8.4 - auto-explain с select * from depesz;

19 ноября Tom Lane применил патч Takahiro Itagaki:
Добавлено расширение auto-explain для автоматического логирования планов медленных запросов
Что оно действительно делает?

Перед тем как я погружусь в детали - небольшое замечание - это первое расширение PostgreSQL (которое я видел) использующее custom_variable_classes GUC.

Конечно же plperl это (GUC) использует, а ещё это используется как временное хранилище между вызовами функций :)

И так, есть 2 способа подключения модуля:
1. LOAD 'auto_explain';
2. shared_preload_libraries = ‘auto_explain’

Первый способ можно использовать в любой сессии (с правами суперюзера), что включит auto-explain только для данной сессии:
# LOAD 'auto_explain';
LOAD
Второй требует правки postgresql.conf, где надо добавить 'auto_explain' в shared_preload_libraries (GUC-переменную).

В этом случае эффект будет для всех сессий.

Так что используем его. Не перепутайте local_preload_libraries и shared_preload_libraries - когда у меня так получилось я не смог запустить PostgreSQL.

После подключения в общем ничего не изменится, всё будет работать как работало до этого, но появится возможность установки доп. переменной:
# set explain.log_min_duration = 5;
что позволит логировать 'explain'
2008-11-23 14:45:14.711 CET depesz@depesz 28352 [local] LOG:  duration: 1003.424 ms  plan:
Result  (cost=0.01..0.03 rows=1 width=0)
InitPlan
->  Result  (cost=0.00..0.01 rows=1 width=0)
2008-11-23 14:45:14.711 CET depesz@depesz 28352 [local] STATEMENT:  select pg_sleep((select 1));
2008-11-23 14:45:14.711 CET depesz@depesz 28352 [local] LOG:  duration: 1005.477 ms  statement: select pg_sleep((select 1));
Последняя строка добавляется из-за ‘log_min_duration_statement’.

Как теперь видно - это очень здорово. Логируется 'explain', но надо учитывать, что если установить нижний порог (explain.log_min_duration) слишком низко, то логи будут расти очень быстро. Планы запросов довольно объёмные.

Дополнительно можно включить логирование "explain analyze", что не очень хорошо, т.к. скажется на производительности, даже если у вас не много запросов выполняющихся дольше explain.log_min_duration.

Причина проста - PostgreSQL вынужден выполнять тайминг всех запросов для того, чтобы иметь возможность вывести результат analyze. Только представьте себе "довесок" от тайминга для сотен запросов в секунду ради пары планов запросов в час.

Ещё одна опция - "explain verbose output" (ознакомиться подробнее можно тут):
# set explain.log_verbose = 1;
SET

# select pg_sleep((select 1));
pg_sleep
----------

(1 row)
Log:
2008-11-23 14:54:48.443 CET depesz@depesz 28812 [local] LOG:  duration: 1001.721 ms  plan:
Result  (cost=0.01..0.03 rows=1 width=0)
Output: pg_sleep(($0)::double precision)
InitPlan
->  Result  (cost=0.00..0.01 rows=1 width=0)
Output: 1
2008-11-23 14:54:48.443 CET depesz@depesz 28812 [local] STATEMENT:  select pg_sleep((select 1));
2008-11-23 14:54:48.443 CET depesz@depesz 28812 [local] LOG:  duration: 1002.139 ms  statement: select pg_sleep((select 1));
Вот, собственно, и всё - хорошее расширение, но будьте с ним осторожны, не забейте весь диск логами...

Замечание от 2010-03-24
Статья была написана до релиза 8.4, с его выходом некоторые вещи могли поменяться, в связи с чем рекомендую также ознакомится с соответствующим разделом документации Appendix F. Additional Supplied Modules - F.2. auto_explain

August 31, 2008

Маленький скрипт для отслеживания логов pg в реальном времени

Если логи вашего pg пишутся в /path/to/pg_log/dir/ и вы хотите отслеживать ошибки в реальном времени попробуйте этот маленький shell-скрипт
#!/bin/bash

cd /path/to/pg_log/dir/;
while true; do
clear;
cat `ls | tail -n 2` | grep ERROR | tail -n 100;
sleep 30;
done

Tiny script for real time pg_log tracking

If your pg-logs are writing to /path/to/pg_log/dir/ and you want to track ERRORs in real time try this tiny shell script
#!/bin/bash

cd /path/to/pg_log/dir/;
while true; do
clear;
cat `ls | tail -n 2` | grep ERROR | tail -n 100;
sleep 30;
done