


Petit mémento pour retrouver la fonction à l’origine d’un SOS non yielding ou un IOCP non yielding. On va en profiter pour rappeler les conditions de détection des deux phénomènes. On part sur une version >= 2005.
Pour mémoire, cette condition de “non-relâche” (non-yielding) d’un scheduler ou d’un IO Completion Port a été implémentée en SQL Server 2000 SP3 à la demande du support, pour permettre de diagnostiquer plus facilement les cas où une fonction bloque un scheduler (qui fonctionne depuis SQL 7.0 dans un mode coopératif rappelons-le). Depuis SQL Server 2005, un thread système a la charge de détecter ces conditions, le Scheduler Monitor.
Erreur 17883, non-yielding Scheduler :
Depuis SQL Server 2005, le Scheduler Monitor se réveille toutes les 5 secondes et lance un check simple (un genre de LooksAlive). Si l’ensemble des hypothèses suivantes sont vérifiées:
– Le scheduler n’est pas idle (il travaille quoi…)
– Le nombre de yields n’a pas évolué depuis le dernier contrôle
– Le worker actif n’est pas déjà dans une exception ou en train de générer un minidump.
… alors le scheduler est considéré comme potentiellement bloqué, et un contrôle un peu plus poussé va suivre (genre de isAlive). Si le worker accumule 10 secondes sans avoir bougé (donc consécutivement à 2 checks simples), le Scheduler Monitor va vérifier si la somme des temps (kernel + user) accumulés par le worker depuis le début de son exécution:
– Est inférieure ou égale à 5% au temps total instance (reporté dans sys.dm_os_sys_info): désigne typiquement les cas où le worker est coincé en attente du retour d’une API externe (exemple typique, WriteFileGather() sur un filesystem encrypté ou compressé, le filter driver de l’antivirus qui retarde l’IO, ou les outils d’encryption 3rd party, le chemin vers la baie qui est en échec …)
– Est supérieure ou égale à 40% du temps total instance [1]: désigne typiquement les cas où le worker est dans une boucle infinie (cas fréquents avec de l’exécution SQLCLR).
– Et que tous les schedulers ne sont pas à 100% de charge (donc qu’il y a des cycles sous le coude)
Alors le scheduler est définitivement considéré comme bloqué et le callback de capture va se mettre en place. Au bout de 60 secondes où la condition de non-yield est maintenue, un minidump (*.mdmp) contenant la stack de tous les threads est capturé par SQLDumper sous ~MSSQL\Log. Il ne contient pas tout l’espace mémoire alloué, ce qui serait en 64 bits franchement impraticable, c’est pour ça que ça s’appelle un minidump. Ca veut dire aussi qu’on ne verra pas nécessairement tout dans le dump.
Il est important de noter que le minidump ne sera pris qu’une seule fois, même si la condition persiste au delà des 60 secondes. Il faudra soit utiliser le TF 1262 ou redémarrer l’instance pour réarmer la condition. En outre, si à l’installation vous avez coché les cases ‘Watson’ (error reporting), le minidump sera envoyé à un des serveurs de reporting de MS.
[1] Note: si la valeur se trouve entre 5 et 40%, on considère que le worker est victime de facteurs externes (pagination, autres processes avec une priorité plus élevée) et un minidump dans ce cas ne sert à rien.
Dans l’ERRORLOG, une belle stack trace:
- 2011-07-24 22:17:45.850 Server * BEGIN STACK DUMP:
- 2011-07-24 22:17:45.850 Server * 07/24/11 22:17:45 spid 2388
- 2011-07-24 22:17:45.850 Server *
- 2011-07-24 22:17:45.850 Server * Non-yielding Scheduler
- 2011-07-24 22:17:45.850 Server Stack Signature for the dump is 0x00000000000003B6
- 2011-07-24 22:17:53.380 Server External dump process return code 0×20000001.
- (...)
Erreur 17887, non yielding IOCP Listener:
Un IO Completion Port est un outil fourni par l’API win32 pour gérer efficacement les entrées sorties asynchrones (cf article sur les IO asynchrones). Dans SQL Server il sert à gérer les demandes de connexion.
Cette condition a été ajoutée avec la version SQL Server 2005 pour détecter les cas où l’IOCP est bloqué et ne peut plus gérer de nouvelles demandes de connexion. L’ensemble des hypothèses suivantes doivent être réunies pour valider la condition d’IOCP bloqué:
– Un IOCP est actif
– Pas de nouvelle demande n’a été postée sur le port depuis le dernier check (toutes les 5 secondes)
– La situation persiste depuis au moins 10 secondes (donc deux checks basiques comme pour l’erreur 17883).
– SQL Server n’est ni sous pression CPU ni sous pression mémoire.
Dans ces conditions, un minidump est capturé exactement comme pour l’erreur 17883. Et là aussi une belle stack trace :
- 2013-08-08 16:05:41.93 Server Using 'dbghelp.dll' version '4.0.5'
- 2013-08-08 16:05:42.08 Server **Dump thread - spid = 0, EC = 0x0000000000000000
- 2013-08-08 16:05:42.09 Server ***Stack Dump being sent to K:\MSSQL10_50.MSSQLSERVER\MSSQL\LOG\SQLDump0001.txt
- 2013-08-08 16:05:42.09 Server * *******************************************************************************
- 2013-08-08 16:05:42.09 Server *
- 2013-08-08 16:05:42.09 Server * BEGIN STACK DUMP:
- 2013-08-08 16:05:42.09 Server * 08/08/13 16:05:42 spid 1996
- 2013-08-08 16:05:42.09 Server *
- 2013-08-08 16:05:42.09 Server * Non-yielding IOCP Listener
- 2013-08-08 16:05:42.09 Server *
- 2013-08-08 16:05:42.09 Server * *******************************************************************************
- 2013-08-08 16:05:42.09 Server * -------------------------------------------------------------------------------
- 2013-08-08 16:05:42.09 Server * Short Stack Dump
- 2013-08-08 16:05:42.32 Server Stack Signature for the dump is 0x0000000000000056
- 2013-08-08 16:06:04.10 Server External dump process return code 0x20000001.
- External dump process returned no errors.
- 2013-08-08 16:06:04.10 Logon Error: 17803, Severity: 20, State: 17.
- 2013-08-08 16:06:04.10 Logon There was a memory allocation failure during connection establishment. Reduce nonessential
- memory load, or increase system memory. The connection has been closed. [CLIENT: 194.26.22.110]
Une ligne est particulièrement intéressante:
- 2013-08-08 16:06:04.13 Server IO Completion Listener (0xce8) Worker 0x00000000006AE1A0 appears to be non-yielding on
- Node 0. Approx CPU Used: kernel 46 ms, user 9609 ms, Interval: 14999.
- 2013-08-08 16:06:59.65 spid88
Où 0xce8 désigne le ThreadID de notre bloquant.
Exemple avec une 17887:
Pour ouvrir le minidump, il faut utiliser windbg et déclarer les symboles dans la bonne version de SQL Server soit en déclarant le serveur de symboles de MS comme décrit dans l’article sur SATA, soit en récupérant le PDB de sqlservr comme décrit par Paul Randal ici.
La particularité du minidump dans ce cas, est qu’il contient outre la stack de tous les threads, une copie de la structure CONTEXT du thread qui bloque au moment précis où l’exception est levée, qui sera accessible dans le debugger via la commande .cxr. CONTEXT contient la valeur des registres du CPU sur lequel notre bloqueur était en exécution, et nous informe sur la stack exacte impliquée dans notre problème, car parfois la situation peut se débloquer entre le moment où l’exception est détectée et le minidump généré. La stack du thread ne serait alors plus valide, voire plus disponible du tout. Ca permet aussi de vérifier si le worker n’a pas progressé au dernier moment.
Alors on y va, on lance windbg, et on charge le minidump File -> Open Crash Dump …
- Loading Dump File [E:\SQLDump0001.mdmp]
- Comment: 'Stack Trace'
- Comment: 'Non-yielding IOCP Listener'
- User Mini Dump File: Only registers, stack and portions of memory are available
- Symbol search path is: SRV*e:\symbols*http://msdl.microsoft.com/download/symbols;E:\Symbols;E:\DENALI\MSSQL11.DENALI\MSSQL\Binn
- Executable search path is:
- Windows 7 Version 7601 (Service Pack 1) MP (2 procs) Free x64
- Product: Server, suite: Enterprise TerminalServer SingleUserTS
- Machine Name:
- Debug session time: Thu Aug 8 15:06:03.000 2013 (UTC + 2:00)
- System Uptime: 20 days 20:56:11.890
- Process Uptime: 8 days 3:28:59.000
- ................................................................
- .....................................................
- Loading unloaded module list
- .....................................................................
- This dump file has an exception of interest stored in it.
- The stored exception information can be accessed via .ecxr.
- (a44.7cc): Unknown exception - code 00000000 (first/second chance not available)
- ntdll!NtWaitForSingleObject+0xa:
- 00000000`77c3135a c3 ret
On va aller chercher la dernière stack de notre worker bloquant. On prend le contexte courant du thread 0xce8 (ThreadID = 3304):
- 0:006> ~~[0xce8]s
- sqlservr!BufferPartition::Steal+0x2d:
- 00000000`00a4da41 0f85b5100900 jne sqlservr!BufferPartition::Steal+0x2f (00000000`00adeafc) [br=0]
Et on affiche la stack:
- 0:005> k
- Child-SP RetAddr Call Site
- 00000000`067aeb30 00000000`00a4dc19 sqlservr!BufferPartition::Steal+0x2d
- 00000000`067aeb70 00000000`00a4e730 sqlservr!BPool::Steal+0x16f
- 00000000`067aec40 00000000`00a4e330 sqlservr!SQLSinglePageAllocator::AllocatePages+0x30
- 00000000`067aec70 00000000`00a4e537 sqlservr!MemoryNode::AllocatePagesInternal+0xfc
- 00000000`067aef10 00000000`00a4e7e1 sqlservr!MemoryClerkInternal::AllocatePages+0xaa
- 00000000`067aef60 00000000`00a4e77b sqlservr!CVarPageMgr::PviNewVarPage+0x41
- 00000000`067aefd0 00000000`00a36fe9 sqlservr!CVarPageMgr::PbAllocate+0x161
- 00000000`067af010 00000000`00e3d5cd sqlservr!CMemObj::Alloc+0x49
- 00000000`067af050 00000000`00e3d39c sqlservr!CErrorReportingManager::CwchFormatToBuffer+0x253
- 00000000`067af1b0 00000000`00e6bba1 sqlservr!CErrorReportingManager::CwchCallFormatToBuffer+0x18
- 00000000`067af1f0 00000000`02acecc2 sqlservr!CLoginClientInfo::CLoginClientInfo+0x61
- 00000000`067af270 00000000`0107e3a4 sqlservr!ReportLoginFailureBySNIConn+0x5a
- 00000000`067af360 00000000`026cb3a3 sqlservr!TDSSNIClient::AcceptCommon+0x3f2
- 00000000`067af660 00000000`00a7daf2 sqlservr!Smux::ReadDone+0x413
- 00000000`067af700 00000000`00a7dc11 sqlservr!SNIReadDone+0xa2
- 00000000`067af770 00000000`00a3bbd8 sqlservr!SOS_Node::ListenOnIOCompletionPort+0x263
- 00000000`067af900 00000000`00a3b8ba sqlservr!SOS_Task::Param::Execute+0x12a
- 00000000`067afa10 00000000`00a3b6ff sqlservr!SOS_Scheduler::RunTask+0x96
- 00000000`067afa70 00000000`00f58fb6 sqlservr!SOS_Scheduler::ProcessTasks+0x128
- 00000000`067afae0 00000000`00f59175 sqlservr!SchedulerManager::WorkerEntryPoint+0x2b6
- 00000000`067afbc0 00000000`00f59839 sqlservr!SystemThread::RunWorker+0xcc
- 00000000`067afc00 00000000`00f59502 sqlservr!SystemThreadDispatcher::ProcessWorker+0x2db
- 00000000`067afcb0 00000000`755937d7 sqlservr!SchedulerManager::ThreadEntryPoint+0x173
- 00000000`067afd50 00000000`75593894 msvcr80!endthreadex+0x47
- 00000000`067afd80 00000000`77ad652d msvcr80!endthreadex+0x104
- 00000000`067afdb0 00000000`77c0c521 kernel32!BaseThreadInitThunk+0xd
- 00000000`067afde0 00000000`00000000 ntdll!RtlUserThreadStart+0x1d
On voit qu’on est bien sur un bon problème mémoire, d’après les derniers appels (SQLSinglePageAllocator::AllocatePages(), BPool:Steal(), BufferPartition::Steal() ). Plus haut dans la stack, on voit les appels vers SNI (connexions réseau): SOS_Node::ListenOnIOCompletionPort(), SNIReadDone(), Smux::ReadDone(), TDSSNIClient::AcceptCommon() … On ne peut pas vraiment en dire plus à ce niveau là.
Quand au contenu de la structure CONTEXT au moment de l’exception, il va falloir faire une petite gymnastique pour retrouver le bon offset. On sait juste que la structure CONTEXT est copiée dans une autre structure appelée g_copiedStackInfo par SQLDumper. On va chercher où se trouve cette structure dans le minidump en utilisant la commande explore (‘x’):
- 0:005> x sqlservr!g_copiedStackInfo
- 00000000`04036900 sqlservr!g_copiedStackInfo = <no type information>
Si on regarde dans winnt.h la définition de CONTEXT:
- typedef struct _CONTEXT
- {
- DWORD ContextFlags;
- /* These are selected by CONTEXT_DEBUG_REGISTERS */
- DWORD Dr0;
- DWORD Dr1;
- DWORD Dr2;
- DWORD Dr3;
- DWORD Dr6;
- DWORD Dr7;
- /* These are selected by CONTEXT_FLOATING_POINT */
- FLOATING_SAVE_AREA FloatSave;
- /* These are selected by CONTEXT_SEGMENTS */
- DWORD SegGs;
- DWORD SegFs;
- DWORD SegEs;
- DWORD SegDs;
- /* These are selected by CONTEXT_INTEGER */
- DWORD Edi;
- DWORD Esi;
- DWORD Ebx;
- DWORD Edx;
- DWORD Ecx;
- DWORD Eax;
- /* These are selected by CONTEXT_CONTROL */
- DWORD Ebp;
- DWORD Eip;
- DWORD SegCs;
- DWORD EFlags;
- DWORD Esp;
- DWORD SegSs;
- BYTE ExtendedRegisters[MAXIMUM_SUPPORTED_EXTENSION];
- } CONTEXT;
Chaque propriété est un DWORD, donc un dd pour lire le contenu doit suffire:
- 0:005> dd sqlservr!g_copiedStackInfo
- 00000000`04036900 00000001 00000000 069ef240 00000000
- 00000000`04036910 000015e0 00000000 00000000 00000000
- 00000000`04036920 00000000 00000000 00000000 00000000
- 00000000`04036930 00000000 00000000 00000000 00000000
- 00000000`04036940 00000000 00000000 00000000 00000000
- 00000000`04036950 0010000b 00001fa0 00000033 00000000
- 00000000`04036960 002b0000 00000297 00000000 00000000
- 00000000`04036970 00000000 00000000 00000000 00000000
Chaque ligne représente une structure CONTEXT. Il faut trouver laquelle est la bonne, malheureusement je n’ai pas les symboles privés donc je ne vais pas pouvoir résoudre le contenu de g_copiedStackInfo, comme me l’indique ce message laconique de windbg:
- 0:005> dt 00000000`04036900 CONTEXT Rip Rsp Rbp
- *************************************************************************
- *** ***
- *** ***
- *** Either you specified an unqualified symbol, or your debugger ***
- *** doesn't have full symbol information. Unqualified symbol ***
- *** resolution is turned off by default. Please either specify a ***
- *** fully qualified symbol module!symbolname, or enable resolution ***
- *** of unqualified symbols by typing ".symopt- 100". Note that ***
- *** enabling unqualified symbol resolution with network symbol ***
- *** server shares in the symbol path may cause the debugger to ***
- *** appear to hang for long periods of time when an incorrect ***
- *** symbol name is typed or the network symbol server is down. ***
- *** ***
- *** For some commands to work properly, your symbol path ***
- *** must point to .pdb files that have full type information. ***
- *** ***
- *** Certain .pdb files (such as the public OS symbols) do not ***
- *** contain the required information. Contact the group that ***
- *** provided you with these symbols if you need this command to ***
- *** work. ***
- *** ***
- *** Type referenced: CONTEXT ***
- *** ***
- *************************************************************************
- Symbol CONTEXT not found.
Donc il va falloir charger les contextes un par un pour voir s’il y a qq chose dedans:
- 0:005> .cxr sqlservr!g_copiedStackInfo
- rax=0000000000000000 rbx=0000000000000000 rcx=0000000000000000
- rdx=0000000000000000 rsi=0000000003b82080 rdi=0000000003b80800
- rip=0000000000070fc0 rsp=000000000007ffc7 rbp=0000000003b80800
- r8=00000000069ef240 r9=00000000008b1080 r10=0000000003b82080
- r11=0000000000000001 r12=0000000000007628 r13=aaaaaaaaaaaaaaab
- r14=00000000008b0080 r15=000000000000005e
- iopl=0 nv up di pl nz na pe nc
- cs=0000 ss=0000 ds=0000 es=0000 fs=0000 gs=0000 efl=00000000
- 00000000`00070fc0 0000 add byte ptr [rax],al ds:00000000`00000000=??
- 0:005> kc
- *** Stack trace for last set context - .thread/.cxr resets it
- Call Site
- 0x0
Nada. Frame suivante (qui se situe à l’adresse de base + 0x10 => ( 00000000`04036910 – 00000000`04036900 ) ):
- 0:005> .cxr sqlservr!g_copiedStackInfo+0x10
- rax=0000000000000000 rbx=0000000003b80800 rcx=0000000000000000
- rdx=000000000007ffc7 rsi=00000000069ef240 rdi=00000000008b1080
- rip=0000000000070fc0 rsp=0000000003b82080 rbp=0000000003b80800
- r8=0000000003b82080 r9=0000000000000001 r10=0000000000007628
- r11=aaaaaaaaaaaaaaab r12=00000000008b0080 r13=000000000000005e
- r14=0000000000070fc0 r15=0000000161ffd000
- iopl=1 ov dn ei ng nz na pe nc
- cs=0000 ss=0010 ds=0000 es=0000 fs=0000 gs=000b efl=00001fa0
- 00000000`00070fc0 0000 add byte ptr [rax],al ds:00000000`00000000=??
- 0:005> kc
- *** Stack trace for last set context - .thread/.cxr resets it
- Call Site
- 0x0
- 0x0
Toujours rien. Allons voir à l’adresse suivante:
- 0:005> .cxr sqlservr!g_copiedStackInfo+0x20
- rax=000000000007ffc7 rbx=0000000003b80800 rcx=0000000003b80800
- rdx=0000000003b82080 rsi=0000000003b82080 rdi=0000000000000001
- rip=0000000000a7edb0 rsp=00000000069ef240 rbp=00000000008b1080
- r8=0000000000007628 r9=aaaaaaaaaaaaaaab r10=00000000008b0080
- r11=000000000000005e r12=0000000000070fc0 r13=0000000161ffd000
- r14=0000000000070fc0 r15=0000000000070fcf
- iopl=0 nv up ei ng nz ac po cy
- cs=0033 ss=002b ds=0000 es=0000 fs=0000 gs=0000 efl=00000297
- sqlservr!BPool::MayGrow+0x3b:
- 00000000`00a7edb0 ?? ???
- 0:005> kc
- *** Stack trace for last set context - .thread/.cxr resets it
- Call Site
- sqlservr!BPool::MayGrow
- sqlservr!BPool::ReplenishFreeList
- sqlservr!BPool::Steal
- sqlservr!SQLSinglePageAllocator::AllocatePages
- sqlservr!MemoryNode::AllocatePagesInternal
- sqlservr!MemoryClerkInternal::AllocatePages
- sqlservr!CVarPageMgr::PviNewVarPage
- sqlservr!CVarPageMgr::PbAllocate
- sqlservr!CMemObj::Alloc
- sqlservr!CErrorReportingManager::CwchFormatToBuffer
- sqlservr!CErrorReportingManager::CwchCallFormatToBuffer
- sqlservr!CLoginClientInfo::CLoginClientInfo
- sqlservr!ReportLoginFailureBySNIConn
- sqlservr!TDSSNIClient::AcceptCommon
- sqlservr!Smux::ReadDone
- sqlservr!SNIReadDone
- sqlservr!SOS_Node::ListenOnIOCompletionPort
- sqlservr!SOS_Task::Param::Execute
- sqlservr!SOS_Scheduler::RunTask
- sqlservr!SOS_Scheduler::ProcessTasks
- sqlservr!SchedulerManager::WorkerEntryPoint
- sqlservr!SystemThread::RunWorker
- sqlservr!SystemThreadDispatcher::ProcessWorker
- sqlservr!SchedulerManager::ThreadEntryPoint
- msvcr80!endthreadex
- msvcr80!endthreadex
- kernel32!BaseThreadInitThunk
- ntdll!RtlUserThreadStart
Cette fois on la tient. Et si on compare les deux stacks (celle obtenue via le ThreadID 0xce8 et celle contenue dans la struct CONTEXT), on voit un décalage:
- sqlservr!BPool::MayGrow
- sqlservr!BPool::ReplenishFreeList
Et BPool:MayGrow est une indication que SQL Server demande une allocation supplémentaire pour ajuster Target et Committed. C’est là que ça coince.
Le fichier bugcheck nous renvoie un état de la mémoire sur la machine au moment du problème:
- Memory
- MemoryLoad = 94%
- Total Physical = 4095 MB
- Available Physical = 219 MB
- Total Page File = 8189 MB
- Available Page File = 2072 MB
- Total Virtual = 8388607 MB
- Available Virtual = 8380979 MB
- **Dump thread - spid = 0, EC = 0x0000000000000000
- ***Stack Dump being sent to K:\MSSQL10_50.MSSQLSERVER\MSSQL\LOG\SQLDump0001.txt
6Gb de page file utilisé, 200Mb de libre, MemoryLoad 94%. On n’est pas loin d’une OOM condition.
Et pourquoi donc on en est arrivé là s’il vous plaît ?
Parce que MAX SERVER MEMORY est à sa valeur par défaut !!
Vilaine habitude. Il faut toujours setter max server memory sur 64 bits.
A+ David B.
Références:
– How to diagnose and correct errors 17883, 17884, 17887, and 17888 – Bob Dorr Microsoft SQL Server CSS, Sameer Tejani SQL Server Development SQLOS Team.
– How to analyze Non-Yielding scheduler or Non-yielding IOCP Listener dumps: Karthick P.K
Continuez votre lecture sur le blog :
- SQL Server 2022 : La compression XML (Capdata team) [SQL Server]
- Retrouver la requête à l’origine d’une erreur 8623 “The query processor ran out of internal resources and could not produce a query plan” (David Baffaleuf) [SQL Server]
- Context switch et switch Context (David Baffaleuf) [Operating System]
- [sqsrvres] OnlineThread: SQL Cluster shared data upgrade failed (David Baffaleuf) [SQL Server]
- Mythe: SQL Server associe un thread à chaque connexion (David Baffaleuf) [SQL Server]


