Tag Archives: Debugging

Fiddler: Zachytávání WCF SOAP volání localhost služby

Pokud ladíte projekt s WCF client-server komunikací (WCF SOAP), může se hodit možnost zachytávat tuto komunikaci ve Fiddleru.

Mnoho návodů vám pomůže nastavit Fiddlera jako proxy, pokud chcete zachytávat komunikaci svého WCF clienta se vzdálenou webovou službou. Pokud však serverovou stranu sami vyvíjíte a běží vám právě na localhost, postup dle těchto návodů vám komunikaci nezachytí.

Je potřeba na straně WCF clienta nastavit adresu cílových endpointů pomocí “localhost.fiddler:port”, všude tam, kde dosud máte “localhost”:

<system.serviceModel>
    <client>
        <endpoint address="http://localhost.fiddler:12890/WebServices/MyService.svc" binding="basicHttpBinding" bindingConfiguration="BasicHttpBinding_IMyService" contract="MyApp.IMyService" name="BasicHttpBinding_IMyService"/>
    </client>
</system.serviceModel>

Fiddler: Ignorování requestů (šumu na pozadí)

Kde jsou ty časy, kdy člověk pustil Fiddler Web Debugger a mohl v něm poklidně ladit svojí webovou aplikaci, aniž by se musel probírat stovkami HTTP requestů generovaných ostatními aplikacemi. Dnes je HTTP protokol natolik oblíbený, že použití Fiddler již není tolik pohodlné.

Naštěstí je možné Fiddlerovi říct, jaké requesty má ignorovat (resp. skrýt z UI, “odbavení” nadále provádí). Děje se tak např. prostřednictvím FiddlerScriptu, kde ve funkci OnBeforeRequest můžeme nastavit (výstřižek ze začátku funkce):

    static function OnBeforeRequest(oSession: Session) {       
      
        if (
            (oSession.hostname == "tfs.havit.eu")
            || (oSession.hostname == "outlook.office365.com")
            || (oSession.hostname == "havit.sharepoint.com")
            || (oSession.hostname == "tfs.havit.eu")
            || (oSession.hostname == "vortex.data.microsoft.com")
            || (oSession.hostname == "nexus.officeapps.live.com")
            || (oSession.hostname == "client-api.itunes.apple.com")
            || (oSession.hostname == "iadsdk.apple.com")
            || (oSession.hostname == "roaming.officeapps.live.com")
            || (oSession.hostname == "mobile.pipe.aria.microsoft.com")
            || (oSession.hostname == "play.itunes.apple.com")
        ) {
            oSession["ui-hide"]="yup";
        }

        // pokračování funkce

            

FiddlerScript najdeme v menu Rules pod volbou Customize Rules… “Ideálně” se edituje prostřednictvím FiddlerScript Syntax Highlight doplňku (na jeho instalaci se ptá Fiddler při otevírání položky Customize Rules…):

image

Kromě oSession.hostname můžeme použít i plné oSession.url, nebo další možnosti poskytovaného FiddlerScript API.

[ASP].NET Worst Practices – záznam, slides a dema [Prague .NET Meetup 02/2016]

Slides a dema z mé přednášky pro setkání Prague .NET Meetup ze 17.2.2016:

Záznam z přednášky je publikován na našem HAVIT YouTube Channel.

Dotčená témata

  • Garbage Collector, Finalization, C# Destructors, Resource Wrapper pattern
  • Process Failure, StackOverflow, Windows Debugger, DebugDiag
  • <compilation debug=“true|false“ />, <deployment retail=“true“/>
  • ASP.NET Over-posting / Mass-assignment
  • skládání stringů vs. StringBuilder
  • vyhledávání v datech – List vs. BinnarySearch vs. Dictionary vs. LINQ ToLookup()
  • perly code-review

Advanced Debugging .NET – záznam, slides a dema [ShowIT SK 02/2016]

Slides a dema z mé přednášky pro konferenci Gopas ShowIT Bratislava z 10.2.2016:

Záznam z přednášky je publikován na našem HAVIT YouTube Channel.

Dotčená témata

  • StackOverflow troubleshooting
  • Windows Debugger, SOS, DebugDiag
  • Prozkoumávání zásobníku
  • Prozkoumávání haldy, rootů, finalization queue
  • GC Root identification (static fields)

Advanced Debugging Stories – záznam, slides a dema [MS Fest Praha 11/2015]

Slides a dema z mé přednášky pro konferenci MS Fest Praha z 29.11.2015.

Záznam je publikován na našem HAVIT YouTube Channelu:

Dotčená témata

  • Windows Debugger – SOS.dll
  • DebugDiag – Collection, Analysis
  • StackOverflowException
  • Stack analysis
  • instalace a zprovoznění WinDbg
  • získání memory-dumpu
  • Heap analysis
  • Finalize Queue, F-reachable Queue
  • Garbage Collector
  • rootování, GCRoot
  • statické fieldy

WinDbg+SOS: Prozkoumávání statických fieldů a statických tříd

Když během svých přednášek používám WinDbg, obvykle vše ukazuji na instancích tříd. Dostávám tedy poměrně často otázku, jak prozkoumat hodnoty statických fieldů tříd, nebo dokonce celé statické třídy.

Statické fieldy

Se statickými fieldy instančních tříd je to jednoduché. Při výpisu instance pomocí !DumpObj <addr> (zkráceně !do) získáme výpis, v němž jsou hodnoty statických fieldů přímo vidět:

0:000> .symfix
0:000> .reload
0:000> .loadby sos clr
0:000> !DumpHeap -type System.Web.HttpRuntime
...
0:000> !DumpObj 075d6c30 
Name:        System.Web.HttpRuntime
MethodTable: 6da63274
EEClass:     6d8321cc
Size:        160(0xa0) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_32\System.Web\v4.0_4.0.0.0__b03f5f7f11d50a3a\System.Web.dll
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
7330b12c  4001238        4 ...amedPermissionSet  0 instance 00000000 _namedPermissionSet
732c14d4  4001239        8 ...olicy.PolicyLevel  0 instance 00000000 _policyLevel
73303e18  400123a        c        System.String  0 instance 00000000 _hostSecurityPolicyResolverType
6da63884  400123b       10 ...ileChangesMonitor  0 instance 075d7068 _fcm
6da63df0  400123c       14 ...ing.CacheInternal  0 instance 075d8a5c _cacheInternal
6da63e9c  400123d       18 ...Web.Caching.Cache  0 instance 075d8850 _cachePublic
7330f91c  400123e       7c       System.Boolean  1 instance        0 _isOnUNCShare
6da63760  400123f       1c ...Web.Util.Profiler  0 instance 075d6cd0 _profiler
6da63798  4001240       20 ...estTimeoutManager  0 instance 075d6cec _timeoutManager
6da6fd80  4001241       24 ....Web.RequestQueue  0 instance 0750215c _requestQueue
7330f91c  4001242       7d       System.Boolean  1 instance        0 _apartmentThreading
7330f91c  4001243       7e       System.Boolean  1 instance        1 _processRequestInApplicationTrust
7330f91c  4001244       7f       System.Boolean  1 instance        1 _disableProcessRequestInApplicationTrust
7330f91c  4001245       80       System.Boolean  1 instance        0 _isLegacyCas
7330f91c  4001246       81       System.Boolean  1 instance        0 _beforeFirstRequest
...
73303e18  4001266       6c        System.String  0 instance 00000000 _clientScriptVirtualPath
73303e18  4001267       70        System.String  0 instance 00000000 _clientScriptPhysicalPath
6da63274  4001230      f90 ...m.Web.HttpRuntime  0   shared   static _theRuntime
    >> Domain:Value  01f81230:NotInit 1f443310:0a4d09b4 1e2d62c0:075d6c30 01fc1b88:30105634 51063e70:0aaf2afc <<
73306d34  4001231      f94        System.Byte[]  0   shared   static s_autogenKeys
    >> Domain:Value  01f81230:NotInit 1f443310:0a4d0360 1e2d62c0:075d65dc 01fc1b88:30104fe0 51063e70:0aaf24a8 <<
73303e18  4001232      f98        System.String  0   shared   static DirectorySeparatorString
    >> Domain:Value  01f81230:NotInit 1f443310:0a4d08dc 1e2d62c0:075d6b58 01fc1b88:3010555c 51063e70:0aaf2a24 <<
73303e18  4001233      f9c        System.String  0   shared   static DoubleDirectorySeparatorString
    >> Domain:Value  01f81230:NotInit 1f443310:0a4d08ec 1e2d62c0:075d6b68 01fc1b88:3010556c 51063e70:0aaf2a34 <<
733047d8  4001234      fa0        System.Char[]  0   shared   static s_InvalidPhysicalPathChars
    >> Domain:Value  01f81230:NotInit 1f443310:0a4d0900 1e2d62c0:075d6b7c 01fc1b88:30105580 51063e70:0aaf2a48 <<
7330f91c  4001235      ca2       System.Boolean  1   shared   static s_initialized
    >> Domain:Value  01f81230:NotInit 1f443310:1 1e2d62c0:1 01fc1b88:1 51063e70:1 <<
73303e18  4001236      fa4        System.String  0   shared   static s_installDirectory
    >> Domain:Value  01f81230:NotInit 1f443310:0a4d0928 1e2d62c0:075d6ba4 01fc1b88:301055a8 51063e70:0aaf2a70 <<
7330f91c  4001237      ca3       System.Boolean  1   shared   static s_isEngineLoaded
    >> Domain:Value  01f81230:NotInit 1f443310:1 1e2d62c0:1 01fc1b88:1 51063e70:1 <<
7330652c  4001268      fa8       System.Version  0   shared   static _iisVersion
    >> Domain:Value  01f81230:NotInit 1f443310:024c4a70 1e2d62c0:4209fd30 01fc1b88:3016e81c 51063e70:3e92e40c <<
7330f91c  4001269      ca4       System.Boolean  1   shared   static _useIntegratedPipeline
    >> Domain:Value  01f81230:NotInit 1f443310:1 1e2d62c0:1 01fc1b88:1 51063e70:1 <<
7330f91c  400126a      ca5       System.Boolean  1   shared   static _enablePrefetchOptimization
    >> Domain:Value  01f81230:NotInit 1f443310:0 1e2d62c0:0 01fc1b88:0 51063e70:0 <<
6daa0b50  400126b      fac ...nloadEventHandler  0   shared   static AppDomainShutdown
    >> Domain:Value  01f81230:NotInit 1f443310:00000000 1e2d62c0:00000000 01fc1b88:00000000 51063e70:00000000 <<
6daa3ffc  400126c      fb0 ....FactoryGenerator  0   shared   static s_factoryGenerator
    >> Domain:Value  01f81230:NotInit 1f443310:00000000 1e2d62c0:00000000 01fc1b88:00000000 51063e70:00000000 <<
733060f0  400126d      fb4 ...ections.Hashtable  0   shared   static s_factoryCache
    >> Domain:Value  01f81230:NotInit 1f443310:00000000 1e2d62c0:00000000 01fc1b88:00000000 51063e70:00000000 <<
7330f91c  400126e      ca6       System.Boolean  1   shared   static s_initializedFactory
    >> Domain:Value  01f81230:NotInit 1f443310:0 1e2d62c0:0 01fc1b88:0 51063e70:0 <<
733041b8  400126f      fb8        System.Object  0   shared   static s_factoryLock
    >> Domain:Value  01f81230:NotInit 1f443310:0a4d091c 1e2d62c0:075d6b98 01fc1b88:3010559c 51063e70:0aaf2a64 <<
73303e18  4001270      fbc        System.String  0   shared   static _DefaultPhysicalPathOnMapPathFailure
    >> Domain:Value  01f81230:NotInit 1f443310:00000000 1e2d62c0:00000000 01fc1b88:00000000 51063e70:00000000 <<

Hodnoty statických fieldů jsou ve výstupu !DumpObj přímo vidět. Ve sloupci Attr je uveden shared, ve sloupci Value je uvedeno static a na dalším řádku jsou vyjmenovány hodnoty pro jednotlivé domény. Musíme si zde uvědomit, že každá aplikační doména (AppDomain), jako jednotka izolace, má vlastní statické fieldy. V každé doméně má tedy příslušný typ vlastní hodnoty statických fieldů, popř. tam nemusí být ještě inicializován (NotInit).

Příslušný řádek tedy uvádí pro každou doménu dvojici Domain:Value, přesně jak je naznačeno – vždy adresa příslušné domény a hodnota statického fieldu v ní. (Je zřejmé, že pro libovolnou instanci dostaneme vždy stejný výpis hodnot statických fieldů, instance nám zde slouží jen jako navigace k příslušnému typu.)

Domény

Výpis domén dostaneme příkazem !DumpDomain [addr], bez uvedení adresy se vypíšou všechny:

0:000> !DumpDomain 51063e70
--------------------------------------
Domain 8:           51063e70
LowFrequencyHeap:   510642c4
HighFrequencyHeap:  5106430c
StubHeap:           51064354
Stage:              OPEN
SecurityDescriptor: 50e671b0
Name:               /LM/W3SVC/2/ROOT-7-130739961229274429
Assembly:           01f74008 [C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll]
ClassLoader:        00fface8
SecurityDescriptor: 4cafd130
  Module Name
72f01000    C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll

Assembly:           01f73540 [C:\Windows\Microsoft.Net\assembly\GAC_32\System.Web\v4.0_4.0.0.0__b03f5f7f11d50a3a\System.Web.dll]
ClassLoader:        00ffaa78
SecurityDescriptor: 50825198
...

Při použití NETEXT můžeme použít přehlednější !wdomain:

0:000> .load D:\NetExt\x86\NetExt.dll
NetExt version 2.0.1.5550 Apr 20 2015
License and usage can be seen here: !whelp license
Check Latest version: !wupdate
For help, type !whelp (or in WinDBG run: '.browse !whelp')
Questions and Feedback: http://netext.codeplex.com/discussions 
Copyright (c) 2014-2015 Rodney Viana (http://blogs.msdn.com/b/rodneyviana) 
Type: !windex -tree or ~*e!wstack to get started

0:000> !wdomain
Address  Domain Name                                                 Modules Base Path & Config
74690c08 System                                                           55 
74690f60 Shared                                                              
01f81230 DefaultDomain                                                    10 Base Path: C:\Windows\SysWOW64\inetsrv\ Config: w3wp.exe.config 
1f443310 /LM/W3SVC/1/ROOT-1-130739944552644364                           232 Base Path: D:\inetpub\www1\ Config: web.config 
1e2d62c0 /LM/W3SVC/2/ROOT-1-130739949798771823                           207 Base Path: D:\inetpub\www2\ Config: web.config 
01fc1b88 /LM/W3SVC/3/ROOT-1-130739955724452334                           199 Base Path: D:\inetpub\www3\ Config: web.config 
51063e70 /LM/W3SVC/4/ROOT-1-130739961229274429                           233 Base Path: D:\inetpub\www4\ Config: web.config 

Statické třídy

Trochu jinak je potřeba postupovat, pokud máme statickou třídu, nebo třídu, od které nemáme k dispozici instanci.

Není to nic komplikovaného, jenom musíme pomocí !Name2EE <ModuleName> <ItemName> získat EEClass adresu, kterou pak použijeme do příkazu !DumpClass <EEClassAddr>:

0:000> !name2ee System.Web.dll System.Web.Hosting.PipelineRuntime
Module:      6d811000
Assembly:    System.Web.dll
Token:       02000342
MethodTable: 6da63a6c
EEClass:     6d811680
Name:        System.Web.Hosting.PipelineRuntime

0:000> !DumpClass 6d811680
Class Name:      System.Web.Hosting.PipelineRuntime
mdToken:         02000342
File:            C:\Windows\Microsoft.Net\assembly\GAC_32\System.Web\v4.0_4.0.0.0__b03f5f7f11d50a3a\System.Web.dll
Parent Class:    72f03e44
Module:          6d811000
Method Table:    6da63a6c
Vtable Slots:    11
Total Method Slots:  16
Class Attributes:    100100  
Transparency:        Transparent
NumInstanceFields:   1
NumStaticFields:     13
      MT    Field   Offset                 Type VT     Attr    Value Name
733041b8  400019b        4        System.Object  0 instance           __identity
7330560c  4000eb1      c60         System.Int32  1   shared   static s_isThisAppDomainRemovedFromUnmanagedTable
    >> Domain:Value  01f81230:NotInit  1f443310:1 1e2d62c0:1 01fc1b88:1 51063e70:0 <<
73302b8c  4000eb2      c64        System.IntPtr  1   shared   static s_ApplicationContext
    >> Domain:Value  01f81230:NotInit  1f443310:018009d0 1e2d62c0:1d85cfa0 01fc1b88:01806498 51063e70:1d87b810 <<
73303e18  4000eb3      e60        System.String  0   shared   static s_thisAppDomainsIsapiAppId
    >> Domain:Value  01f81230:NotInit  1f443310:024b0100 1e2d62c0:2f12c534 01fc1b88:300febe0 51063e70:039b9f00 <<
7330f91c  4000eb4      c84       System.Boolean  1   shared   static s_StopProcessingCalled
    >> Domain:Value  01f81230:NotInit  1f443310:0 1e2d62c0:0 01fc1b88:0 51063e70:0 <<
7330f91c  4000eb5      c85       System.Boolean  1   shared   static s_InitializationCompleted
    >> Domain:Value  01f81230:NotInit  1f443310:1 1e2d62c0:1 01fc1b88:1 51063e70:1 <<
733041b8  4000eb6      e64        System.Object  0   shared   static _delegatelock
    >> Domain:Value  01f81230:NotInit  1f443310:024c4990 1e2d62c0:4209fc50 01fc1b88:3016e73c 51063e70:3e92e32c <<
7330560c  4000eb7      c68         System.Int32  1   shared   static _inIndicateCompletionCount
    >> Domain:Value  01f81230:NotInit  1f443310:2 1e2d62c0:1 01fc1b88:1 51063e70:5 <<
73302b8c  4000eb8      c6c        System.IntPtr  1   shared   static _asyncCompletionDelegatePointer
    >> Domain:Value  01f81230:NotInit  1f443310:1b016186 1e2d62c0:1b016d5e 01fc1b88:1b018b16 51063e70:1b018d96 <<
6da6f6b0  4000eb9      e68 ...ompletionDelegate  0   shared   static _asyncCompletionDelegate
    >> Domain:Value  01f81230:NotInit  1f443310:025ca294 1e2d62c0:0e370f7c 01fc1b88:3ccd512c 51063e70:5d41cac0 <<
73302b8c  4000eba      c70        System.IntPtr  1   shared   static _asyncDisconnectNotificationDelegatePointer
    >> Domain:Value  01f81230:NotInit  1f443310:1b016276 1e2d62c0:1b016a3e 01fc1b88:1b018a4e 51063e70:1b0188e6 <<
6da6f714  4000ebb      e6c ...ificationDelegate  0   shared   static _asyncDisconnectNotificationDelegate
    >> Domain:Value  01f81230:NotInit  1f443310:025ca2b4 1e2d62c0:0e370f9c 01fc1b88:3ccd514c 51063e70:5d41cae0 <<
73302b8c  4000ebc      c74        System.IntPtr  1   shared   static _executeDelegatePointer
    >> Domain:Value  01f81230:NotInit  1f443310:1b0161fe 1e2d62c0:1b016a66 01fc1b88:1b0189fe 51063e70:1b018bb6 <<
6da6f778  4000ebd      e70 ...eFunctionDelegate  0   shared   static _executeDelegate
    >> Domain:Value  01f81230:NotInit  1f443310:025ca2d4 1e2d62c0:0e370fbc 01fc1b88:3ccd516c 51063e70:5d41cb00 <<
73302b8c  4000ebe      c78        System.IntPtr  1   shared   static _disposeDelegatePointer
    >> Domain:Value  01f81230:NotInit  1f443310:1b016226 1e2d62c0:1b016f16 01fc1b88:1b018ac6 51063e70:1b018ca6 <<
6da6f7dc  4000ebf      e74 ...eFunctionDelegate  0   shared   static _disposeDelegate
    >> Domain:Value  01f81230:NotInit  1f443310:025ca2f4 1e2d62c0:0e370fdc 01fc1b88:3ccd518c 51063e70:5d41cb20 <<
73302b8c  4000ec0      c7c        System.IntPtr  1   shared   static _roleDelegatePointer
    >> Domain:Value  01f81230:NotInit  1f443310:1b01624e 1e2d62c0:1b016b56 01fc1b88:1b018bde 51063e70:1b018c06 <<
6da6f840  4000ec1      e78 ...eFunctionDelegate  0   shared   static _roleDelegate
    >> Domain:Value  01f81230:NotInit  1f443310:025ca314 1e2d62c0:0e370ffc 01fc1b88:3ccd51ac 51063e70:5d41cb40 <<
73302b8c  4000ec2      c80        System.IntPtr  1   shared   static _principalDelegatePointer
    >> Domain:Value  01f81230:NotInit  1f443310:1b01615e 1e2d62c0:1b016b06 01fc1b88:1b018aee 51063e70:1b018cce <<
6da6f8a4  4000ec3      e7c ...lFunctionDelegate  0   shared   static _principalDelegate
    >> Domain:Value  01f81230:NotInit  1f443310:025ca334 1e2d62c0:0e37101c 01fc1b88:3ccd51cc 51063e70:5d41cb60 <<

….interpretace výstupu je zde již zřejmá, stejné jako u !DumpObj.

Debugging Story: Bug v IIS recykluje AppDomains

Posledních 14 dní mě zaměstnal problém, jehož vyřešení mi zabralo více času a energie než kdykoliv předtím. Nedá mi to, abych se o situaci nepodělil, protože pokud někoho potká něco podobného, nemá snad šanci než se dogooglit. Uvádím zde velmi zkrácenou verzi, celkem jsem za tu dobu otestoval devět různých hypotéz příčiny, analyzoval 40 GB memory-dumpů, prohlédl tisíce řádek zdrojového kódu System.Web.HttpRuntime a související infrastruktury i tisíce řádek kódu aplikace samotné.

Symptom – počáteční situace

U jednoho z našich zákazníků jsem byl povolán k prozkoumání aplikace, která se chovala tak nějak divně. Dokud zabírala relativně málo paměti (~ 1.5 GB w3wp.exe), běžela. Ve špičkách však začínala brát paměti více paměti a zpomalovat se až tuhnout. Zákazník to prozatím řešil nastavením recyklace aplikačního poolu při dosažení limitu 1.85 GB + naplánovanými recyklacemi ráno a večer. Přes den se tak pool recykloval několikrát. V poolu byla jediná website.

Diagnostika – základní => upřesněný Symptom – AppDomains

První, co si v takové situaci obvykle dělám, je analýza memory-dumpu odebraného z produkce ve její slabší chvilce. Pro analýzu používám WinDbg (+SOS.dll + NETEXT.dll + atp.) a paralelně si hned pouštím i základní reporty DebugDiag. Obvykle se danými symptomy projevuje nějaký typ memory-leaku, takže ve WinDbg člověk automaticky začíná přes !DumpHeap -stat, resp. !EEHeap.

V tomto případě však hlavní anomálii ukázal DebugDiag a potvrdil !wdomain (z NETEXT.dll), popř. !DumpDomain (z SOS.dll) – v procesu nebyly jen obvyklé domény (System, Shared, Default, 1x pro WebSite ála /LM/W3SVC/4/ROOT-1-130737467133911036), ale web-site byla ve worker-procesu reprezentována několika doménami:

System Domain
Shared Domain
DefaultDomain
/LM/W3SVC/4/ROOT-41-130737467133911036 
/LM/W3SVC/4/ROOT-72-130737499283949318 
/LM/W3SVC/4/ROOT-73-130737499297231139 
/LM/W3SVC/4/ROOT-57-130737482790332688 
/LM/W3SVC/4/ROOT-63-130737490107147967 
/LM/W3SVC/4/ROOT-71-130737497444302282 

Každá taková aplikační doména website pak měla samozřejmě i svůj HttpRuntime (včetně cache), svoje statické fieldy, všechno. Paměť worker-procesu tedy byla plněna samostatnými instancemi celé aplikace, spoustou jejich infrastrukturních věcí a na samotný běh aplikace zbývalo paměti málo.

Diagnostika – recyklace AppDomains (základní)

První moje myšlenky se ubíraly směrem, že něco přivozuje neplánovanou recyklaci aplikačních domén (nezaměňujme s recyklací aplikačního poolu!). Připomeňme si základní situace, které recyklaci aplikační domény způsobují:

    1. Machine.Config, Web.Config or Global.asax are modified
    2. The bin directory or its contents is modified
    3. The number of re-compilations (aspx, ascx or asax) exceeds the limit specified by the <compilation numRecompilesBeforeAppRestart=/> setting in machine.config or web.config (by default this is set to 15)
    4. The physical path of the virtual directory is modified
    5. The CAS policy is modified
    6. The web service is restarted
    7. (.NET 2.0 only) Application Sub-Directories are deleted

V úvahu zde připadá cokoliv z uvedeného, seznam navíc nemusí být nutně vyčerpávající, striktní výčet podmínek se v dokumentaci dost těžko hledá.

V mém případě jeden z dalších odebraných memory-dumpů ukazoval zajímavé údaje. Část z nadbytečných aplikačních domén se ukázala být v běžícím shutdownu (HttpRuntime._shutdownInProgress = 1), přičemž jako důvod bylo udáváno ConfigurationChange (HttpRuntime._shutDownReason = 3 = ApplicationShutdownReason.ConfigurationChange). Call-stack ukončování pak byl

at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo) 
at System.Environment.get_StackTrace() 
at System.Web.Hosting.HostingEnvironment.InitiateShutdownInternal() 
at System.Web.Hosting.HostingEnvironment.InitiateShutdownWithoutDemand() 
at System.Web.HttpRuntime.ShutdownAppDomain(String stackTrace) 
at System.Web.Configuration.HttpConfigurationSystem.OnConfigurationChanged(Object sender, InternalConfigEventArgs e) 
at System.Configuration.Internal.InternalConfigRoot.OnConfigChanged(InternalConfigEventArgs e) 
at System.Configuration.BaseConfigurationRecord.OnStreamChanged(String streamname) 
at System.Web.Configuration.WebConfigurationHostFileChange.OnFileChanged(Object sender, FileChangeEvent e) 
at System.Web.DirectoryMonitor.FireNotifications() 
at System.Web.Util.WorkItem.CallCallbackWithAssert(WorkItemCallback callback) 
at System.Web.Util.WorkItem.OnQueueUserWorkItemCompletion(Object state) 
at System.Threading.QueueUserWorkItemCallback.WaitCallback_Context(Object state) 
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) 
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) 
at System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem() 
at System.Threading.ThreadPoolWorkQueue.Dispatch() 
at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback()

V HttpRuntime._shutDownMessage pak bylo něco jako

CONFIG change 
HostingEnvironment initiated shutdown 
HostingEnvironment caused shutdown 
CONFIG change 
CONFIG change 
CONFIG change 
CONFIG change 
CONFIG change 
CONFIG change 
CONFIG change 
CONFIG change 
CONFIG change

…i když trochu podezřele, ale poměrně jasně se tedy ukazuje, že se aktivovala detekce změn na disku, kterou ASP.NET vyhodnotil jako změnu konfigurace, a proto spouští novou aplikační doménu v nové konfiguraci a starou doménu ukončuje (že se domény trochu množí ponechme prozatím stranou – lze to vysvětlit například tím, že zatímco nová doména se spouští ihned, stará aplikační doména se ukončuje až po doběhnutí všech rozpracovaných requestů a úklidu).

Instance FileChangeEvent, ze kterých by se dalo vyčíst jméno souboru, již bohužel garbage collector uklidil, k dalším detailům jsem se v tu chvíli nedopracoval.

Diagnostika – CONFIG change

V tu chvíli se zdálo být jasné, že něco hrabe na disku na konfigurační soubory aplikace (antivir? backup? aplikace?). Abych se dobral, co se tam děje, použil jsem Process Monitor ze SysInternals (lze snadno spustit přímo z http://live.sysinternals.com) a abych to dokázal nějak dobře hledat v čase, zapnul jsem si monitorování Application Lifecycle Events do Event Logu – do globálního web.configu (lze i do aplikačního) jsem přidal do sekce <healthMonitoring><rules>

<add name="Application Lifetime Events Default" eventName="Application Lifetime Events"
                    provider="EventLogProvider" profile="Default" minInstances="1"
                    maxLimit="Infinite" minInterval="00:01:00" custom="" />

Výsledkem této zdlouhavé a vyčerpávající diagnostiky (pořád jsem hledat ten golden-bullet řádek ProcMonu, kde se mi to celé zápisem sestřeluje) bylo několik zjištění:

  • do .config souborů, složky /bin, Temporary ASP.NET Files, atp. s největší pravděpodobností nic nezapisuje, v podstatě krom ASP.NET samotného ani nečte,
  • aplikace si do několika podsložek poměrně často sama zapisuje (konkrétní složky nejsou podstatné, dojme tomu App_Data) + dokonce křížem zapisuje několik aplikací do svých podsložek navzájem – jedná se však o různá logování (TXT soubory), PDF reporty, atp. – nic, co by mělo být konfigurační změnou a restarty způsobovat.
  • aplikace se přes den restartuje hodně často, klidně každých 15 minut, někdy se spustí i několik instancí během minuty, v noci naopak aplikace „žije poklidně“

Pokus – FCN Mode = Disabled

Abych se v tu chvíli posunul někam dále, rozhodnul jsem se pro vypnutí File Change Notifications ASP.NET, tj. vypnout detekci změn souborů na disku. Věděl jsem, že tím nenajdu příčinu, ale chtěl jsem si alespoň potvrdit hypotézu, že problémem jsou změny souborů, a že mám hledat tímto směrem dál.

File Change Notifications lze vypnout dvěma způsoby:

  • od .NET 4.5 lze použít nepříliš dokumentovanou application-level volbu <httpRuntime fcnMode=“Disabled“ /> do web.configu
  • použitím server-wide přepínače FCNMode v registrech
    HKLM\SOFTWARE\Wow6432Node\Microsoft\ASP.NET\FCNMode = 1 (DWORD)
    HKLM\SOFTWARE\Microsoft\ASP.NET\FCNMode = 1 (DWORD)
    

K mému velkému překvapení restarty aplikace neustaly. Stále se v Event Logu objevovaly události

    • Application is starting.
    • Application is shutting down. Reason: Configuration changed.

WTF?!

Dalším memory-dumpem jsem si potvrdil, že FileMonitor instance na HttpRuntime skutečně zmizely, a že HttpRuntime._fcnMode je opravdu 1 (Disabled).

Nový symptom – IIS configuration change

Podrobnějším zkoumáním memory-dumpu se však ukázalo, že něco se přecijenom změnilo. Přestože zůstal u končících appdomains HttpRuntime._shutDownReason = ConfigurationChanged, v _shutDownMessage se najednou změnil obsah na

IIS configuration change
HostingEnvironment initiated shutdown
HostingEnvironment caused shutdownn

a HttpRuntime._shutDownCallStack se změnil na něco jako

at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
at System.Environment.get_StackTrace()
at System.Web.Hosting.HostingEnvironment.InitiateShutdownInternal()
at System.Web.Hosting.PipelineRuntime.StopProcessing()

Diagnostika – IIS configuration change

…mno, začíná jít do tuhýho, metoda StopProcessing() vypadá nějak takhle:

        [EnvironmentPermission(SecurityAction.Assert, Unrestricted = true)]
        public void StopProcessing() {
            Debug.Trace("PipelineDomain", "StopProcessing with stack = " + Environment.StackTrace
                        + " for AppId= " +  s_thisAppDomainsIsapiAppId);
 
            if (!HostingEnvironment.StopListeningWasCalled && !HostingEnvironment.ShutdownInitiated) {
                // If GL_STOP_LISTENING wasn't triggered, the reset is likely due to a configuration change.
                HttpRuntime.SetShutdownReason(ApplicationShutdownReason.ConfigurationChange, "IIS configuration change");
            }
 
            s_StopProcessingCalled = true;
            // inititate shutdown and
            // require the native callback for Stop
            HostingEnvironment.InitiateShutdownWithoutDemand();
        }

…jak je vidět, tak na řádku 6-9 se zapisuje reason „IIS configuration change“, ale z komentáře by se dalo usuzovat, že existují i další nepravděpodobné důvody, pro které se IIS rozhodne app-domain sestřelit a dojde na StopProcessing().

Process Monitor opět nic neukázal, nevypadá to, že by něco do konfiguračních souborů hrabalo.

Došlo tedy na další úroveň znásilnění produkčního serveru – pomocí DebugDiag (proč by se člověk dnes drbal s WinDbg či ADPLUS, když to jde tak snadno) jsem si nastavil breakpointy na vytváření nové aplikační domény (mscorlib.dll!System.AppDomain.InternalCreateDomain) a ukončování aplikační domény (tuším chytáno na System.Web.dll!System.Web.HttpRuntime.RaiseShutdownWebEventOnce) a odebral memory-dumpy přímo z krizového okamžiku. Případné pokusníky upozorňuji, že toto je již velmi invazivní metoda, která v podstatě způsobí naattachování debuggeru na proces, nastavení breakpointů, čekání na jejich hit, což samotné aplikaci výkonově degraduje a dostane do další křeče.

Díky častému restartování aplikačních domén se mi podařilo získat poměrně rychle memory-dumpy.

Thread spouštění nové aplikační domény vypadal takto:

	mscorlib_ni!System.AppDomain.InternalCreateDomain(System.String, System.Security.Policy.Evidence, System.AppDomainSetup) 
	mscorlib_ni!System.AppDomain.CreateDomain(System.String, System.Security.Policy.Evidence, System.AppDomainSetup)+28 
	mscorlib_ni!System.AppDomain.CreateDomain(System.String, System.Security.Policy.Evidence, System.AppDomainSetup)+28 
	mscorlib_ni!System.AppDomain.CreateDomain(System.String, System.Security.Policy.Evidence, System.AppDomainSetup, System.Security.PermissionSet, System.Security.Policy.StrongName[])+8c 
	mscorlib_ni!System.AppDomain.CreateDomain(System.String, System.Security.Policy.Evidence, System.AppDomainSetup, System.Security.PermissionSet, System.Security.Policy.StrongName[])+8c 
	System_Web_ni!System.Web.Hosting.ApplicationManager.CreateAppDomainWithHostingEnvironment(System.String, System.Web.Hosting.IApplicationHost, System.Web.Hosting.HostingEnvironmentParameters)+f10 
	System_Web_ni!System.Web.Hosting.ApplicationManager.CreateAppDomainWithHostingEnvironment(System.String, System.Web.Hosting.IApplicationHost, System.Web.Hosting.HostingEnvironmentParameters)+f10 
	System_Web_ni!System.Web.Hosting.ApplicationManager.CreateAppDomainWithHostingEnvironmentAndReportErrors(System.String, System.Web.Hosting.IApplicationHost, System.Web.Hosting.HostingEnvironmentParameters)+25 
	System_Web_ni!System.Web.Hosting.ApplicationManager.CreateAppDomainWithHostingEnvironmentAndReportErrors(System.String, System.Web.Hosting.IApplicationHost, System.Web.Hosting.HostingEnvironmentParameters)+25 
	System_Web_ni!System.Web.Hosting.ApplicationManager.GetAppDomainWithHostingEnvironment(System.String, System.Web.Hosting.IApplicationHost, System.Web.Hosting.HostingEnvironmentParameters)+6c 
	System_Web_ni!System.Web.Hosting.ApplicationManager.GetAppDomainWithHostingEnvironment(System.String, System.Web.Hosting.IApplicationHost, System.Web.Hosting.HostingEnvironmentParameters)+6c 
	System_Web_ni!System.Web.Hosting.ApplicationManager.CreateObjectInternal(System.String, System.Type, System.Web.Hosting.IApplicationHost, Boolean, System.Web.Hosting.HostingEnvironmentParameters)+4d 
	System_Web_ni!System.Web.Hosting.ApplicationManager.CreateObjectInternal(System.String, System.Type, System.Web.Hosting.IApplicationHost, Boolean, System.Web.Hosting.HostingEnvironmentParameters)+4d 
	System_Web_ni!System.Web.Hosting.ProcessHost.StartApplication(System.String, System.String, System.Object ByRef)+18f 
	System_Web_ni!System.Web.Hosting.ProcessHost.StartApplication(System.String, System.String, System.Object ByRef)+18f 
	System_Web_ni!DomainNeutralILStubClass.IL_STUB_COMtoCLR(IntPtr, IntPtr, IntPtr)+7d 
	System_Web_ni!DomainNeutralILStubClass.IL_STUB_COMtoCLR(IntPtr, IntPtr, IntPtr)+7d 
	clr!COMToCLRDispatchHelper+6b 
	clr!COMToCLRWorker+3e6 
	0x01b1a062 
	webengine4!W3_MGD_APP_CONTEXT::CreateAppDomain+92 
	[[ComMethodFrame]] 
	webengine4!W3_MGD_APP_CONTEXT::OnApplicationResolveModules+90 
	webengine4!CMgdEngGlobalModule::OnGlobalApplicationResolveModules+51 
	iiscore!VIRTUAL_MODULE::GlobalDoWork+da 
	iiscore!W3_SERVER::GlobalNotify+e5 
	iiscore!W3_APPLICATION::ResolveModules+22 
	iiscore!W3_CONTEXT::SetupStateMachinePhase2+350 
	iiscore!W3_CONTEXT::SetupStateMachine+263 
	iiscore!W3_CONTEXT_BASE::StartNotificationLoop+71 
	iiscore!W3_MAIN_CONTEXT::OnNewRequest+a8 
	w3dt!UL_NATIVE_REQUEST::DoWork+79 
	w3dt!UL_RECEIVE_CONTEXT::DoWork+1b 
	w3dt!WP_CONTEXT::OnCompletion+22 
	w3tp!THREAD_POOL_DATA::ThreadPoolThread+a8 
	w3tp!THREAD_POOL_DATA::ThreadPoolThread+2b 
	w3tp!THREAD_MANAGER::ThreadManagerThread+4d 
	kernel32!BaseThreadInitThunk+24 
	ntdll!__RtlUserThreadStart+2f 
	ntdll!_RtlUserThreadStart+1b 

Thread ukončování staré aplikační domény takto:

		ntdll!NtReleaseSemaphore+c 
		KERNELBASE!ReleaseSemaphore+14 
		clr!CLRSemaphore::Release+2f 
		clr!ThreadpoolMgr::UnfairSemaphore::Release+d2 
		clr!ThreadpoolMgr::MaybeAddWorkingWorker+1c6 
		clr!ManagedPerAppDomainTPCount::SetAppDomainRequestsActive+2f 
		mscorlib_ni!DomainNeutralILStubClass.IL_STUB_PInvoke()+33 
		[[InlinedCallFrame]] 
		mscorlib_ni!System.Threading.ThreadPoolWorkQueue.EnsureThreadRequested()+4c 
		mscorlib_ni!System.Threading.ThreadPoolWorkQueue.Enqueue(System.Threading.IThreadPoolWorkItem, Boolean)+42 
		mscorlib_ni!System.Threading.ThreadPool.QueueUserWorkItemHelper(System.Threading.WaitCallback, System.Object, System.Threading.StackCrawlMark ByRef, Boolean)+bd 
		mscorlib_ni!System.Threading.ThreadPool.QueueUserWorkItemHelper(System.Threading.WaitCallback, System.Object, System.Threading.StackCrawlMark ByRef, Boolean)+bd 
		mscorlib_ni!System.Threading.ThreadPool.QueueUserWorkItem(System.Threading.WaitCallback)+1d 
		mscorlib_ni!System.Threading.ThreadPool.QueueUserWorkItem(System.Threading.WaitCallback)+1d 
		System_Web_ni!System.Web.Hosting.HostingEnvironment.InitiateShutdownInternal()+12e 
		System_Web_ni!System.Web.Hosting.HostingEnvironment.InitiateShutdownWithoutDemand()+21 
		System_Web_ni!System.Web.Hosting.PipelineRuntime.StopProcessing()+3f 
		System_Web_ni!DomainNeutralILStubClass.IL_STUB_COMtoCLR()+12 
		clr!COMToCLRDispatchHelper+28 
		clr!COMToCLRWorkerBodyWithADTransition+217 
		[[ContextTransitionFrame]] 
		clr!COMToCLRWorker+61 
		0x01b1a062 
		webengine4!W3_MGD_APP_CONTEXT::EndApplicationInstance+54 
		[[ComMethodFrame]] 
		webengine4!W3_MGD_APP_CONTEXT::OnApplicationEnd+3b 
		webengine4!CMgdEngGlobalModule::OnGlobalApplicationStop+1f 
		iiscore!VIRTUAL_MODULE::GlobalDoWork+16a 
		iiscore!W3_SERVER::GlobalNotify+e5 
		iiscore!W3_APPLICATION::DereferenceApplication+2e 
		iiscore!W3_METADATA::DereferenceMetadata+17 
		iiscore!W3_MAIN_CONTEXT::OnIoCompletion+86 
		w3dt!UL_NATIVE_REQUEST::DoWork+a0 
		w3dt!UL_SEND_CONTEXT::DoWork+1b 
		w3dt!WP_CONTEXT::OnCompletion+22 
		w3tp!THREAD_POOL_DATA::ThreadPoolThread+a8 
		w3tp!THREAD_POOL_DATA::ThreadPoolThread+2b 
		w3tp!THREAD_MANAGER::ThreadManagerThread+4d 
		kernel32!BaseThreadInitThunk+24 
		ntdll!__RtlUserThreadStart+2f 
		ntdll!_RtlUserThreadStart+1b 

V obou případech je vidět, že operace iniciuje nativní část W3WP, tedy zjednodušeně řečeno IIS. Zdrojové kódy této části bohužel u sebe nemám a poprvé se mi stalo, že by se mi hodily. Jako MVP bych si o ně mohli požádat, ale je to procedura poměrně zdlouhavá. Každopádně z call-stacku ukončování by se dalo více-méně usuzovat (např. dle funkce OnIoCompletion), že se jedná opět o callback nějaké file-change-monitoru, tedy vážně nějaké dosud neobjevené drbání na disku.

Cause

…už to začíná být neúměrně dlouhé, tak to zkrátím. Problém jsem konzultoval prostřednictvím uzavřeného mailing-listu s ostatními ASP.NET/IIS MVPs + s Microsoftem a díky podrobným nasbíraným symptomům jsme se poměrně rychle dostali k jádru věci.

Problém způsobuje hotfix KB3007507, který se na předmětný Windows 2012 R2 server nainstaloval jako součást KB3000850 přes Windows Update (někdy v půlce prosince 2014).

Projevuje se tak, že pokud ve složce webové aplikace (+ podsložkách) probíhá intenzivnější disková aktivita, IIS to neuhodnotí a odpálí AppDomain, jako by se jednalo o změnu konfigurace. Nepotvrzené vysvětlení je, že se přehltí change-monitory, ostatně podobné problémy mělo IIS už dříve:

I když již existuje pre-release podoba hotfixu KB3052480, která by měla problém řešit, stačí odinstalovat KB3000850, restartovat server a problém je vyřešen.

Kdyby se někdo do podobné situace dostal, mám i jednoduchou WebSite, která problém dokáže relativně spolehlivě reprodukovat.