Начиная с версии 9.6 текущие ожидания можно посмотреть в представлении pg_stat_activity, которое показывает информацию о работающих процессах. Выберем только часть полей:
=> SELECT pid, backend_type, wait_event_type, wait_event FROM pg_stat_activity;
pid | backend_type | wait_event_type | wait_event -------+---------------------+-----------------+--------------------- 13214 | background worker | Activity | LogicalLauncherMain 13212 | autovacuum launcher | Activity | AutoVacuumMain 13236 | client backend | | 13210 | background writer | Activity | BgWriterMain 13209 | checkpointer | Activity | CheckpointerMain 13211 | walwriter | Activity | WalWriterMain (6 rows)
Пустые значения говорят о том, что процесс ничего не ждет и выполняет полезную работу.
Чтобы получить более или менее полную картину ожиданий процесса, требуется выполнять семплирование с некоторой частотой. Воспользуемся расширением pg_wait_sampling.
Сервер в виртуальной машине курса уже собран с этим расширением, но его необходимо внести в конфигурационный параметр shared_preload_libraries (что требует перезагрузки сервера).
=> ALTER SYSTEM SET shared_preload_libraries = 'pg_wait_sampling';
ALTER SYSTEM
=> \q
postgres$ pg_ctl -w -l /home/postgres/logfile -D /usr/local/pgsql/data restart
waiting for server to shut down.... done server stopped waiting for server to start.... done server started
student$ psql
Теперь установим расширение в базе данных.
=> CREATE DATABASE locks_memory;
CREATE DATABASE
=> \c locks_memory
You are now connected to database "locks_memory" as user "postgres".
=> CREATE EXTENSION pg_wait_sampling;
CREATE EXTENSION
Расширение позволяет просмотреть некоторую историю ожиданий, которая хранится в кольцевом буфере. Но наиболее интересно увидеть профиль ожиданий - накопленную статистику за все время работы.
Подождем несколько секунд...
=> SELECT * FROM pg_wait_sampling_profile;
pid | event_type | event | queryid | count -------+------------+---------------------+---------+------- 13346 | Activity | WalWriterMain | 0 | 342 13375 | Client | ClientRead | 0 | 4 13344 | IO | SLRUFlushSync | 0 | 1 13347 | Activity | AutoVacuumMain | 0 | 342 13344 | Activity | CheckpointerMain | 0 | 341 13345 | Activity | BgWriterMain | 0 | 343 13344 | IO | DataFileSync | 0 | 1 13400 | Client | ClientRead | 0 | 298 13409 | Client | ClientRead | 0 | 1 13350 | Activity | LogicalLauncherMain | 0 | 343 (10 rows)
Поскольку за прошедшее после запуска сервера время ничего не происходило, основные ожидания относятся к типу Activity (служебные процессы ждут, пока появится работа) и Client (psql ждет, пока пользователь пришлет запрос).
С установками по умолчанию частота семплирования - 100 раз в секунду. Поэтому, чтобы оценить длительность ожиданий в секундах, значение count надо делить на 100.
Чтобы понять, к какому процессу относятся ожидания, добавим к запросу представление pg_stat_activity:
=> SELECT p.pid, a.backend_type, a.application_name AS app, p.event_type, p.event, p.count FROM pg_wait_sampling_profile p LEFT JOIN pg_stat_activity a ON p.pid = a.pid ORDER BY p.pid, p.count DESC;
pid | backend_type | app | event_type | event | count -------+---------------------+------+------------+----------------------+------- 13344 | checkpointer | | Activity | CheckpointerMain | 353 13344 | checkpointer | | IO | DataFileSync | 1 13344 | checkpointer | | IO | SLRUFlushSync | 1 13345 | background writer | | Activity | BgWriterMain | 355 13346 | walwriter | | Activity | WalWriterMain | 354 13347 | autovacuum launcher | | Activity | AutoVacuumMain | 354 13350 | background worker | | Activity | LogicalLauncherMain | 355 13375 | | | Client | ClientRead | 4 13400 | client backend | psql | Client | ClientRead | 309 13400 | client backend | psql | IPC | MessageQueueInternal | 1 13409 | | | Client | ClientRead | 1 (11 rows)
Дадим нагрузку с помощью pgbench и посмотрим, как изменится картина.
student$ pgbench -i locks_memory
NOTICE: table "pgbench_history" does not exist, skipping NOTICE: table "pgbench_tellers" does not exist, skipping NOTICE: table "pgbench_accounts" does not exist, skipping NOTICE: table "pgbench_branches" does not exist, skipping creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.15 s, remaining 0.00 s) vacuum... set primary keys... done.
Сбрасываем собранный профиль в ноль и запускаем тест на 30 секунд в отдельном процессе. Одновременно будем смотреть, как изменяется профиль.
=> SELECT pg_wait_sampling_reset_profile();
pg_wait_sampling_reset_profile -------------------------------- (1 row)
student$ pgbench -T 30 locks_memory
=> SELECT p.pid, a.backend_type, a.application_name AS app, p.event_type, p.event, p.count FROM pg_wait_sampling_profile p LEFT JOIN pg_stat_activity a ON p.pid = a.pid ORDER BY p.pid, p.count DESC;
pid | backend_type | app | event_type | event | count -------+---------------------+---------+------------+---------------------+------- 13344 | checkpointer | | Activity | CheckpointerMain | 202 13345 | background writer | | Activity | BgWriterMain | 202 13346 | walwriter | | Activity | WalWriterMain | 202 13347 | autovacuum launcher | | Activity | AutoVacuumMain | 202 13350 | background worker | | Activity | LogicalLauncherMain | 202 13400 | client backend | psql | Client | ClientRead | 202 13616 | client backend | pgbench | Client | ClientRead | 3 13616 | client backend | pgbench | IO | WALWrite | 1 (8 rows)
=> SELECT p.pid, a.backend_type, a.application_name AS app, p.event_type, p.event, p.count FROM pg_wait_sampling_profile p LEFT JOIN pg_stat_activity a ON p.pid = a.pid ORDER BY p.pid, p.count DESC;
pid | backend_type | app | event_type | event | count -------+---------------------+---------+------------+----------------------+------- 13344 | checkpointer | | Activity | CheckpointerMain | 1395 13345 | background writer | | Activity | BgWriterMain | 1395 13346 | walwriter | | Activity | WalWriterMain | 1395 13347 | autovacuum launcher | | Activity | AutoVacuumMain | 1394 13350 | background worker | | Activity | LogicalLauncherMain | 1395 13400 | client backend | psql | Client | ClientRead | 1394 13400 | client backend | psql | IPC | MessageQueueInternal | 1 13616 | client backend | pgbench | Client | ClientRead | 17 13616 | client backend | pgbench | IO | WALWrite | 7 (9 rows)
=> SELECT p.pid, a.backend_type, a.application_name AS app, p.event_type, p.event, p.count FROM pg_wait_sampling_profile p LEFT JOIN pg_stat_activity a ON p.pid = a.pid ORDER BY p.pid, p.count DESC;
pid | backend_type | app | event_type | event | count -------+---------------------+---------+------------+----------------------+------- 13344 | checkpointer | | Activity | CheckpointerMain | 2590 13345 | background writer | | Activity | BgWriterMain | 2590 13346 | walwriter | | Activity | WalWriterMain | 2590 13347 | autovacuum launcher | | Activity | AutoVacuumMain | 2588 13350 | background worker | | Activity | LogicalLauncherMain | 2590 13400 | client backend | psql | Client | ClientRead | 2588 13400 | client backend | psql | IPC | MessageQueueInternal | 2 13616 | client backend | pgbench | Client | ClientRead | 34 13616 | client backend | pgbench | IO | WALWrite | 13 (9 rows)
Ожидания процесса pgbench будут получаться разными в зависимости от конкретной системы. В нашем случае с большой вероятностью будет представлено ожидание записи журнала (IO/WALWrite), однако большую часть времени процесс не простаивал.
starting vacuum...end. transaction type: <builtin: TPC-B (sort of)> scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 30 s number of transactions actually processed: 28388 latency average = 1.057 ms tps = 946.257553 (including connections establishing) tps = 946.348284 (excluding connections establishing)
Всегда нужно помнить, что отсутствие какого-либо ожидания при семплинге не говорит о том, что ожидания не было. Если оно было короче, чем период семплирования (сотая часть секунды в нашем примере), то могло просто не попасть в выборку.
Поэтому легкие блокировки скорее всего не появились в профиле - но появятся, если собирать данные в течении длительного времени. Чтобы гарантированно посмотреть на них, мы искусственно замедлим работу файловой системы: любая операция ввода-вывода будет занимать 1/10 секунды.
=> \q
postgres$ pg_ctl -w -D /usr/local/pgsql/data stop
waiting for server to shut down.... done server stopped
postgres$ pg_ctl -w -l /home/postgres/logfile -D /usr/local/pgsql-slow/data start
waiting for server to start..... done server started
Снова сбросим профиль и дадим нагрузку.
student$ psql locks_memory
=> SELECT pg_wait_sampling_reset_profile();
pg_wait_sampling_reset_profile -------------------------------- (1 row)
student$ pgbench -T 30 locks_memory
=> SELECT p.pid, a.backend_type, a.application_name AS app, p.event_type, p.event, p.count FROM pg_wait_sampling_profile p LEFT JOIN pg_stat_activity a ON p.pid = a.pid ORDER BY p.pid, p.count DESC;
pid | backend_type | app | event_type | event | count -------+---------------------+---------+------------+---------------------+------- 13823 | checkpointer | | Activity | CheckpointerMain | 201 13824 | background writer | | Activity | BgWriterMain | 201 13825 | walwriter | | IO | WALWrite | 176 13825 | walwriter | | Activity | WalWriterMain | 25 13826 | autovacuum launcher | | Activity | AutoVacuumMain | 201 13829 | background worker | | Activity | LogicalLauncherMain | 201 13856 | client backend | psql | Client | ClientRead | 200 13894 | client backend | pgbench | LWLock | WALWriteLock | 91 13894 | client backend | pgbench | IO | DataFileRead | 1 (9 rows)
=> SELECT p.pid, a.backend_type, a.application_name AS app, p.event_type, p.event, p.count FROM pg_wait_sampling_profile p LEFT JOIN pg_stat_activity a ON p.pid = a.pid ORDER BY p.pid, p.count DESC;
pid | backend_type | app | event_type | event | count -------+---------------------+---------+------------+----------------------+------- 13823 | checkpointer | | Activity | CheckpointerMain | 1380 13824 | background writer | | Activity | BgWriterMain | 1380 13825 | walwriter | | LWLock | WALWriteLock | 792 13825 | walwriter | | Activity | WalWriterMain | 330 13825 | walwriter | | IO | WALWrite | 257 13826 | autovacuum launcher | | Activity | AutoVacuumMain | 1358 13829 | background worker | | Activity | LogicalLauncherMain | 1380 13856 | client backend | psql | Client | ClientRead | 1378 13856 | client backend | psql | IPC | MessageQueueInternal | 1 13894 | | | LWLock | WALWriteLock | 153 13894 | | | IO | WALWrite | 19 13894 | | | IO | DataFileRead | 1 13951 | client backend | pgbench | IO | WALWrite | 587 13951 | client backend | pgbench | LWLock | WALWriteLock | 483 13951 | client backend | pgbench | IO | DataFileExtend | 19 13956 | autovacuum worker | | IO | WALWrite | 464 13956 | autovacuum worker | | LWLock | WALWriteLock | 41 (17 rows)
=> SELECT p.pid, a.backend_type, a.application_name AS app, p.event_type, p.event, p.count FROM pg_wait_sampling_profile p LEFT JOIN pg_stat_activity a ON p.pid = a.pid ORDER BY p.pid, p.count DESC;
pid | backend_type | app | event_type | event | count -------+---------------------+---------+------------+----------------------+------- 13823 | checkpointer | | Activity | CheckpointerMain | 2562 13824 | background writer | | Activity | BgWriterMain | 2562 13825 | walwriter | | LWLock | WALWriteLock | 1408 13825 | walwriter | | IO | WALWrite | 705 13825 | walwriter | | Activity | WalWriterMain | 447 13826 | autovacuum launcher | | Activity | AutoVacuumMain | 2518 13829 | background worker | | Activity | LogicalLauncherMain | 2562 13856 | client backend | psql | Client | ClientRead | 2559 13856 | client backend | psql | IPC | MessageQueueInternal | 2 13894 | | | LWLock | WALWriteLock | 153 13894 | | | IO | WALWrite | 19 13894 | | | IO | DataFileRead | 1 13951 | client backend | pgbench | IO | WALWrite | 1019 13951 | client backend | pgbench | LWLock | WALWriteLock | 981 13951 | client backend | pgbench | IO | DataFileExtend | 19 13956 | autovacuum worker | | IO | DataFileWrite | 926 13956 | autovacuum worker | | IO | WALWrite | 706 13956 | autovacuum worker | | LWLock | WALWriteLock | 41 (18 rows)
Теперь основное ожидание процесса pgbench связано с вводом-выводом, точнее с записью журнала, которая выполняется в синхронном режиме при каждой фиксации. Поскольку (вспомним слайд презентации) запись журнала на диск защищена легкой блокировкой WALWriteLock, она также присутствует в профиле.
starting vacuum...end. transaction type: <builtin: TPC-B (sort of)> scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 30 s number of transactions actually processed: 21 latency average = 1608.846 ms tps = 0.621564 (including connections establishing) tps = 0.621724 (excluding connections establishing)
Конец демонстрации.