В арсенале Microsoft SQL Server есть одна интересная штука – service broker. По сути своей это очередь сообщений, встроенная в СУБД, способная обеспечить транзакционную целостность данных. Вещь удобная и, в грамотных руках, способная выстроить систему обмена между SQL Server’ами без применения дополнительных внешних сервисов – прямо из коробки.

С одной стороны service broker удобен, но с другой – от него не мало сюрпризов, способных поломать голову нюансами своей работы. О решении одного из таких сюрпризов поговорим прямо сейчас.

Обнаружили, что логи MS SQL Server, одной из наших, систем жутко забиты сообщениями от service broker типа :

An error occurred in dialog transmission: Error: 601, State: 3.
Could not continue scan with NOLOCK due to data movement.

Не долгие поиски на просторах всемирной сети так или иначе выводили на информацию о том, что какие то данные в БД закораптились и требуется их обнаружение (для дальнейшего восстановления) при помощи инструкции DBCC CHECKDB. Счастье было не долгим, ибо данный подход не выявил ни одной проблемы – ни в пользовательских БД, ни в системных.

Так как логи продолжали ужасать своим натиском (пару десятков записей за несколько секунд), а первый план по выявлению причин этого “наводнения” провалился – было решено вести поиски на стороне service broker, ибо читался след от брокера – как минимум по словам “dialog transmission ”.

Подобные поиски в системах начинаются с просмотра очереди на отправку sys.transmission_queue – не стал исключением и наш случай. Первый же select из sys.transmission_queue вывалил на экран тот самый “Could not continue scan with NOLOCK due to data movement”, что с одной стороны вселило уверенности, что копаем в правильную сторону, но с другой – как выявить проблему, если select заканчивается таким сообщением?

Лезем в данные по конечным точкам диалогов sys.conversation_endpoints. С ужасом обнаруживаю, что там висит около 12 миллионов не закрытых диалогов. Первые 10 минут зачистки ненужных накоплений показали, что впереди нас ждет целая неделя ожиданий – ибо чистка протекала крайне медленно. Само закрытие диалога было долгим. У нас был главный подозреваемый — куча не закрытых диалогов service broker'а и надо было его “расколоть”.

Так как сидеть целую неделю, и закрывать диалоги не хотелось, был накидан такой план:

1. через sqlcmd пачками вычитываем хендлеры подвисших диалогов

2. формируем sql batch на завершение полученых диалогов

3. через sqlcmd выполняем сформированный sql batch и гоняем это по циклу, пока не закроем все подвисшие диалоги

set nocount on;
select 'set nocount on;'
union all
select 'set xact_abort off;'
union all
select top 900 'end conversation ''' + cast(conversation_handle as varchar(100)) + ''' with cleanup;'  from sys.conversation_endpoints where far_service = '//far_db.far_host/far_service'

batch.sql (пример sql batch – для пункта 2)

@echo off 
for /L %%B in (0,1,13000) do (
    sqlcmd -i c:\usr\sql_cd.sql -o c:\usr\res.sql -S server_name -d db_name -r1 
    sqlcmd -i c:\usr\res.sql  -S server_name -d db_name -r1 
    del c:\usr\res.sql
)

end_conversation.bat (батник для пунктов 1 и 3)

Этот товарищ отработал чуть менее двух суток и закрыл все подвисшие диалоги. Как видно из примера – все эти диалоги были открыты для одного конкретного сервиса. С самим удаленным сервисом брокера разобрались до начала массового закрытия диалогов.

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

Следующей мыслью было потушить service broker end point на СУБД в целом и отключить брокер на основной БД в частности, но и это, увы, не спасло от продолжающихся ошибок в логах.

В какой то из дней решения вопроса возникла необходимость переключиться на зеркало от основной БД. Именно в момент переключения на зеркало нашей БД и вылезла в логах информация о проблеме:

16:42:40.41 spid41s SQL Server detected a logical consistency-based I/O error: incorrect pageid (expected 6:260707; actual 559:-641654744). It occurred during a read of page (6:260707) in database ID 2 at offset 0x0000007f4c6000 in file 'D:\TempDB\tempdb_mssql_5.ndf'. Additional messages in the SQL Server error log or operating system error log may provide more detail. This is a severe error condition that threatens database integrity and must be corrected immediately. Complete a full database consistency check (DBCC CHECKDB). This error can be caused by many factors; for more information, see SQL Server Books Online.

Глядя на неё и стало понятно, что виновником торжества выступает tempdb нашей СУБД.

Как известно, у tempdb одно лекарство – рестарт службы sql. Выбиваем окно у бизнеса для простоя сервиса и перезагружаем основную ноду. После рестарта сервера логи перестало заваливать.

Как оказалось – проблема на самом деле крылась в закорапченных данных. Так, что применяя DBCC CHECKDB – не забывайте применять его и к tempdb и следите за диалогами.