По материалам статьи Sean Gallardy «Demystifying Dumps: Non-Yielding Scheduler

23 августа 2021 г

Одним из наиболее распространенных случаев, приводящих к генерации дампа памяти в SQL Server, является «ступор» при выполнении задачи на планировщике: non-yielding scheduler (для краткости называемый NYS). Что же это значит? Почему он вызывает дамп памяти? Где можно найти что-нибудь, что можно исследовать для поиска источника ступора? Хорошие вопросы, давайте на них ответим.

Введение

Чтобы понять, что означает non-yielding, мы должны понимать, как планировщик должен правильно, без ступора уступать ресурсы и почему иногда он впадает в ступор. Я не собираюсь углубляться в детали работы планировщика SQLOS, в интеграцию с Windows и механизмы сигнализации, но собираюсь обсудить несколько ключевых моментов.

SQL Server использует кооперативное планирование (которое также можно было бы назвать планированием без вытеснения задач). Windows (клиент и сервер) использует вытесняющее планирование (забавный факт, Windows изначально использовала кооперативное планирование, но начиная с Windows 95 / NT3.51 оно было заменено на вытесняющее). Сначала легче понять, как работает вытесняющее планирование, которое, как следует из названия, позволяет одному рабочему элементу вытеснять другой рабочий элемент. Особенностью такого подхода является то, что любой поток может просто взять управление на себя и запустить свою задачу в любое время по любой причине и не гарантируя правильного запуска завершения/остановки. В дизайне с вытеснением любая выполняющаяся задача может быть изменена в любой момент времени и может или не может быть запланирована снова. Задача не имеет никакого контроля над тем, выполняется она или нет. Очевидно, это сильно упрощённое описание чрезвычайно сложной проблемной области, но этого достаточно для нашего описания. Если вытеснение означает что задача не контролирует выполняется она или нет, то кооперативное планирование означает, что все задачи (я использую задачи как общий термин, безотносительно к объекту процесса SQL Server) должны взаимодействовать и координировать друг друга для совместной работы и управления временем исполнения. В кооперативной модели каждая задача решает, когда наступает подходящий момент для запуска другой задачи и прекращения монополизации времени использования доступного ресурса и вычислительной мощности. Эти ресурсы и мощности уступаются, т.е. она передаёт контроль следующей в очереди планировщика задаче. Таким образом, при кооперативном планировании все наши задачи должны быть «хорошими» гражданами! «Плохая» задача может испортит всю систему, это деликатный процесс.

To Yield or Not to Yield

Теперь, когда вы вспомнили, что такое кооперативное планирование, становиться понятно, что такая задача как SQL Server, должна быть удобной для других задач, поскольку она периодически уступает ресурсы, чтобы другие могли работать. Позвольте мне застопориться (ха!) на нескольких вопросах, и давайте поговорим о вытеснении при многозадачности.

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

Обратите внимание, что в то время как SQL Server использует кооперативное планирование, Windows по-прежнему использует вытесняющее планирование (Linux тоже, и не для педантизма, а потому, что таков есть весь этот уровень абстракции Linux). Всё это означает, что на сегодняшний день операционная система по-прежнему сама выбирает, какие потоки будут работать, хотя SQL Server и может предоставить ей для запуска только несколько потоков, а не потенциально возможные тысячи потоков. Этим достигается более упорядоченная работа и выполняться будут те задачи, у которых действительно есть чем заняться (в отличие от тех, которые чего-то ждут).

Поговорим об ожиданиях, предположениях о возможном времени ожидания, обо всём что является частью ожидания уступки ресурсов. Возьмем «тривиальный» пример с получением закрытого ключа сертификата для некоторого типа шифрования, допустим, для S&G, являющимся Transparent Data Encryption. Похоже, эта операция должна быть быстрой, не так ли? Нужно всего то перейти в память, либо на диск, расшифровать ключ и отдать его в буфер приложения. Это если предполагается, что ключ локальный. А что, если ключ находится в HSM? Конечно, теперь у нас добавиться ещё несколько переходов, чтобы добраться до HSM. А что, если HSM не находится рядом с сервером (например, в том же центре обработки данных)? Тогда добиться ещё несколько переходов, скажем, в Azure Key Vault. Причём в последнем случае мы посредством сетей передачи данных проходим через Интернет. Что, если в какой-либо точке в этой цепочке произойдет сбой, возможно, где-то в сети выйдет из строя маршрутизатор, или в центре обработки данных выйдет из строя порт коммутатора, потребуется некоторое время, чтобы перенаправить трафик. До того момента, когда трафик перенаправлен, и TCP уже несколько раз смог переслать пакеты, сколько прошло «секунд»? Значит мы можем ожидать, что тривиальная операция легко превратиться в хаос из-за долгого времени ожидания. Если вам нужен менее сложный пример, не выходящий за рамки локальной системы, было ли у вас когда-нибудь в журнале ошибок сообщение о том, что ввод-вывод занимает более 15 секунд?

Из всего вышесказанного может показаться, что кооперативное планирование - отстой. Оно тормозит, в основном в тех случаях, где ему нужно взаимодействовать с чем-либо за пределами границ приложения. В приведенном выше примере вызов Windows API выходит за границы приложения. Чтобы не нарываться на неприятности, обычно эти вызовы переводятся с кооперативного планирования на вытесняющее планирование внутри SQL Server. Это не бесплатно и связано с большими накладными расходами, не говоря уже о том, что другие задачи могут ждать завершения этой вытесняемой задачи, потому что они зависят от возвращаемых ей данных. В примере с TDE мы не сможем зашифровать/расшифровать данные или фрагменты журнала до тех пор, пока не будет получен ключ, и это фактически остановит работу в SQL Server.

Регулировщик

Поскольку уже запущенная задача может повести себя некорректно, существует фоновая задача, отвечающая за проверку кооперативных планировщиков и гарантирующая, что работа планируемых ими задач не стопорятся, а продвигается вперед, как было описано ранее. К счастью, многие элементы внутри SQL Server имеют простые имена (в отличие от типичных маркетинговых названий Microsoft - «Microsoft Windows Azure Skype For Enterprise Business With ML and AI In Containers On Hyper-Scale Big Data Compute Cloud» :). Имя может помочь вам локализовать проблему, поскольку задачи по умолчанию добавляют информацию с именами в кольцевой буфер работоспособности SQL Server. Если у вас есть дамп из-за застопорившегося планировщика, стек вызовов будет подобен стеку, показанному в следующей ниже главе «Заглянем в шкафчик с уликами», что делает довольно простым просмотр стеков для понимания причин дампа.

Надзор

Теперь, когда мы закончили суперкороткую предысторию кооперативного планирования и уступки ресурсов, разберёмся почему возникает non-yielding scheduler дамп? Существует несколько причин, но основные из них заключаются в том, что дамп полезен при устранении потенциальных проблем с продуктом и может помочь (но не всегда) в анализе первопричин долгой работы задачи, если это не баг. Одним из примеров проблемы с продуктом может быть то, что список, содержащий некоторую информацию (неважно, какой на самом деле), всегда считается небольшим, т.е. менее 100 элементов. Перемещение по указанному списку должно быть относительно быстрым, всего 100 пунктов… предположение, что список всегда будет небольшим, может быть ошибочным - особенно в продукте, который активно разрабатывался почти 30 лет. Может быть, какая-то новая функция изменит способ работы некоторых исходных элементов и сейчас этот список может вырасти до 10 миллионов элементов, а это уже не так быстро обработать. В большинстве случаев NYS не являются проблемами SQL Server (если мы не приемлем возможность существования каких-либо проблем, и даже когда проблема возникает из-за вызова простого Windows API WriteFile – считаем, что это «проблема SQL Server», тогда на самом деле мы просто ужасные люди, которые винят других во всем на свете), и имеют мало общего со средой, в которой работает SQL Server. Опять же, хочу подчеркнуть, что я сказал "в большинстве случаев" ;).

Как уже говорилось, монитор (регулировщик) планировщиков следит за нормальным прогрессом и монополизацией времени планировщиками. Используется разная логика для обнаружения разнообразных обстоятельств (не все могут быть NYS), однако, если задача не завершилась добровольно в течение определенного времени (обычно это 70 секунд, которые можно замерять по обычным настенным часам, хотя и это может измениться), монитор планировщиков начинает действовать. В рамках этого процесса выполняются разные вещи, однако значение для нас имеют только две. Первая - это файл минидампа всех потоков, вторая - копия текущего стека выполнения планировщика, который застопорился и не уступает ресурсы. Кроме этого чрезвычайно полезная информация записывается в журнал ошибок службы SQL Server.

Заглянем в шкафчик с уликами

У нас есть два основных источника информации:

· Сам файл минидампа

· Файл Errorlog с дополнительной информацией

Можно открыть минидамп в вашем любимом отладчике, но большинство людей используют windbg или WinDBGX. Там нужно указать на общедоступные символы, которые легче всего получить с сервера Microsoft Symbol Server (V:\Symbols_Public тут каталог для локального кеша символов):

srv*V:\Symbols_Public*https://msdl.microsoft.com/download/symbols

Как только дамп открыт, мы можем дважды проверить, не является ли он non-yielding scheduler дампом (хотя комментарии к дампу должны сразу это показать), найдя поток, который вызвал дамп. SQLDumpr - это исполняемый файл, используемый для создания дампа, мы можем искать в стеке дампа слова: dump, dumping, sqldumper и т. д. Но, если вы пролистаете все потоки и просмотрите их, вы также должны его найти. Ниже приведен пример поиска потока дампа:

> !findstack sqllang!SQLDumperLibraryInvoke

Thread 030, 1 frame(s) match

Отлично, поток отладчика 0n30 содержит нужный нам стек дампа, давайте посмотрим его:

~[0n30]s; kc

00 ntdll!NtWaitForSingleObject

01 KERNELBASE!WaitForSingleObjectEx

02 sqlservr!CDmpDump::DumpInternal

03 sqlservr! CDmpDump::Dump

04 sqllang!SQLDumperLibraryInvoke

05 sqllang!SQLLangDumperLibraryInvoke

06 sqllang!CImageHelper::DoMiniDump

07 sqllang!stackTrace

08 sqlservr!SQL_SOSNonYieldSchedulerCallback

09 sqldk!SOS_Scheduler::ExecuteNonYieldSchedulerCallbacks

0a sqldk!SchedulerMonitor::CheckScheduler

0b sqldk!SchedulerMonitor::CheckSchedulers

0c sqldk!SchedulerMonitor::Run

0d sqldk!SchedulerMonitor::EntryPoint

0e sqldk!SOS_Task::Param::Execute

0f sqldk!SOS_Scheduler::RunTask

10 sqldk!SOS_Scheduler::ProcessTasks

11 sqldk!SchedulerManager::WorkerEntryPoint

12 sqldk!SystemThread::RunWorker

13 sqldk!SystemThreadDispatcher::ProcessWorker

14 sqldk!SchedulerManager::ThreadEntryPoint

15 kernel32!BaseThreadInitThunk

16 ntdll!RtlUserThreadStart

Ага, NYS дамп. Что теперь? Как мы можем получить дополнительную информацию загрузив публичные символы? Вот тут-то и появляется журнал ошибок! Просматривая журнал ошибок, вы можете найти информацию о дампе и увидеть там идентификационную подпись дампа:

Server * ***************************************************************************

Server *

Server * BEGIN STACK DUMP:

Server * 01/01/01 10:10:10 spid 1234

Server *

Server * Non-yielding Scheduler

Server *

Server * ***************************************************************************

Прямо под заголовком дампа вы увидите что-то вроде следующего:

Process 0:0:0 (0x22c0) Worker 0x0000000006A32120 appears to be non-yielding on Scheduler 8. Thread creation time: 17253840547306. Approx Thread CPU Used: kernel 62775 ms, user 3475 ms. Process Utilization 19%. System Idle 58%. Interval: 71590 ms.

Давайте коротко с этим разберемся. Первая часть (0x22c0) - это идентификатор потока Windows для потока, который не уступал. Там мы можем найти время потока в режиме ядра (со стороны ОС) исполнявшегося до этого потока, которое заняло 62,7 секунд, а за ним следует время проведённое потоком в пользовательском режиме - 3,5 секунды, и, наконец, общее время равно 71,5 секунд .

Это помогает нам несколькими способами:

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

Теперь, когда мы узнали, что скорее всего, мы должны искать в том, что происходило в режим ядра (есть два стека для потоков, пользовательский режим и режим ядра – всё, что происходит на стороне режима ядра не может быть просмотрено из пользовательского режима). Давайте переключимся на проблемную ветку и посмотрим, как она выглядит:

~~[0x22c0]s; kc

00 ntdll!NtWriteFile

01 KERNELBASE!WriteFile

02 sqlmin!DiskWriteAsync

03 sqlmin!FCB::AsyncWriteInternal

04 sqlmin!FCB::AsyncWrite

05 sqlmin!RecoveryUnit::GatherWrite

06 sqlmin!BPool::LazyWriter

07 sqlmin!lazywriter

08 sqldk!SOS_Task::Param::Execute

09 sqldk!SOS_Scheduler::RunTask

0a sqldk!SOS_Scheduler::ProcessTasks

0b sqldk!SchedulerManager::WorkerEntryPoint

0c sqldk!SystemThread::RunWorker

0d sqldk!SystemThreadDispatcher::ProcessWorker

0e sqldk!SchedulerManager::ThreadEntryPoint

0f kernel32!BaseThreadInitThunk

10 ntdll!RtlUserThreadStart

Приведенный выше стек показывает, что выполнялось перед тем, как был сделан дамп. Из дампа стало ясно, что был переход в код ядра - в этом случае NtWriteFile, который, как вы уже догадались, используется для записи в файлы. Этот интерфейс был вызван потоком LazyWriter. Поскольку не так много времени тратится этим кодом в пользовательском режиме, маловероятно, что проблема связана с самим LazyWriter. Более вероятно, что вызовы NtWriteFile (в расширении WriteFile) занимают так много времени, что один или несколько вызовов Windows API WriteFile могут занять более 70 секунд!

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

x sqlmin!*stack*

<несколько строк>

sqlmin!g_copiedStackInfo

<ещё несколько строк>

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

.cxr sqlmin!g_copiedStackInfo+0x20; kc

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

00 ntdll!NtSetEvent

01 KERNELBASE!SetEvent

02 sqldk!SOS_Scheduler::ResumeNoCuzz

03 sqlmin!EventInternal<SuspendQueueSLock>::Signal

04 sqlmin!BPool::WritePageCompletion

05 sqlmin!FCB::IoCompletion

06 sqldk!IOQueue::CheckForIOCompletion

07 sqldk!IOQueue::Insert

08 sqlmin!SOS_Scheduler::AddIOCompletionRequest

09 sqlmin!DiskWriteAsync

0a sqlmin!FCB::AsyncWriteInternal

0b sqlmin!FCB::AsyncWrite

0c sqlmin!RecoveryUnit::GatherWrite

0d sqlmin!BPool::LazyWriter

0e sqlmin!lazywriter

0f sqldk!SOS_Task::Param::Execute

10 sqldk!SOS_Scheduler::RunTask

11 sqldk!SOS_Scheduler::ProcessTasks

12 sqldk!SchedulerManager::WorkerEntryPoint

13 sqldk!SystemThread::RunWorker

14 sqldk!SystemThreadDispatcher::ProcessWorker

15 sqldk!SchedulerManager::ThreadEntryPoint

16 kernel32!BaseThreadInitThunk

17 ntdll!RtlUserThreadStart

Ка видно стеки не совпадают, но они все еще про LazyWriter, и оба имеют элементы в режиме ядра вверху стека. Это совпадает с данными из журнала ошибок, в котором указано, что большую часть времени задача провела в режиме ядра. Чтобы не повторяться слишком часто, и поскольку у нас есть только общедоступные символы, невозможно копнуть слишком глубоко (если приспичит, мы можем получить дополнительную информацию на основе регистров и, зная вызываемый Windows API [у нас всё это есть!]).

Подводя итог (не хочу оставлять никого в подвешенном состоянии), если в вашей среде произошел дамп с уликами подобными этим, то проверьте системы с точки зрения ядра и исполнительной системы, а также то, что делают другие приложения. Следующим шагом проверки будет сам сервер. Судя по приведенным выше данным, это не проблема, связанная с SQL Server. Вы заметите, что дамп памяти в пользовательском режиме - это всего лишь моментальный снимок во времени, он не хранит то, что делают другие приложения, состояние системы, какие-либо счетчики производительности и т. п. Поэтому отбросьте свои страхи о том, что дампы памяти — это конец всему, всё сводится к анализу первопричин, и, как правило, у вас никогда не будет всей необходимой информации.

Демистификация дампов: Non-Yielding Scheduler