Долгосрочный запрос для реплики только для чтения, который занимает несколько минут на первичной

У меня есть 4 узла AG установки следующим образом:

Аппаратная конфигурация ВМ всех узлов:

• Microsoft SQL Server 2017 Enterprise Edition (RTM-CU14) (KB4484710)
• 16 виртуальных ЦП
• 356 ГБ ОЗУ (длинный рассказ об этом ...)
• максимальная степень параллелизма: 1 (в соответствии с требованиями поставщика приложений)
• порог стоимости для параллелизма: 50
• максимальная память сервера (МБ): 338944 (331 ГБ)

Конфигурация AG:

• Узел 1: Первичный или синхронный коммит, нечитаемый вторичный, сконфигурированный для автоматического перехода на другой ресурс
• Узел 2. Первичный или синхронный коммит, нечитаемый вторичный, сконфигурированный для автоматического перехода на другой ресурс
• Узел 3: Доступный для чтения вторичный набор с асинхронной фиксацией, настроенный для аварийного переключения вручную
• Узел 4: Доступный для чтения вторичный набор с асинхронной фиксацией, настроенный для аварийного переключения вручную

Вопрос в вопросе:

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

Поведение исполнения на первичном узле:

При выполнении на основном узле время выполнения обычно составляет около 1 секунды. Вот план выполнения , и ниже приведены статистические данные, полученные из STATISTICS IO и STATISTICS TIME от основного узла:

(347 rows affected)
Table 'Worktable'. Scan count 647, logical reads 2491, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'workitemlc'. Scan count 300, logical reads 7125, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulertask'. Scan count 1, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'wfschedulertask'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerservice'. Scan count 1, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerworkerpool'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'itemlc'. Scan count 1, logical reads 26372, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

 SQL Server Execution Times:
   CPU time = 500 ms,  elapsed time = 656 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

Поведение при выполнении на дополнительном узле только для чтения:

При выполнении на дополнительном узле только для чтения (т. Е. Узле 3 или узле 4) этот запрос использует тот же план выполнения (это другая ссылка на план), и отображается примерно такая же статистика выполнения (например, может быть еще несколько страниц). сканирует, так как эти результаты постоянно меняются), но, за исключением времени процессора, они выглядят очень похоже. Вот статистика, полученная из STATISTICS IO и STATISTICS TIME из вторичного узла только для чтения:

(347 rows affected)
Table 'Worktable'. Scan count 647, logical reads 2491, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'workitemlc'. Scan count 300, logical reads 7125, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulertask'. Scan count 1, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'wfschedulertask'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerservice'. Scan count 1, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerworkerpool'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'itemlc'. Scan count 1, logical reads 26372, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

 SQL Server Execution Times:
   CPU time = 55719 ms,  elapsed time = 56335 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

Другие детали:

Я также работать как sp_WhoIsActiveи Пол РэндалWaitingTasks.sql сценарий на вторичной обмотке , а этот запрос выполняется, но я не вижу какие - либо ожидает , что происходит, так когда - либо, что откровенно расстраивает:

Это также не выглядит как случай задержки AG, поскольку состояние синхронизации на самом деле довольно хорошее:

--https://sqlperformance.com/2015/08/monitoring/availability-group-replica-sync

SELECT 
       ar.replica_server_name, 
       adc.database_name, 
       ag.name AS ag_name, 
       drs.is_local, 
       drs.synchronization_state_desc, 
       drs.synchronization_health_desc, 
       --drs.last_hardened_lsn, 
       --drs.last_hardened_time, 
       drs.last_redone_time, 
       drs.redo_queue_size, 
       drs.redo_rate, 
       (drs.redo_queue_size / drs.redo_rate) / 60.0 AS est_redo_completion_time_min,
       drs.last_commit_lsn, 
       drs.last_commit_time
FROM sys.dm_hadr_database_replica_states AS drs
INNER JOIN sys.availability_databases_cluster AS adc 
       ON drs.group_id = adc.group_id AND 
       drs.group_database_id = adc.group_database_id
INNER JOIN sys.availability_groups AS ag
       ON ag.group_id = drs.group_id
INNER JOIN sys.availability_replicas AS ar 
       ON drs.group_id = ar.group_id AND 
       drs.replica_id = ar.replica_id
ORDER BY 
       ag.name, 
       ar.replica_server_name, 
       adc.database_name;

Этот запрос кажется худшим нарушителем. Другие запросы, которые также занимают менее секунды на первичном узле, могут занимать 1–5 секунд на вторичном узле, и, хотя поведение не столь серьезное, оно, похоже, вызывает проблемы.

Наконец, я также посмотрел на серверы и проверил наличие внешних процессов, таких как A / V-сканирование, внешние задания, генерирующие неожиданный ввод-вывод и т. Д., И пришел с пустыми руками. Я не думаю, что это вызвано чем-то вне процесса SQL Server.

Вопрос:

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

На протяжении всего моего исследования я просто не могу найти причину такой разницы в производительности. Я ожидаю увидеть какое-то ожидание на вторичных узлах, но ничего. Как я могу дополнительно устранить это, чтобы определить основную причину? Кто-нибудь видел такое поведение раньше и нашел способ его решить?

ОБНОВЛЕНИЕ # 1 После обмена состояниями третьего узла (одной из реплик только для чтения) на недоступные для чтения, а затем обратно в читаемые в качестве теста, эта реплика все еще удерживается открытой транзакцией, причем любые клиентские запросы отображают HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGПодождите.

Выполнение DBCC OPENTRANкоманды дает следующие результаты:

Oldest active transaction:
    SPID (server process ID): 420s
    UID (user ID) : -1
    Name          : QDS nested transaction
    LSN           : (941189:33148:8)
    Start time    : May  7 2019 12:54:06:753PM
    SID           : 0x0
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

При поиске этого SPID sp_who2он отображается как BACKGROUNDпроцесс с QUERY STORE BACKуказанием в качестве команды.

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

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

Окончательное обновление (проблема решена самостоятельно)

После того, как была отмечена 52-часовая отметка открытой транзакции хранилища запросов (как указано выше), AG решил автоматически выполнить аварийное переключение. До того, как это произошло, я потянул некоторые дополнительные метрики. По этой ссылке , предоставленной Шоном, в рассматриваемой базе данных было очень большое хранилище версий, посвященное этой базе данных, в частности, в один момент я записал 1651360 страниц в reserved_page_countполе и 13210880 для reserved_space_kbзначения.

Согласно ERRORLOGs, отказоустойчивый произошло после 5 - минутного наводнению сбоев транзакций , связанных с упрочняющими QDS base transactionи QDS nested transactionсделки.

Аварийное переключение вызвало сбой около 10 минут в моем случае. База данных размером ~ 6 ТБ и очень активная, так что, на мой взгляд, это было довольно неплохо. Пока новый основной узел был в сети в течение этого времени, ни один клиентский запрос не мог завершиться, поскольку все они ожидали QDS_LOADDBтипа ожидания.

После отработки отказа номера хранилищ версий сократились до 176 для reserved_page_countи 1408 для reserved_space_kb. Запросы к вторичным репликам, доступным только для чтения, также начали выполняться так же быстро, как если бы они запускались с первичной, поэтому похоже, что поведение полностью исчезло в результате аварийного переключения.

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

Когда вторичная реплика помечается как читаемая, сначала необходимо получить хорошее устойчивое состояние для информации о версиях, чтобы была известная и хорошая отправная точка для всех операций чтения на вторичном сервере. Когда это ожидает перехода и все еще есть открытые транзакции на первичном сервере, это проявится как HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGи также является хорошим индикатором того, что первичный сервер действительно проходит через небольшой отток данных (или, по крайней мере, у кого-то действительно длинная открытая транзакция, которая тоже не хорошо). Чем дольше транзакции открыты и чем больше изменений данных, тем больше будет версий.

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

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

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

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

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

Есть и другие предметы, которые также могут быть в игре, но это кажется наиболее правдоподобным, учитывая текущие данные и то, как реплика реагировала.

DMVs контроля версий TempDB (не путать с версиями ADR).

Отказ от ответственности: я ничего не знаю о группах доступности, но я немного знаю о запросах устранения неполадок, которые, по-видимому, используют больше ресурсов ЦП, чем следовало бы.

У вас проблема с процессором в том, что вы используете слишком много. Одна важная вещь, которую стоит сказать об ожиданиях, - почти все они не заняты процессором. Когда рабочий переходит в состояние ожидания, он уступил и больше не работает в планировщике в SQLOS. Так что, если у вас есть запрос MAXDOP 1 со следующей статистикой выполнения:

Время ЦП = 55719 мс, прошедшее время = 56335 мс.

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

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

• Есть ли на вторичном сервере дорогостоящий мониторинг, такой как расширенные события, трассировки или профилирование?
• Аппаратное обеспечение вторичного сервера примерно соответствует первичному?
• Есть ли какие-либо проблемы конфигурации или программного обеспечения со вторичным сервером?
• Какие-нибудь существенные ожидания или защелки? Может быть неприменимо к вашему запросу, но все же может дать подсказки.
• Какие-нибудь существенные блокировки?
• Существуют ли другие DMV или вещи, которые вы можете проверить в SQL Server, которые могут дать подсказки? Вы упомянули, что группы доступности, вероятно, являются ключевой частью проблемы.
• О чем говорит трассировка ETW?
• Какие у вас есть соглашения о поддержке?

Большая часть вышеперечисленного хорошо освещена в различных постах и ​​документах блога, но я остановлюсь на трассировке ETW. Если вы хотите знать, почему SQL Server использует так много ЦП для определенного запроса, и у вас есть доступ к хосту, вы всегда можете выполнить трассировку ETW, чтобы просмотреть стеки вызовов и посмотреть, сколько ЦП делают различные стеки вызовов. Другими словами, хост-система с удовольствием расскажет вам, для чего используется процессор, если вы знаете, как спрашивать. Обычные методы трассировки ETW включают Windows Performance Recorder и PerfView .

Осмысление этих результатов требует глубоких внутренних знаний, и легко прийти к неправильному выводу. Во многих случаях лучше собрать необработанные данные и попросить экспертов посмотреть на них. При выполнении трассировки вы хотите, чтобы в SQL Server было как можно меньше действий. Ниже приведено несколько ответов, которые используют трассировку ETW, чтобы сделать выводы о SQL Server:

• Как диагностировать try_parse очень медленным?
• Почему создание простой группы строк CCI может занять до 30 секунд?
• Логические чтения в оперативной памяти появляются в статистике ожидания или где?
• Почему NOLOCK делает сканирование с назначением переменной медленнее?
• Какой алгоритм стоит за исключением оператора EXCEPT?
• Команда ALTER TABLE без значения по умолчанию, принимающего навсегда?
• Данные неявно упорядочены, как если бы это был кластерный индекс; Могу ли я воспользоваться этим?

Я подозреваю, что в вашем случае, если вы сможете собирать стеки вызовов во время 45-секундного запроса, вы получите очень полезные подсказки о природе проблемы.

Поскольку проблема решается самостоятельно, мне остается размышлять над ее причиной (рифмовка не преднамеренная). Исходя из сообщения Шона и того факта, что открытая транзакция хранилища запросов, по-видимому, была основной причиной моего увеличенного размера хранилища версий (например, причиной HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGожидания), я могу только предположить, что хранилище запросов было частью поведения, которое было представил. Эта база данных больше (~ 6 ТБ), достаточно активна, и большинство обращающихся к ней запросов генерируется на клиенте и не параметризуется (то есть специальные запросы), поэтому я не верю, что Query Store поддается предоставлению много пользы в этом сценарии. Из-за этого мы будем отключать хранилище запросов в этой среде во время будущего периода обслуживания, после которого, я подозреваю, мы больше не увидим подобное поведение.

Мы открыли тикет с Microsoft, но выбор времени был не в нашу пользу, так как проблема была решена до того, как мы смогли провести какой-либо подробный анализ с помощью трассировки PSSDIAG или подобного. Я надеюсь, что они смогут провести локализованное тестирование и повторить эту проблему, если мы столкнемся с этой ошибкой. Если будут обнаружены какие-либо дальнейшие обновления более постоянного разрешения, я обязательно обновлю этот ответ.