Устранение задержек перемещения данных между группами доступности AlwaysOn с синхронной фиксацией

Автор: Simon Su, Troubleshooting data movement latency between synchronous-commit AlwaysOn Availability Groups
Технические рецензенты: Pam Lahoud, Sourabh Agarwal, Tejas Shah

В узлах группы доступности (AG) с синхронной фиксацией иногда можно наблюдать, что ваши транзакции ожидают в состоянии HADR_SYNC_COMMIT. Ожидания HADR_SYNC_COMMIT указывают на то, что SQL Server ожидает сигнала от удалённых реплик для фиксации транзакции. Чтобы понять задержку фиксации транзакций, вы можете обратиться к следующим статьям:

• Troubleshooting High HADR_SYNC_COMMIT wait type with AlwaysOn Availability Groups
• SQL Server 2012 AlwaysOn – Part 12 – Performance Aspects and Performance Monitoring II

В приведённой выше ссылке вы узнаете, что задержку транзакций можно оценить с помощью двух счетчиков производительности:

• SQL Server:Database Replica –> Transaction Delay
• SQL Server:Database Replica –> Mirrored Write Transactions/sec

Например, предположим, что есть плохо работающие узлы AG, и вы видите, что «SQL Server:Database Replica –> Transaction Delay» составляет 1000 мс, а «SQL Server:Database Replica –> Mirrored Write Transactions/sec» равно 50. Это означает, что в среднем каждая транзакция имеет задержку 1000 мс / 50 = 20 мс.

Учитывая приведённый пример, можем ли мы узнать, откуда берётся задержка в 20 мс? Какие факторы вызывают эту задержку? Чтобы найти ответы на такие вопросы, нам нужно понять, как работает синхронная фиксация: AlwaysOn HADRON Learning Series: How does AlwaysOn process a synchronous-commit request?

Для отслеживания перемещения данных между репликами нам повезло, что у нас есть нужные xEvents: KB3173156 — обновление добавляет расширенные события и счетчики производительности AlwaysOn в SQL Server 2014 или 2016

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

На первичной реплике:

1. Блок журнала -> LogCache -> LogFlush -> LocalHarden (LDF)
2. Блок журнала -> logPool -> LogCapture -> SendToRemote
(1. и 2 выполняются параллельно)

На удалённой синхронной реплике:

Процесс закрепления (harden) аналогичен процессу на первичной реплике: получение блока журнала -> LogCache -> LogFlush -> HardenToLDF -> AckPrimary

xEvents (см. первую ссылку в этой статье) происходят в разных местах перемещения блока журнала. На рисунке ниже показан подробный поток перемещения журнала для каждого шага и соответствующие Xevents:

Как показано выше, когда трассировка xEvent захвачена, мы можем узнать точные временные точки каждого шага перемещения блока журнала и точно определить, откуда берётся задержка транзакции. Обычно задержка состоит из трёх частей:

1. Продолжительность закрепления журнала на первичной реплике
   Она равна разнице во времени между Log_flush_start (шаг 2) и Log_flush_complete (шаг 3).
2. Продолжительность закрепления журнала на удалённой реплике
   Она равна разнице во времени между Log_flush_start (шаг 10) и Log_flush_complete (шаг 11).
3. Продолжительность сетевого трафика
   Сумма разниц во времени: (первичная: hadr_log_block_send_complete -> вторичная: hadr_transport_receive_log_block_message, шаги 6-7) и (вторичная: hadr_lsn_send_complete -> первичная: hadr_receive_harden_lsn_message, шаги 12-13).

Я использую следующий скрипт для захвата xEvents:

/* Примечание: эта трассировка может генерировать очень большой объём данных очень быстро, в зависимости от фактической интенсивности транзакций. На загруженном сервере она может расти на несколько ГБ в минуту, поэтому не запускайте скрипт слишком долго, чтобы избежать влияния на рабочий сервер. */
CREATE EVENT SESSION [AlwaysOn_Data_Movement_Tracing] ON SERVER
ADD EVENT sqlserver.file_write_completed,
ADD EVENT sqlserver.file_write_enqueued,
ADD EVENT sqlserver.hadr_apply_log_block,
ADD EVENT sqlserver.hadr_apply_vlfheader,
ADD EVENT sqlserver.hadr_capture_compressed_log_cache,
ADD EVENT sqlserver.hadr_capture_filestream_wait,
ADD EVENT sqlserver.hadr_capture_log_block,
ADD EVENT sqlserver.hadr_capture_vlfheader,
ADD EVENT sqlserver.hadr_db_commit_mgr_harden,
ADD EVENT sqlserver.hadr_db_commit_mgr_harden_still_waiting,
ADD EVENT sqlserver.hadr_db_commit_mgr_update_harden,
ADD EVENT sqlserver.hadr_filestream_processed_block,
ADD EVENT sqlserver.hadr_log_block_compression,
ADD EVENT sqlserver.hadr_log_block_decompression,
ADD EVENT sqlserver.hadr_log_block_group_commit,
ADD EVENT sqlserver.hadr_log_block_send_complete,
ADD EVENT sqlserver.hadr_lsn_send_complete,
ADD EVENT sqlserver.hadr_receive_harden_lsn_message,
ADD EVENT sqlserver.hadr_send_harden_lsn_message,
ADD EVENT sqlserver.hadr_transport_flow_control_action,
ADD EVENT sqlserver.hadr_transport_receive_log_block_message,
ADD EVENT sqlserver.log_block_pushed_to_logpool,
ADD EVENT sqlserver.log_flush_complete,
ADD EVENT sqlserver.log_flush_start,
ADD EVENT sqlserver.recovery_unit_harden_log_timestamps
ADD TARGET package0.event_file(SET filename=N'c:\mslog\AlwaysOn_Data_Movement_Tracing.xel',max_file_size=(500),max_rollover_files=(4))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=ON);
GO

В демонстрационных целях я просто выполнил INSERT INTO [AdventureWorks2014]..t1 VALUES(1), а затем захватил трассировку xEvent на первичной и вторичной репликах. Ниже приведены скриншоты захваченных xEvents:

Первичная реплика:

Вторичная синхронная реплика:

Примечание: Вы можете заметить, что log_block_id (146028889512) для hadr_receive_harden_lsn_message не совпадает с другими (146028889488). Это связано с тем, что возвращаемый идентификатор всегда является следующим непосредственным идентификатором закреплённого блока журнала. Для сопоставления xEvents мы можем использовать hadr_db_commit_mgr_update_harden:

Имея приведённые выше журналы xEvent, мы теперь получаем следующую детальную разбивку задержек по времени фиксации транзакции:

	От	До	Задержка
Сеть: Первичная -> Вторичная	Первичная: hadr_log_block_send_complete 2018-03-06 16:56:28.2174613	Вторичная: hadr_transport_receive_log_block_message 2018-03-06 16:56:32.1241242	3.907 секунд
Сеть: Вторичная -> Первичная	Вторичная: hadr_lsn_send_complete 2018-03-06 16:56:32.7863432	Первичная: hadr_receive_harden_lsn_message 2018-03-06 16:56:33.3732126	0.587 секунд
Закрепление журнала (Первичная)	log_flush_start 2018-03-06 16:56:28.2168580	log_flush_complete 2018-03-06 16:56:28.8785928	0.663 секунд
Закрепление журнала (Вторичная)	Log_flush_start 2018-03-06 16:56:32.1242499	Log_flush_complete 2018-03-06 16:56:32.7861231	0.663 секунд

Я перечислил разницы во времени (задержки) только для сети и процесса закрепления журнала. Могут быть и другие места задержек, например, сжатие/распаковка блоков журнала, но в основном задержка исходит из этих трёх частей:

• Сетевая задержка между репликами. В приведённом выше примере она составляет 3.907 + 0.587 = 4.494 секунды.
• Закрепление журнала на первичной реплике = 0.663 секунды.
• Закрепление журнала на вторичной реплике = 0.663 секунды.

Чтобы получить общую задержку транзакции, мы не можем просто суммировать их, потому что сброс журнала на первичной реплике и сетевая передача происходят параллельно. Например, сеть занимает 4.494 секунды, но закрепление журнала на первичной реплике завершилось (log_flush_complete: 2018-03-06 16:56:28.8785928) задолго до того, как первичная реплика получила подтверждение от реплики (hadr_receive_harden_lsn_message: 2018-03-06 16:56:33.3732126). К счастью, нам не нужно вручную определять, какую временную метку использовать для расчёта общего времени фиксации транзакции. Мы можем использовать разницу во времени между двумя xEvents hadr_log_block_group_commit, чтобы узнать время фиксации. Например, в приведённом выше журнале:

• Первичная: hadr_log_block_group_commit: 2018-03-06 16:56:28.2167393
• Первичная: hadr_log_block_group_commit: 2018-03-06 16:56:33.3732847

Общее время фиксации = разница между двумя временными метками = 5.157 секунд.

Это число равно времени передачи по сети плюс время закрепления журнала на вторичной реплике. Это логично, потому что вторичная реплика должна ждать поступления блока журнала по сети перед закреплением журнала; она не может выполнять закрепление журнала параллельно, как на первичной реплике.

Если вы посмотрите на второе событие hadr_log_block_group_commit, у него есть столбец «processing_time», который является точно таким же временем фиксации транзакции, о котором мы говорим:

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

Кстати, вы можете заметить, что в xEvents первичной реплики происходит событие «hadr_db_commit_mgr_harden_still_waiting». Это событие происходит каждые 2 секунды (2 секунды заданы жёстко), когда первичная реплика ожидает подтверждающего сообщения от вторичной реплики. Если подтверждение возвращается в течение 2 секунд, вы не увидите этого xEvent.

Обновление от 2018.09.08

Я разработал инструмент для автоматического анализа трассировки: AGLatency Report Tool Introduction

Справочные материалы

• New in SSMS – Always On Availability Group Latency Reports
• Руководство по мониторингу и устранению неполадок в группах доступности AlwaysOn