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 (Vincent Delabre) [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]