Ожидания SOS_SCHEDULER_YIELD и спин-блокировка LOCK_HASH

Автор: Paul Randal, SOS_SCHEDULER_YIELD waits and the LOCK_HASH spinlock

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

Первоначально я опубликовал эту статью, а затем обсудил его с моим хорошим другом Бобом Уордом (Bob Ward) из службы поддержки продуктов, который усомнился в моих выводах, основываясь на своём опыте (спасибо, Боб!). После более глубокого исследования я обнаружил, что моя первоначальная версия была неверной, поэтому это исправленная версия.

Ожидание SOS_SCHEDULER_YIELD означает, что выполняющийся поток добровольно уступил процессор, чтобы позволить другим потокам выполняться. Код SQL Server «усыпан» местами, где происходит «добровольная уступка» (voluntary yield) — там, где может возникать высокая загрузка процессора.

Одно из таких мест, где поток «засыпает», но явно не уступает, — это отступление (backoff) после коллизии спин-блокировки в ожидании, чтобы увидеть, сможет ли он получить доступ к спин-блокировке. Спин-блокировка — это очень легковесный механизм синхронизации глубоко внутри SQL Server, который защищает доступ к структуре данных (не к самим данным базы данных). 

Когда поток добровольно уступает, он не попадает в список ожидающих задач — так как он ничего не ожидает, — а вместо этого переходит в конец очереди планировщика, готовых к выполнению (Runnable Queue). Сами по себе ожидания SOS_SCHEDULER_YIELD не являются причиной для беспокойства, если только они не составляют большинство ожиданий в системе и производительность не страдает.

Для настройки теста я создам простую базу данных и таблицу:

USE [master];
GO
DROP DATABASE [YieldTest];
GO
 
CREATE DATABASE [YieldTest];
GO
USE [YieldTest];
GO
 
CREATE TABLE [SampleTable] ([c1] INT IDENTITY);
GO
CREATE NONCLUSTERED INDEX [SampleTable_NC] ON [SampleTable] ([c1]);
GO
 
SET NOCOUNT ON;
GO
INSERT INTO [SampleTable] DEFAULT VALUES;
GO 100

Затем я очищу статистику ожиданий и защёлок (кратких, легковесных блокировок):

DBCC SQLPERF (N'sys.dm_os_latch_stats', CLEAR);
GO
 
DBCC SQLPERF (N'sys.dm_os_wait_stats', CLEAR);
GO

И затем запущу 50 клиентов, выполняющих следующий код (у меня просто CMD-скрипт, который открывает 50 окон CMD, каждое из которых выполняет T-SQL-код):

USE [YieldTest];
GO
SET NOCOUNT ON;
GO
 
DECLARE @a INT;
WHILE (1=1)
BEGIN
    SELECT @a = COUNT (*) FROM [YieldTest]..[SampleTable] WHERE [c1] = 1;
END;
GO

И процессоры на моём ноутбуке полностью забиты. Загрузка процессора не является временем пользовательского режима Windows (% User Time), и из всех счётчиков, которые я обычно отслеживаю, я вижу устойчиво высокое количество запросов блокировок в секунду для блокировок объектов и страниц (почти 950 тысяч запросов в секунду для обоих типов! Обожаю свой ноутбук :-)

Итак, давайте копнём глубже. Во-первых, взглянем на статистику ожиданий:

WaitType            Wait_S  Resource_S Signal_S WaitCount Percentage AvgWait_S AvgRes_S AvgSig_S
------------------- ------- ---------- -------- --------- ---------- --------- -------- --------
SOS_SCHEDULER_YIELD 4574.77 0.20       4574.57  206473    99.43      0.0222    0.0000   0.0222

SOS_SCHEDULER_YIELD почти на 100% ожиданий в системе означает, что у меня есть нагрузка на процессор — как я видел на графиках процессора выше. Тот факт, что ничего другого не отображается, заставляет меня подозревать, что это проблема со спин-блокировками.

Проверка вывода sys.dm_os_waiting_tasks (см. скрипт во втором посте) показывает, что ничего не ожидает, и если я обновляю несколько раз, я вижу иногда типы ожиданий ASYNC_NETWORK_IO и/или PREEMPTIVE_OS_WAITFORSINGLEOBJECT — что я и ожидал от окон CMD, выполняющих T-SQL-код.

Проверка статистики защёлок не показывает ожиданий защёлок, кроме нескольких ожиданий защёлок BUFFER.

Итак, теперь давайте посмотрим на спин-блокировки. Сначала я сделаю снимок спин-блокировок в системе:

-- Базовый уровень
IF EXISTS (SELECT * FROM [tempdb].[sys].[objects]
    WHERE [name] = N'##TempSpinlockStats1')
    DROP TABLE [##TempSpinlockStats1];
GO
SELECT * INTO [##TempSpinlockStats1]
FROM sys.dm_os_spinlock_stats
WHERE [collisions] > 0
ORDER BY [name];
GO

Затем ждём 10 секунд или около того, пока нагрузка продолжается... и затем ещё один снимок спин-блокировок:

-- Захват обновлённой статистики
IF EXISTS (SELECT * FROM [tempdb].[sys].[objects]
    WHERE [name] = N'##TempSpinlockStats2')
    DROP TABLE [##TempSpinlockStats2];
GO
SELECT * INTO [##TempSpinlockStats2]
FROM sys.dm_os_spinlock_stats
WHERE [collisions] > 0
ORDER BY [name];
GO

Теперь запускаем код, который я придумал, чтобы показать разницу между двумя снимками:

-- Разница между ними
SELECT
    '***' AS [New],
    [ts2].[name] AS [Spinlock],
    [ts2].[collisions] AS [DiffCollisions],
    [ts2].[spins] AS [DiffSpins],
    [ts2].[spins_per_collision] AS [SpinsPerCollision],
    [ts2].[sleep_time] AS [DiffSleepTime],
    [ts2].[backoffs] AS [DiffBackoffs]
FROM [##TempSpinlockStats2] [ts2]
LEFT OUTER JOIN [##TempSpinlockStats1] [ts1]
    ON [ts2].[name] = [ts1].[name]
WHERE [ts1].[name] IS NULL
UNION
SELECT
    '' AS [New],
    [ts2].[name] AS [Spinlock],
    [ts2].[collisions] - [ts1].[collisions] AS [DiffCollisions],
    [ts2].[spins] - [ts1].[spins] AS [DiffSpins],
    CASE ([ts2].[spins] - [ts1].[spins]) WHEN 0 THEN 0
        ELSE ([ts2].[spins] - [ts1].[spins]) /
            ([ts2].[collisions] - [ts1].[collisions]) END
            AS [SpinsPerCollision],
    [ts2].[sleep_time] - [ts1].[sleep_time] AS [DiffSleepTime],
    [ts2].[backoffs] - [ts1].[backoffs] AS [DiffBackoffs]
FROM [##TempSpinlockStats2] [ts2]
LEFT OUTER JOIN [##TempSpinlockStats1] [ts1]
    ON [ts2].[name] = [ts1].[name]
WHERE [ts1].[name] IS NOT NULL
    AND [ts2].[collisions] - [ts1].[collisions] > 0
ORDER BY [New] DESC, [Spinlock] ASC;
GO

New  Spinlock                        DiffCollisions DiffSpins  SpinsPerCollision DiffSleepTime DiffBackoffs
---- ------------------------------- -------------- ---------- ----------------- ------------- ------------
     LOCK_HASH                       6191134        4005774890 647               686           1601383
     OPT_IDX_STATS                   1164849        126549245  108               57            7555
     SOS_OBJECT_STORE                73             305        4                 0             0
     SOS_WAITABLE_ADDRESS_HASHBUCKET 115            44495      386               0             3
     XDESMGR                         1              0          0                 0             0

Это говорит мне о том, что существует огромная конкуренция за спин-блокировку LOCK_HASH, что дополнительно подтверждается спин-блокировкой OPT_IDX_STATS (которая контролирует доступ к метрикам, отслеживаемым sys.dm_db_index_usage_stats). Спин-блокировка LOCK_HASH защищает доступ к хеш-корзинам, используемым менеджером блокировок для эффективного отслеживания ресурсов блокировок, удерживаемых внутри SQL Server, и для эффективного поиска коллизий хешей блокировок (т.е. удерживает ли кто-то блокировку в несовместимом режиме?). В данном случае конкуренция настолько сильна, что вместо простого «кручения» потоки фактически «отступают» (backing off) и позволяют другим потокам выполняться, чтобы обеспечить прогресс.

И это имеет полный смысл из-за того, что делает моя нагрузка: 50 одновременных подключений пытаются прочитать одну и ту же строку на одной и той же странице в одном и том же некластерном индексе.

Но является ли это причиной ожиданий SOS_SCHEDULER_YIELD? Чтобы доказать это так или иначе, я создал сеанс расширенных событий, который захватывал бы стеки вызовов при возникновении ожидания:

-- Примечание: до SQL 2012 используйте wait_type = 120,
-- а на 2014 SP1 используйте wait_type = 123. Вы ОБЯЗАНЫ проверить
-- map_value для вашей сборки.
-- В SQL 2012 имя цели 'histogram', но старое имя всё ещё работает.
CREATE EVENT SESSION [MonitorWaits] ON SERVER
ADD EVENT [sqlos].[wait_info]
    (ACTION ([package0].[callstack])
    WHERE [wait_type] = 124) -- только SOS_SCHEDULER_YIELD
ADD TARGET [package0].[asynchronous_bucketizer] (
    SET filtering_event_name = N'sqlos.wait_info',
    source_type = 1, -- source_type = 1 означает действие
    source = N'package0.callstack') -- группировка по стеку вызовов
WITH (MAX_MEMORY = 50MB, max_dispatch_latency = 5 seconds)
GO
 
-- Запуск сеанса
ALTER EVENT SESSION [MonitorWaits] ON SERVER STATE = START;
GO
 
-- Трассировочный флаг для разрешения стека вызовов
DBCC TRACEON (3656, -1);
--DBCC TRACEON (2592, -1); -- SQL Server 2019+ требует и этот
GO
 
-- Пусть нагрузка выполняется несколько секунд
 
-- Получение стеков вызовов из цели-«бакетизатора»
-- Показывают ли они вызовы в менеджер блокировок?
SELECT
    [event_session_address],
    [target_name],
    [execution_count],
    CAST ([target_data] AS XML)
FROM sys.dm_xe_session_targets [xst]
INNER JOIN sys.dm_xe_sessions [xs]
    ON ([xst].[event_session_address] = [xs].[address])
WHERE [xs].[name] = N'MonitorWaits';
GO
 
-- Остановка сеанса событий
ALTER EVENT SESSION [MonitorWaits] ON SERVER STATE = STOP;
GO

Я также убедился, что у меня есть правильные файлы символов в каталоге \binn. После выполнения нагрузки и анализа стеков вызовов я обнаружил, что большинство ожиданий исходили из добровольных уступок глубоко в коде методов доступа (Access Methods). Пример стека вызовов:

IndexPageManager::GetPageWithKey+ef [ @ 0+0x0
GetRowForKeyValue+146 [ @ 0+0x0
IndexRowScanner::EstablishInitialKeyOrderPosition+10a [ @ 0+0x0
IndexDataSetSession::GetNextRowValuesInternal+7d7 [ @ 0+0x0
RowsetNewSS::FetchNextRow+12a [ @ 0+0x0
CQScanRangeNew::GetRow+6a1 [ @ 0+0x0
CQScanCountStarNew::GetRowHelper+44 [ @ 0+0x0
CQScanStreamAggregateNew::Open+70 [ @ 0+0x0
CQueryScan::Uncache+32f [ @ 0+0x0
CXStmtQuery::SetupQueryScanAndExpression+2a2 [ @ 0+0x0
CXStmtQuery::ErsqExecuteQuery+2f8 [ @ 0+0x0
CMsqlExecContext::ExecuteStmts<1,1>+cca [ @ 0+0x0
CMsqlExecContext::FExecute+58b [ @ 0+0x0
CSQLSource::Execute+319

Это явно (для меня) не связано со спин-блокировкой LOCK_HASH, так что это ложный след. В данном случае я просто ограничен процессором. Когда поток «засыпает» при отступлении от спин-блокировки, он напрямую вызывает Windows Sleep() — поэтому это вообще не отображается как тип ожидания SQL Server, даже несмотря на то, что вызов сна происходит из слоя SQLOS. Что обидно.

Как обойти это и снизить использование процессора? Это действительно искусственная нагрузка, но такое может происходить и в реальности. Даже если я попытаюсь использовать WITH (NOLOCK), поиск с NOLOCK захватит блокировку стабильности схемы таблицы (SCH-S) для гарантии того, что структура таблицы не изменится во время поиска, так что это избавляет только от блокировок страниц, но не от блокировок объектов и не помогает загрузке процессора. С этой (возможно, странной) нагрузкой я мог бы сделать несколько вещей (просто с ходу):

• Включить read_commited_snapshot для базы данных, что уменьшит количество отступлений от спин-блокировки LOCK_HASH
• Распределить подключения по нескольким копиям базы данных, обновляемым с помощью репликации
• Реализовать кэширование на среднем уровне или на стороне клиента с механизмом уведомления об изменениях данных (например, с помощью DDL-триггера, отправляющего сообщение Service Broker)

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

В следующий раз мы рассмотрим другую причину ожиданий SOS_SCHEDULER_YIELD.