Уровень 3.0

Предусловия:

Изучена лекция «Запись грязных страниц»

Запись грязных страниц

Откройте терминал и подключитесь в psql к базе данных postgres c ролью postgres:

[student@pkles-gt0040964 ~]$ sudo -iu postgres

-bash-4.4$ psql

psql (15.5)
Введите "help", чтобы получить справку.

Создайте базу данных pgbench_db и подключитесь к ней:

postgres=# CREATE DATABASE pgbench_db;

CREATE DATABASE

postgres=# \c pgbench_db

Вы подключены к базе данных "pgbench_db" как пользователь "postgres".

Создайте расширение pg_buffercache:
```
pgbench_db=# CREATE EXTENSION pg_buffercache;
```
```
CREATE EXTENSION
```
Расширение pg_buffercache позволяет посмотреть содержимое кеша буферов.
Создайте расширение pg_walinspect:
```
pgbench_db=# CREATE EXTENSION pg_walinspect;
```
```
CREATE EXTENSION
```
Расширение pg_walinspect позволяет посмотреть содержимое записей WAL.
Установите значение параметра checkpoint_timeout в 1 час:
```
pgbench_db=# ALTER SYSTEM SET checkpoint_timeout = '1h';
```
```
ALTER SYSTEM
```
```
pgbench_db=# SELECT pg_reload_conf();
```
```
 pg_reload_conf
----------------
 t
(1 строка)
```
Значение параметра checkpoint_timeout по умолчанию составляет 5 минут. Столь частое срабатывание контрольных точек может мешать проведению экспериментов. Поэтому временно увеличим значение данного параметра до 1 часа.
Откройте второй терминал и перейдите в режим выполнения команд от имени пользователя postgres:
```
[student@pkles-gt0041054 ~]$ sudo -iu postgres
-bash-4.4$
```
Во втором сеансе поменяйте язык выводимых сообщений на английский:
```
-bash-4.4$ export LC_MESSAGES=en_US.UTF-8
```
Смена языка сообщений потребовалась для удобства интерпретации вывода утилиты pg_controldata, которая будет использована в лабораторной работе для просмотра содержимого файла pg_control.

Выполнение контрольной точки

Во втором сеансе инициализируйте и выполните 30-секундный тест pgbench:

-bash-4.4$ pgbench -i pgbench_db

dropping old tables...
NOTICE:  table "pgbench_accounts" does not exist, skipping
NOTICE:  table "pgbench_branches" does not exist, skipping
NOTICE:  table "pgbench_history" does not exist, skipping
NOTICE:  table "pgbench_tellers" does not exist, skipping
creating tables...
generating data (client-side)...
100000 of 100000 tuples (100%) done (elapsed 0.01 s, remaining 0.00 s)
vacuuming...
creating primary keys...
done in 0.27 s (drop tables 0.00 s, create tables 0.01 s, client-side generate 0.11 s, vacuum 0.05 s, primary keys 0.10 s).

-bash-4.4$ pgbench -T 30 pgbench_db

pgbench (15.5)
starting vacuum...end.
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 1
query mode: simple
number of clients: 1
number of threads: 1
maximum number of tries: 1
duration: 30 s
number of transactions actually processed: 25453
number of failed transactions: 0 (0.000%)
latency average = 1.178 ms
initial connection time = 4.668 ms
tps = 848.552385 (without initial connection time)

В первом сеансе проверьте, сколько грязных страниц находится в кеше буферов:
```
pgbench_db=# SELECT count(*) not_empty_buffers, count(*) FILTER (WHERE isdirty) dirty_buffers
FROM pg_buffercache
WHERE usagecount IS NOT NULL;
```
```
 not_empty_buffers | dirty_buffers
-------------------+---------------
              4495 |          2169
(1 строка)
```
Количество грязных страниц в кеше оценено с использованием расширения pg_buffercache.

Всего в кеше сейчас 4495 (not_empty_buffers) страниц, из которых 2169 грязных (dirty_buffers).
В первом сеансе сохраните текущую позицию вставки в журнал WAL в переменной psql:
```
pgbench_db=# SELECT pg_current_wal_insert_lsn() AS before_insert_lsn \gset
```
```
pgbench_db=#  \echo :before_insert_lsn
```
```
0/14FF0B98
```
Вспомним, что позиция вставки — это LSN следующей новой записи в журнале WAL.
В первом сеансе выполните вручную контрольную точку и сохраните текущую позицию вставки в переменной psql:
```
pgbench_db=# CHECKPOINT;
```
```
CHECKPOINT
```
```
pgbench_db=# SELECT pg_current_wal_insert_lsn() AS after_insert_lsn \gset
```
```
pgbench_db=# \echo :after_insert_lsn
```
```
0/150AD3C0
```
Контрольная точка выполнена вручную. Автоматическое выполнение контрольных точек пока фактически отключено (checkpoint_timeout = 1 час).
В первом сеансе посмотрите, сколько осталось грязных буферов в кеше буферов:
```
pgbench_db=# SELECT count(*) not_empty_buffers, count(*) FILTER (WHERE isdirty) dirty_buffers
FROM pg_buffercache
WHERE usagecount IS NOT NULL;
```
```
 not_empty_buffers | dirty_buffers
-------------------+---------------
              4496 |             0
(1 строка)
```
Как и ожидалось, после выполнения контрольной точки грязных буферов в кеше не осталось.

При этом они были не вытеснены из кеша (общее количество страниц в кеше осталось прежним), а только сброшены на накопители.

В первом сеансе посмотрите, появилась ли в журнале WAL запись о контрольной точке:

pgbench_db=# SELECT start_lsn, resource_manager, record_type, record_length, description
FROM pg_get_wal_records_info(:'before_insert_lsn', :'after_insert_lsn')
WHERE record_type ~ 'CHECKPOINT'\gx

-[ RECORD 1 ]----+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
start_lsn        | 0/14FF0BE0
resource_manager | XLOG
record_type      | CHECKPOINT_ONLINE
record_length    | 148
description      | redo 0/14FF0B98; tli 1; prev tli 1; fpw true; xid 364511; oid 24681; multi 1; offset 0; oldest xid 770 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 364511; online

Для просмотра журнала была использована функция pg_get_wal_records_info расширения pg_walinspect.

После завершения контрольной точки в журнал была добавлена запись типа CHECKPOINT_ONLINE, LSN которой '0/14FF0BE0'.

А в поле description записан LSN, соответствующий началу контрольной точки (redo 0/14FF0B98).

Во втором сеансе посмотрите содержимое файла pg_control:
```
-bash-4.4$ pg_controldata -D /pgdata/\{pangolin-version\}/data/ | head
```
```
pg_control version number:            1300
Catalog version number:               202409231
Database system identifier:           7538415936932818542
Database cluster state:               in production
pg_control last modified:             Ср 20 авг 2025 17:00:13
Latest checkpoint location:           0/14FF0BE0
Latest checkpoint's REDO location:    0/14FF0B98
Latest checkpoint's REDO WAL file:    000000010000000000000014
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
```
После завершения контрольной точки информация о ней также была записана в файле pg_control, используемом при восстановлении после сбоя.

LSN записи в журнале о контрольной точке указан в поле Latest checkpoint location, а LSN начала контрольной точки — в поле Latest checkpoint's REDO location.

Вспомним, что для восстановления после сбоя требуются записи WAL с начала последней завершенной контрольной точки.

Выполнение восстановления

В первом сеансе посмотрите содержимое таблицы pgbench_branches:
```
pgbench_db=# SELECT * FROM pgbench_branches;
```
```
 bid | bbalance | filler
-----+----------+--------
   1 |   633477 |
(1 строка)
```
В таблице pgbench_branches одна строка. Вставим еще одну.
В первом сеансе вставьте еще одну строку в таблицу pgbench_branches:
```
pgbench_db=# INSERT INTO pgbench_branches VALUES (2, 1000, 'Страница с этой строкой находится только в оперативной памяти перед сбоем');
```
```
INSERT 0 1
```
Вставленная строка в настоящий момент находится в странице, расположенной только в кеше буферов. Контрольные точки не выполняются, других обслуживающих процессов, которые могли бы ее вытеснить, также нет.

Обратите внимание: даже в этом случае страница теоретически может быть сброшена в накопитель процессом фоновой записи. Однако, при отсутствии других обслуживающих процессов и наличии свободных буферов в кеше буферов, этого не должно произойти. Ведь для записи грязной страницы процессом фоновой записи нужно, чтобы значение параметра usage count в заголовке буфера равнялось 0. В свою очередь значение usage count снижается алгоритмом вытеснения страниц (clock sweep), который не должен быть использован при наличии свободных буферов.
Во втором сеансе сымитируйте сбой:
```
-bash-4.4$ pg_ctl stop -m immediate
```
```
waiting for server to shut down.... done
server stopped
```
Сбой сымитирован путем остановки экземпляра в режиме immediate. В данном режиме немедленно прерываются все серверные процессы без выполнения процедуры штатной остановки, в том числе без выполнения контрольной точки.
Во втором сеансе проверьте состояние кластера в файле pg_control и при помощи утилиты pg_ctl:
```
-bash-4.4$ pg_controldata -D /pgdata/\{pangolin-version\}/data/ | head -n 4
```
```
pg_control version number:            1300
Catalog version number:               202409231
Database system identifier:           7538415936932818542
Database cluster state:               in production
```
```
-bash-4.4$ pg_ctl status
```
```
pg_ctl: no server running
```
В файле pg_control состояние кластера по-прежнему in production, в то время как утилита pg_ctl сообщает, что экземпляр не запущен.

При запуске процесс startup увидит в файле pg_control состояние in production и поймет, что произошел сбой, после чего начнет процедуру восстановления с использованием журнала WAL.

Во втором сеансе запустите экземпляр:

-bash-4.4$ pg_ctl start -l logfile

waiting for server to start.... done
server started

Во втором сеансе посмотрите содержимое журнала сообщений:
```
-bash-4.4$ tail logfile
```
```
2025-08-20 17:33:27.723 MSK [79369] LOG:  database system was not properly shut down; automatic recovery in progress
2025-08-20 17:33:27.726 MSK [79369] LOG:  redo starts at 0/14FF0B98
2025-08-20 17:33:27.729 MSK [79369] LOG:  invalid record length at 0/150AD678: wanted 26, got 0
2025-08-20 17:33:27.729 MSK [79369] LOG:  redo done at 0/150AD628 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2025-08-20 17:33:27.733 MSK [79367] LOG:  checkpoint starting: end-of-recovery immediate wait
2025-08-20 17:33:27.751 MSK [79367] LOG:  checkpoint complete: wrote 105 buffers (0.6%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.006 s, sync=0.004 s, total=0.020 s; sync files=17, longest=0.002 s, average=0.001 s; distance=754 kB, estimate=754 kB
2025-08-20 17:33:27.757 MSK [79363] LOG:  database system is ready to accept connections
2025-08-20 17:33:27.757 MSK [79375] LOG:  License checker started
2025-08-20 17:33:27.758 MSK [79363] LOG:  Start integrity check launcher
2025-08-20 17:33:27.760 MSK [79374] LOG:  Start of integrity check
```
При запуске в журнал сообщений сначала было записано сообщение о том, что экземпляр не был корректно остановлен ("database system was not properly shut down").

Затем — что восстановление началось с записи WAL c LSN = 0/14FF0B98 ("redo starts at 0/14FF0B98").

Далее — сообщение о достижении конца журнала WAL ("invalid record length at 0/150AD678") и сообщение о завершении восстановления на записи с LSN = '0/150AD628' ("redo done at 0/150AD628").

Наконец, после этого пара сообщений о выполнении контрольной точки для сброса восстановленных страниц на накопители ("checkpoin starting" и "checkpoint complete").

Проверим, восстановилась ли ранее вставленная строка в таблицу pgbench_branches.

В первом сеансе посмотрите содержимое таблицы pgbench_branches:

pgbench_db=# SELECT * FROM pgbench_branches;

WARNING:  terminating connection due to immediate shutdown command
сервер неожиданно закрыл соединение
        Скорее всего сервер прекратил работу из-за сбоя
        до или в процессе выполнения запроса.
Подключение к серверу потеряно. Попытка восстановления удачна.

Однако при выполнении запроса было выдано предупреждение, что соединение было разорвано из-за сбоя, но теперь оно восстановлено. Попробуем еще раз.

В первом сеансе повторите запрос:

pgbench_db=# select * from pgbench_branches;

 bid | bbalance |                                          filler
-----+----------+------------------------------------------------------------------------------------------
   2 |     1000 | Страница с этой строкой находится только в оперативной памяти перед сбоем
   1 |   633477 |
(2 строки)

Вставленная строка восстановилась, хотя на момент сбоя находилась в странице только в оперативной памяти.

Мониторинг и настройка

Во втором сеансе проинициализируйте тест pgbench:
```
-bash-4.4$ pgbench -i -s 50 pgbench_db
```
```
dropping old tables...
creating tables...
generating data (client-side)...
5000000 of 5000000 tuples (100%) done (elapsed 5.23 s, remaining 0.00 s)
vacuuming...
creating primary keys...
done in 8.02 s (drop tables 0.16 s, create tables 0.02 s, client-side generate 5.52 s, vacuum 0.30 s, primary keys 2.03 s).
```
Теперь при инициализации pgbench был установлен масштаб, равный 50 (-s 50) для увеличения количества изменяемых строк и, соответственно, количества грязных страниц.
В первом сеансе сбросьте статистики представления pg_stat_bgwriter:
```
pgbench_db=# SELECT pg_stat_reset_shared('bgwriter');
```
```
 pg_stat_reset_shared
----------------------

(1 строка)
```
Функция pg_stat_reset_shared позволяет сбросить только часть статистических счетчиков. В данном случае сброшены счетчики, используемые в системном представлении pg_stat_bgwriter.

Во втором сеансе запустите 2-минутный тест pgbench:

-bash-4.4$ pgbench -T 120 -c 50  pgbench_db

pgbench (15.5)
starting vacuum...end.
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 50
query mode: simple
number of clients: 50
number of threads: 1
maximum number of tries: 1
duration: 120 s
number of transactions actually processed: 88755
number of failed transactions: 0 (0.000%)
latency average = 68.146 ms
initial connection time = 194.180 ms
tps = 733.721380 (without initial connection time)

После завершения теста посмотрите содержимое представления pg_stat_bgwriter в первом сеансе:
```
pgbench_db=# SELECT * FROM pg_stat_bgwriter\gx
```
```
-[ RECORD 1 ]---------+-----------------------------
checkpoints_timed     | 0
checkpoints_req       | 1
checkpoint_write_time | 124961
checkpoint_sync_time  | 13466
buffers_checkpoint    | 1194
buffers_clean         | 33933
maxwritten_clean      | 293
buffers_backend       | 59834
buffers_backend_fsync | 0
buffers_alloc         | 122356
stats_reset           | 2025-08-20 20:38:26.41215+03
```
За время теста контрольных точек по расписанию выполнено не было (checkpoints_timed = 0).

Один раз (checkpoints_req = 1) контрольная точка была выполнена при превышении размером журнала WAL значения max_wal_size. Такой вывод можно сделать, поскольку вручную контрольные точки в указанный период не выполнялись.

При этом в ходе контрольной точки было сброшено только 1194 страницы (buffers_checkpoint).

В свою очередь, процесс фоновой записи успел сбросить 33933 страницы (buffers_clean).

А обслуживающие процессы сбросили 59834 страницы (buffers_backend), что значительно превосходит сумму двух предыдущих показателей.

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

Однако ничего удивительного в этом нет, поскольку на таком коротком временном отрезке контрольные точки не выполнялись по расписанию.

Попробуем это исправить.
В первом сеансе установите значение параметра checkpoint_timeout в 30 секунд:
```
pgbench_db=# ALTER SYSTEM SET checkpoint_timeout = 30;
```
```
ALTER SYSTEM
```
```
pgbench_db=# SELECT pg_reload_conf();
```
```
 pg_reload_conf
----------------
 t
(1 строка)
```
Теперь контрольная точка должна выполняться по расписанию каждые 30 секунд.

В первом сеансе сбросьте статистику представления pg_stat_bgwriter:

pgbench_db=# SELECT pg_stat_reset_shared('bgwriter');

 pg_stat_reset_shared
----------------------

(1 строка)

Во втором сеансе снова запустите 2-минутный тест pgbench:

-bash-4.4$ pgbench -T 120 -c 50  pgbench_db

pgbench (15.5)
starting vacuum...end.
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 50
query mode: simple
number of clients: 50
number of threads: 1
maximum number of tries: 1
duration: 120 s
number of transactions actually processed: 78483
number of failed transactions: 0 (0.000%)
latency average = 76.374 ms
initial connection time = 250.991 ms
tps = 654.675076 (without initial connection time)

После завершения теста в первом сеансе посмотрите содержимое представления pg_stat_bgwriter:
```
pgbench_db=# SELECT * FROM pg_stat_bgwriter\gx
```
```
-[ RECORD 1 ]---------+------------------------------
checkpoints_timed     | 6
checkpoints_req       | 0
checkpoint_write_time | 106100
checkpoint_sync_time  | 34288
buffers_checkpoint    | 27586
buffers_clean         | 32839
maxwritten_clean      | 314
buffers_backend       | 46256
buffers_backend_fsync | 0
buffers_alloc         | 109399
stats_reset           | 2025-08-20 20:51:17.648315+03
```
Ситуация значительно улучшилась.

Теперь в процессе выполнения контрольных точек было сброшено 27586 грязных страниц, процессом фоновой записи — 32839.

Но количество записанных страниц обслуживающими процессами (46256), хотя теперь и меньше суммы двух предыдущих значения, однако является сопоставимым с указанной суммой.

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

Но все же попробуем выправить ситуацию в текущих условиях.

Обратите внимание на значение поля maxwritten_clean, которое показывает, сколько раз фоновый процесс останавливал сброс грязных страниц из-за превышения их предельного количества, определяемого значением параметра bgwriter_lru_maxpages (по умолчанию 100).

То есть 314 раз фоновый процесс не сбрасывал грязные страницы и прекращал свою работу, засыпая на bgwriter_delay единиц времени (по умолчанию 200 ms).

Попробуем увеличить значение bgwriter_lru_maxpages.

В первом сеансе установите значение параметра bgwriter_lru_maxpages в 300:

pgbench_db=# ALTER SYSTEM SET bgwriter_lru_maxpages = 300;

ALTER SYSTEM

pgbench_db=# SELECT pg_reload_conf();

 pg_reload_conf
----------------
 t
(1 строка)

В первом сеансе сбросьте статистику представления pg_stat_bgwriter:

pgbench_db=# SELECT pg_stat_reset_shared('bgwriter');

 pg_stat_reset_shared
----------------------

(1 строка)

Во втором сеансе снова запустите 2-минутный тест pgbench:

-bash-4.4$ pgbench -T 120 -c 50  pgbench_db

pgbench (15.5)
starting vacuum...end.
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 50
query mode: simple
number of clients: 50
number of threads: 1
maximum number of tries: 1
duration: 120 s
number of transactions actually processed: 83098
number of failed transactions: 0 (0.000%)
latency average = 72.252 ms
initial connection time = 190.766 ms
tps = 692.022879 (without initial connection time)

После завершения теста посмотрите содержимое представления pg_stat_bgwriter в первом сеансе:

pgbench_db=# SELECT * FROM pg_stat_bgwriter\gx

-[ RECORD 1 ]---------+------------------------------
checkpoints_timed     | 5
checkpoints_req       | 0
checkpoint_write_time | 79862
checkpoint_sync_time  | 1668
buffers_checkpoint    | 19055
buffers_clean         | 63974
maxwritten_clean      | 139
buffers_backend       | 3842
buffers_backend_fsync | 0
buffers_alloc         | 114241
stats_reset           | 2025-08-20 20:58:21.\{pangolin-version\}8+03

Теперь обслуживающие процессы как минимум на порядок меньше сбрасывали грязных страниц (3842), чем совместно процесс контрольной точки и фоновый процесс (19055 + 63974). Количество прерываний работы фонового процесса стало значительно меньше (139 против 314).

В реальных системах, конечно, не стоит задавать такое небольшое значение checkpoint_timeout. Здесь это было сделано для наглядности результатов при непродолжительном времени эксперимента.

Завершение

В первом сеансе сбросьте значения параметров checkpoint_timeout и bgwriter_lru_maxpages:

pgbench_db=# ALTER SYSTEM RESET checkpoint_timeout;

ALTER SYSTEM

pgbench_db=# ALTER SYSTEM RESET bgwriter_lru_maxpages;

ALTER SYSTEM

pgbench_db=# SELECT pg_reload_conf();

 pg_reload_conf
----------------
 t
(1 строка)

В первом сеансе проверьте значения сброшенных параметров:

pgbench_db=# SELECT name, setting FROM pg_settings WHERE name IN ('checkpoint_timeout', 'bgwriter_lru_maxpages');

         name          | setting
-----------------------+---------
 bgwriter_lru_maxpages | 100
 checkpoint_timeout    | 300
(2 строки)

В первом сеансе подключитесь к базе данных postgres, удалите базу данных pgbench_db и выйдите из сеанса:

pgbench_db=# \c postgres

Вы подключены к базе данных "postgres" как пользователь "postgres".

postgres=# DROP DATABASE pgbench_db;

DROP DATABASE

postgres=# \q

Самопроверка

Вопрос 1

Состояние содержания файла pg_control, полученное с использованием утилиты pg_controldata, представлено ниже:

pg_control version number:            1300
Catalog version number:               202409231
Database system identifier:           7538415936932818542
Database cluster state:               in production
pg_control last modified:             Ср 20 авг 2025 21:01:26
Latest checkpoint location:           2/1987E268
Latest checkpoint's REDO location:    2/1987E220
Latest checkpoint's REDO WAL file:    000000010000000200000019
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1

Какой LSN соответствует записи WAL, начиная с которой будет выполняться восстановление в случае сбоя при указанном состоянии файла pg_control?

2/1987E2682/1987E220000000010000000200000019

Вопрос 2

В сеансе psql выполнен следующий запрос:

some_db=# SELECT * FROM pg_stat_bgwriter\gx

-[ RECORD 1 ]---------+------------------------------
checkpoints_timed     | 300
checkpoints_req       | 1
checkpoint_write_time | 133160
checkpoint_sync_time  | 1689
buffers_checkpoint    | 28344
buffers_clean         | 100357
maxwritten_clean      | 463
buffers_backend       | 67365
buffers_backend_fsync | 0
buffers_alloc         | 260745
stats_reset           | 2025-08-20 20:58:21.614338+03

Сколько грязных страниц было записано на накопители фоновым процессом с момента последнего сброса статистики?

Вопрос 3

Значения каких конфигурационных параметров оказывают влияние на частоту сброса грязных страниц обслуживающими процессами? Выберите все верные варианты ответа

Вопрос 4

В сеансе psql выполнен следующий запрос:

some_db=# SELECT * FROM pg_stat_bgwriter\gx

-[ RECORD 1 ]---------+------------------------------
checkpoints_timed     | 300
checkpoints_req       | 35
checkpoint_write_time | 133160
checkpoint_sync_time  | 1689
buffers_checkpoint    | 28344
buffers_clean         | 100357
maxwritten_clean      | 463
buffers_backend       | 67365
buffers_backend_fsync | 0
buffers_alloc         | 260745
stats_reset           | 2025-08-20 20:58:21.614338+03

Сколько раз была вызвана контрольная точка с момента последнего сброса статистики?

Запись грязных страниц​

Выполнение контрольной точки​

Выполнение восстановления​

Мониторинг и настройка​

Завершение​

Самопроверка​