Retrouver la fonction à l’origine d’un Non Yielding IOCP Listener

Lundi, août 12, 2013
By David Baffaleuf in Operating System (dbaffaleuf@capdata-osmozium.com) [70 article(s)]

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

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 + 0×10 => ( 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 :




Cliquer pour partager cet article sur Viadeo
Cliquer sur "CAPTURER" pour sauvegarder cet article dans Evernote Clip to Evernote

Tags: , , ,

One Response to “Retrouver la fonction à l’origine d’un Non Yielding IOCP Listener”

  1. A noter que depuis la version SQL Server 2012, beaucoup de fonctionnalités core ont été déplacées du binaire principal (sqlservr) vers des dll (sqlmin, sqllang, sqldk):

    select * from sys.dm_os_loaded_modules where name like ‘%sqlmin.dll%’
    or name like ‘%sqllang.dll%’
    or name like ‘%sqldk.dll%’;

    En conséquence la structure g_copiedStackInfo se trouve depuis SQL 2012 dans sqlmin et non plus dans sqlservr. Donc si vous voulez suivre les instructions sur une version 2012 ou supérieure, il faudra utiliser sqlmin!g_copiedStackInfo à la place de sqlservr!g_copiedStackInfo.

    A+

    #67373

Leave a Reply