Sysadminium

В этой статье разберём журнал PostgreSQL, а именно как его настраивать, что в него можно записывать и как его анализировать.

Если помните при запуске PostgreSQL, мы указали файл журнала: pg_ctl start -l /home/postgres/logfile.

В этот журнал PostgreSQL записывает некоторые из своих действий. Настраивая журналирование мы можем задать:

• какие действия заносить в журнал;
• насколько подробно описывать эти действия;
• сколько будут хранится файлы журнала и как переключаться на другие файлы.

Если сейчас заглянуть в журнал и посмотреть последние строчки в которых есть слово FATAL, то можно увидеть следующее:

postgres@s-pg13:~$ grep FATAL /home/postgres/logfile | tail
2021-06-28 16:49:47.333 MSK [15360] FATAL:  terminating connection due to administrator command

FATAL: terminating connection due to administrator command – это завершение процесса с помощью функции pg_terminate_backend(pid). Это мы проделывали на прошлом уроке.

За настройку журнала отвечают следующие опции:

• log_destination = можем указать один, или через запятую несколько приёмников:
  • stderr – поток ошибок (в обычном текстовом виде)
  • csvlog – формат CSV (только с коллектором)
  • syslog – писать ошибки в syslog (только для Linux)
  • eventlog – писать ошибки журнал событий Windows (только для Windows)
• logging_collector = (on или off). При включении позволяет собирать дополнительную информацию и никогда не теряет сообщения, в отличие от syslog. При этом запись можно вести в stderr или csvlog. Может стать узким местом, так как после каждого действия записывается журнальная запись и только потом совершается следующее действие.
• log_directory и log_filename – каталог и файл журнала. Следует указывать только если log_destination = stderr.

Что можем записывать в журнал?

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

• log_min_messages – минимальный уровень логирования. Допустимые значения: DEBUG5 – DEBUG1, INFO, NOTICE, WARNINF, ERROR, LOG, FATAL, PANIC. Каждый из перечисленных уровней включает все идущие после него. По умолчанию используется WARNINF;
• log_min_duration_statement – время в миллисекундах. Если команда выполнялась дольше этого времени, то по ней будет запись в журнале. Если установить равное нулю, то абсолютно все команды буду записаны в журнал;
• log_duration – (on или off) записывать время выполнения команд;
• application_name – (on или off) записывать имя приложения;
• log_checkpoints – (on или off) записывать информацию по контрольным точкам;
• log_(dis)connections – (on или off) записывать подключения к серверу и отключения от него;
• log_lock_waits – (on или off) записывать, если сеанс ожидает блокировку дольше, чем указано в deadlock_timeout;
• log_statement – (none, ddl, mod, all) записывать текст выполняемых команд:
  • none – отключено;
  • ddl – CREATE, ALTER, DROP;
  • mod – dll + INSERT, UPDATE, DELETE, TRUNCATE, COPY;
  • all – все команды (кроме команд с синтаксическими ошибками);
• log_temp_files – использование временных файлов. Если процессу не хватило оперативной памяти то он создаст временный файл на диске и будет его использовать. Если это случается то, например можно увеличить параметр workmem.
• и другое.

Ротация жарналов

Если писать все в 1 файл, то постепенно он вырастит до огромных размеров. Поэтому лучше использовать некоторую схему ротации. Следующими параметрами можно настроить ротацию, если мы используем log_destination=stderr:

• log_filename – может принять не просто имя файла, а маску имени. С помощью специальных символов можно указать текущее время;
• log_rotation_age – задает время переключения на следующий файл в минутах;
• log_rotation_size – задает размер файла, при котором нужно переключиться на следующий файл;
• log_truncate_on_rotation – если включить (on) то вы разрешите серверу перезаписывать уже существующие файлы. Если выключить (off) – то файл не будет перезаписываться, записи будут писаться в конец файла.

Комбинируя все выше перечисленное, можно настроить некоторую схему ротации. Например:

• log_filename = postgres-%H.log / log_rotation_age = 1h – 24 файла в сутки;
• log_filename = postgres-%a.log / log_rotation_age = 1d – 7 файлов в неделю.

Анализ журнала

Анализировать журнал можно средствами операционной системы, например: grep, awk и подобными. А также можно использовать pgBadger – это анализатор лога PostgreSQL, но он требует определённых настроек журнала.

Практика

Настроим журнал, чтобы он захватывал все запросы (log_min_duration_statement=0). Дополнительно в качестве префикса укажем “pid=%p“. Затем заставим сервер перечитать конфигурацию и выполним некоторый запрос (SELECT sum(random()) FROM generate_series(1,1000000)). Далее отключимся от сервера и посмотрим журнал:

postgres@s-pg13:~$ psql
Timing is on.
psql (13.3)
Type "help" for help.

postgres@postgres=# ALTER SYSTEM SET log_min_duration_statement=0;
ALTER SYSTEM
Time: 0,972 ms

postgres@postgres=# ALTER SYSTEM SET log_line_prefix='(pid=%p) ';
ALTER SYSTEM
Time: 0,676 ms
postgres@postgres=# SELECT pg_reload_conf();
 pg_reload_conf
----------------
 t
(1 row)
Time: 4,366 ms

postgres@postgres=# SELECT sum(random()) FROM generate_series(1,1000000);
        sum
--------------------
 499542.50257688144
(1 row)
Time: 169,902 ms

postgres@postgres=# \q

postgres@s-pg13:~$ tail /home/postgres/logfile
2021-06-28 12:46:31.109 MSK [13031] ERROR:  syntax error at or near "data_lowlevel" at character 1
2021-06-28 12:46:31.109 MSK [13031] STATEMENT:  data_lowlevel
2021-06-28 15:10:52.758 MSK [29389] LOG:  received SIGHUP, reloading configuration files
2021-06-28 15:10:52.759 MSK [29389] LOG:  parameter "track_io_timing" changed to "on"
2021-06-28 15:10:52.759 MSK [29389] LOG:  parameter "track_functions" changed to "all"
2021-06-28 16:49:47.333 MSK [15360] FATAL:  terminating connection due to administrator command
2021-06-28 17:10:07.701 MSK [29389] LOG:  received SIGHUP, reloading configuration files
2021-06-28 17:10:07.702 MSK [29389] LOG:  parameter "log_min_duration_statement" changed to "0"
(pid=29389) LOG:  parameter "log_line_prefix" changed to "(pid=%p) "
(pid=15653) LOG:  duration: 169.197 ms  statement: SELECT sum(random()) FROM generate_series(1,1000000);

Как видите, теперь в логах есть информация обо всех командах и время, которое они выполнялись!

Более подробно про настройку журнала можете почитать здесь.

---