Slides z naší (Robert Haken & Jiří Kanda) včerejší přednášky pro Microsoft ALM Camp:
Záznam jsme tentokrát nepořizovali. Jednalo se však o okleštěnou verzi velmi podobného vystoupení pro WUG Praha z ledna 2015.
Služba SendGrid vkládá dvojité konce řádků v e-mailových klientech Outlook a Thunderbird, pokud je nastaveno transfer encoding v MIME na „quoted-printable“. Pro vyřešení problému je třeba nastavit transfer encoding na „7bit“. Popsáno také zde. Bod číslo čtyři.
... MailMessage message = new MailMessage(); message.BodyTransferEncoding = System.Net.Mime.TransferEncoding.SevenBit; ...
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.
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.)
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.
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.
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.
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í:
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.
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í:
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:
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
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()
…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.
Po migraci na Office 365 – Exchange Online jsme potřebovali znovu nastavit na vybraných mail-enabled veřejných složkách, aby se v nich starší zprávy automaticky mazaly.
Nedělá se to přes Retention Policy jako u běžných mailboxů, ale ve vlastnostech veřejné složky je na záložce Limits přímo volba Age limits:
Nastavené trvá nějakou dobu, než se projeví a starší zprávy vypadnou. Posledně to chtělo tuším den. nepomáhá ani Start-Start-ManagedFolderAssistant na PF-mailbox z PowerShellu.
…tak příště už to snad nebudu hledat.
Řešil jsem dnes s kolegou Jakubem Čermákem zajímavou situaci. Komprimovanou podobu situace zaznamenávám jako inspiraci pro podobné situace ladění.
Na jednom z našich produkčních webových serverů dnes v časných ranních hodinách vyskočila zátěž CPU na 100%. Rychlý pohled do TaskManageru ukázal, že viníkem byl aplikační pool s redakčním systémem UmbracoCMS, který používáme pro jeden z frontendů jako content-databázi a administrační UI (UmbracoCMS zde tedy nerenderuje front-end, ale samostatná ASP.NET front-endová aplikace si přes API říká Umbraco-webu pouze pro data, z kterých výstup sestavuje – různé HTML segmenty, resources atp. editované v CMS).
Stejná situace již v minulosti dvakrát nastala (rozestup v řádu týdnů), vždy pomohlo restartování aplikačního poolu Umbraco. Tentokrát se nám podařilo před restartem poolu sejmout memory-dump postiženého procesu.
Na každý získaný memory-dump dnes již automaticky jako první úkon pouštím DebugDiag. Získám tím relativně rychle základní přehled o situaci, např.
Výstup z DebugDiag ukázal, že call-stack několika desítek aktivních threadů se shoduje:
mscorlib_ni!System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.Boolean, mscorlib]].Insert(System.__Canon, Boolean, Boolean)+1f0 Umbraco.Core.Models.EntityBase.TracksChangesEntityBase.OnPropertyChanged(System.Reflection.PropertyInfo)+3e Umbraco.Core.Models.EntityBase.TracksChangesEntityBase.SetPropertyValueAndDetectChanges[[System.__Canon, mscorlib]](System.Func`2<System.__Canon,System.__Canon>, System.__Canon, System.Reflection.PropertyInfo)+5c Umbraco.Core.Models.ContentType.set_AllowedTemplates(System.Collections.Generic.IEnumerable`1<Umbraco.Core.Models.ITemplate>)+80 clr!CallDescrWorkerInternal+83 clr!CallDescrWorkerWithHandler+4a clr!CallDescrWorkerReflectionWrapper+1a clr!RuntimeMethodHandle::InvokeMethod+46a [[DebuggerU2MCatchHandlerFrame]] [[HelperMethodFrame_PROTECTOBJ] (System.RuntimeMethodHandle.InvokeMethod)] System.RuntimeMethodHandle.InvokeMethod(System.Object, System.Object[], System.Signature, Boolean) mscorlib_ni!System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(System.Object, System.Object[], System.Object[])+4c mscorlib_ni!System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)+d3 mscorlib_ni!System.Reflection.RuntimePropertyInfo.SetValue(System.Object, System.Object, System.Object[])+2c Umbraco.Core.Models.DeepCloneHelper.DeepCloneRefProperties(Umbraco.Core.Models.IDeepCloneable, Umbraco.Core.Models.IDeepCloneable)+61d Umbraco.Core.Models.ContentTypeCompositionBase.DeepClone()+3d Umbraco.Core.Models.ContentTypeCompositionBase.<DeepClone>b__2f(Umbraco.Core.Models.IContentTypeComposition)+14 System_Core_ni!System.Linq.Enumerable+WhereSelectListIterator`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].MoveNext()+f4 mscorlib_ni!System.Collections.Generic.List`1[[System.__Canon, mscorlib]]..ctor(System.Collections.Generic.IEnumerable`1<System.__Canon>)+218 System_Core_ni!System.Linq.Enumerable.ToList[[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1<System.__Canon>)+50 Umbraco.Core.Models.ContentTypeCompositionBase.DeepClone()+1bb Umbraco.Core.Persistence.Caching.RuntimeCacheProvider.GetById(System.Type, System.Guid)+ea Umbraco.Core.Persistence.Repositories.RepositoryBase`2[[System.Int32, mscorlib],[System.__Canon, mscorlib]].TryGetFromCache(Int32)+bb Umbraco.Core.Persistence.Repositories.RepositoryBase`2[[System.Int32, mscorlib],[System.__Canon, mscorlib]].Get(Int32)+3c Umbraco.Core.Persistence.Repositories.ContentRepository.CreateContentFromDto(Umbraco.Core.Models.Rdbms.DocumentDto, System.Guid)+5d Umbraco.Core.Persistence.Repositories.ContentRepository.PerformGet(Int32)+2e0 Umbraco.Core.Persistence.Repositories.RepositoryBase`2[[System.Int32, mscorlib],[System.__Canon, mscorlib]].Get(Int32)+7b Umbraco.Core.Services.ContentService.GetById(Int32)+69 Havit.XyzPortal.Services.ContentManagement.EpoUrlProvider.GetUrl(Umbraco.Core.ApplicationContext, Int32, System.Uri, Umbraco.Web.Routing.UrlProviderMode)+108 Umbraco.Web.Routing.UrlProvider+<>c__DisplayClass3.<GetUrl>b__0(Umbraco.Web.Routing.IUrlProvider)+32 System_Core_ni!System.Linq.Enumerable+WhereSelectArrayIterator`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].MoveNext()+52 System_Core_ni!System.Linq.Enumerable.FirstOrDefault[[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1<System.__Canon>, System.Func`2<System.__Canon,Boolean>)+d7 Umbraco.Web.Routing.UrlProvider.GetUrl(Int32, System.Uri, Umbraco.Web.Routing.UrlProviderMode)+ec Umbraco.Web.Templates.TemplateUtilities.ParseInternalLinks(System.String)+170 Havit.XyzPortal.UmbracoCMS.UmContentApiController.TraverseResourceDictionary(System.Collections.Generic.List`1<Havit.XyzPortal.Services.Resources.DataObjects.ResourceDictionaryDTO>, Umbraco.Core.Models.IContent, Boolean)+32e Havit.XyzPortal.UmbracoCMS.UmContentApiController.TraverseResourceDictionary(System.Collections.Generic.List`1<Havit.XyzPortal.Services.Resources.DataObjects.ResourceDictionaryDTO>, Umbraco.Core.Models.IContent, Boolean)+dd Havit.XyzPortal.UmbracoCMS.UmContentApiController.TraverseResourceDictionary(System.Collections.Generic.List`1<Havit.XyzPortal.Services.Resources.DataObjects.ResourceDictionaryDTO>, Umbraco.Core.Models.IContent, Boolean)+dd Havit.XyzPortal.UmbracoCMS.UmContentApiController.Resources(System.Nullable`1<Boolean>)+113 Havit.XyzPortal.UmbracoCMS.UmContentApiController.Resources()+21 DynamicClass.lambda_method(System.Runtime.CompilerServices.Closure, System.Object, System.Object[])+4f System.Web.Http.Controllers.ReflectedHttpActionDescriptor+ActionExecutor+<>c__DisplayClass13.<GetExecutor>b__c(System.Object, System.Object[])+15 System.Web.Http.Controllers.ReflectedHttpActionDescriptor+ActionExecutor.Execute(System.Object, System.Object[])+f System.Threading.Tasks.TaskHelpers.RunSynchronously[[System.__Canon, mscorlib]](System.Func`1<System.Threading.Tasks.Task`1<System.__Canon>>, System.Threading.CancellationToken)+78 System.Web.Http.Controllers.ApiControllerActionInvoker+<>c__DisplayClass3.<InvokeActionAsync>b__0()+29 System.Threading.Tasks.TaskHelpers.RunSynchronously[[System.__Canon, mscorlib]](System.Func`1<System.Threading.Tasks.Task`1<System.__Canon>>, System.Threading.CancellationToken)+78 System.Web.Http.Controllers.ApiControllerActionInvoker.InvokeActionAsync(System.Web.Http.Controllers.HttpActionContext, System.Threading.CancellationToken)+98 System.Web.Http.ApiController+<>c__DisplayClass3.<ExecuteAsync>b__2()+33 System.Web.Http.ApiController+<>c__DisplayClass3.<ExecuteAsync>b__1()+c5 System.Threading.Tasks.TaskHelpersExtensions+<>c__DisplayClass32`1[[System.__Canon, mscorlib]].<Then>b__31(System.Threading.Tasks.Task)+f System.Threading.Tasks.TaskHelpersExtensions.ThenImpl[[System.__Canon, mscorlib],[System.__Canon, mscorlib]](System.__Canon, System.Func`2<System.__Canon,System.Threading.Tasks.Task`1<System.__Canon>>, System.Threading.CancellationToken, Boolean)+114 System.Web.Http.ApiController+<>c__DisplayClass3.<ExecuteAsync>b__0()+74 System.Web.Http.ApiController.ExecuteAsync(System.Web.Http.Controllers.HttpControllerContext, System.Threading.CancellationToken)+1cf System.Web.Http.Dispatcher.HttpControllerDispatcher.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)+76 System_Net_Http_ni!System.Net.Http.HttpMessageInvoker.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)+4f System.Web.Http.Dispatcher.HttpRoutingDispatcher.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)+175 System.Web.Http.HttpServer.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)+ff System_Net_Http_ni!System.Net.Http.HttpMessageInvoker.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)+4f System.Web.Http.WebHost.HttpControllerHandler.BeginProcessRequest(System.Web.HttpContextBase, System.AsyncCallback, System.Object)+11f System_Web_ni!System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()+1e2 System_Web_ni!System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)+120 System_Web_ni!System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)+92a System_Web_ni!System.Web.HttpApplication.BeginProcessRequestNotification(System.Web.HttpContext, System.AsyncCallback)+83 System_Web_ni!System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)+28e System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)+5c1 System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)+22 System_Web_ni!DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)+51 clr!UMThunkStub+6e webengine4!W3_MGD_HANDLER::ProcessNotification+78 webengine4!W3_MGD_HANDLER::DoWork+34f webengine4!RequestDoWork+34e webengine4!CMgdEngHttpModule::OnExecuteRequestHandler+21 iiscore!NOTIFICATION_CONTEXT::RequestDoWork+233 iiscore!NOTIFICATION_CONTEXT::CallModulesInternal+174 iiscore!NOTIFICATION_CONTEXT::CallModules+25 iiscore!W3_CONTEXT::DoWork+34d iiscore!W3_CONTEXT::IndicateCompletion+8c webengine4!MgdIndicateCompletion+60 System_Web_ni!DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)+7b [[InlinedCallFrame] (System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion)] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatusByRef) System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)+7af System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)+22 System_Web_ni!DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)+51 clr!UM2MThunk_WrapperHelper+43 clr!UM2MThunk_Wrapper+5a clr!Thread::DoADCallBack+139 [[ContextTransitionFrame]] clr!UM2MDoADCallBack+91 clr!UMThunkStub+26d webengine4!W3_MGD_HANDLER::ProcessNotification+78 webengine4!ProcessNotificationCallback+42 clr!UnManagedPerAppDomainTPCount::DispatchWorkItem+122 clr!ThreadpoolMgr::ExecuteWorkRequest+46 clr!ThreadpoolMgr::WorkerThreadStart+f4 clr!Thread::intermediateThreadProc+7d kernel32!BaseThreadInitThunk+d ntdll!RtlUserThreadStart+1d
První procházení zdrojových kódů dotčených metod (nejprve „just my code“, dále i Umbraco a nakonec i .NET) neukázalo na očividného viníka. Na call-stacku se děje zhruba toto:
// class ContentType : TracksChangesEntityBase
public IEnumerable<ITemplate> AllowedTemplates
{
get
{
return this._allowedTemplates;
}
set
{
base.SetPropertyValueAndDetectChanges<IEnumerable<ITemplate>>(delegate (IEnumerable<ITemplate> o) {
this._allowedTemplates = value;
return this._allowedTemplates;
}, this._allowedTemplates, AllowedTemplatesSelector);
}
}
// TracksChangesEntityBase
internal bool SetPropertyValueAndDetectChanges<T>(Func<T, T> setValue, T value, PropertyInfo propertySelector)
{
T local = value;
T local2 = setValue(value);
if (!object.Equals(local, local2))
{
this.OnPropertyChanged(propertySelector);
return true;
}
return false;
}
protected virtual void OnPropertyChanged(PropertyInfo propertyInfo)
{
this._propertyChangedInfo.set_Item(propertyInfo.get_Name(), true);
if (this.PropertyChanged != null)
{
this.PropertyChanged(this, new PropertyChangedEventArgs(propertyInfo.get_Name()));
}
}
Onen Dictionary<>.Insert(), který je na vrcholu call-stacků je tedy ve skutečnosti in-linovaná podoba slovníkového indexeru _propertyChangedInfo[propertyInfo.Name] = true;
Víme, že Dictionary je thread-safe pouze pro čtení, ale co se nám to tam v tom Insertu() děje, když každý tracked-objekt vzniká jako clone a má vlastní slovník pro ukládání změněných properties?
Pro doplnění z diagnostiky:
Zkusili jsme dále bádat, co přesně se v metodě Dictionary<>.Insert() děje, co by se mohlo zacyklit. Zdrojový kód metody Insert() vypadá poměrně očekávaně, klasické tanečky kolem hash-tabulky. Vytahuje se GetHashCode(), hledá se volný bucket, umísťuje se hodnota, …
private void Insert(TKey key, TValue value, bool add) {
if( key == null ) {
ThrowHelper.ThrowArgumentNullException(ExceptionArgument.key);
}
if (buckets == null) Initialize(0);
int hashCode = comparer.GetHashCode(key) & 0x7FFFFFFF;
int targetBucket = hashCode % buckets.Length;
#if FEATURE_RANDOMIZED_STRING_HASHING
int collisionCount = 0;
#endif
for (int i = buckets[targetBucket]; i >= 0; i = entries[i].next) {
if (entries[i].hashCode == hashCode && comparer.Equals(entries[i].key, key)) {
if (add) {
ThrowHelper.ThrowArgumentException(ExceptionResource.Argument_AddingDuplicate);
}
entries[i].value = value;
version++;
return;
}
#if FEATURE_RANDOMIZED_STRING_HASHING
collisionCount++;
#endif
}
int index;
if (freeCount > 0) {
index = freeList;
freeList = entries[index].next;
freeCount--;
}
else {
if (count == entries.Length)
{
Resize();
targetBucket = hashCode % buckets.Length;
}
index = count;
count++;
}
entries[index].hashCode = hashCode;
entries[index].next = buckets[targetBucket];
entries[index].key = key;
entries[index].value = value;
buckets[targetBucket] = index;
version++;
#if FEATURE_RANDOMIZED_STRING_HASHING
if(collisionCount > HashHelpers.HashCollisionThreshold && HashHelpers.IsWellKnownEqualityComparer(comparer))
{
comparer = (IEqualityComparer<TKey>) HashHelpers.GetRandomizedEqualityComparer(comparer);
Resize(entries.Length, true);
}
#endif
}
Vydali jsme se cestou pokusu o zjištění, kde přesně se v metodě Insert() nacházíme (což bylo asi nadbytečné, jak se ukázalo později, navíc v metodě je jediný cyklus, takže se celkem nabízí, nicméně nám to pomohlo nasměrovat další síly k cíli).
Ve WinDbg jsme si nechali vypsat pomocí !ClrStack zásobník jednoho z postižených threadů (všechny vypadaly stejně plus/mínus pár instrukcí dopředu/dozadu uvnitř metody Insert()):
0:041> !ClrStack
OS Thread Id: 0xbe0 (41)
Child SP IP Call Site
000000001206bb70 000007fef7371fc0 System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.Boolean, mscorlib]].Insert(System.__Canon, Boolean, Boolean)
000000001206bc00 000007fe999e025e Umbraco.Core.Models.EntityBase.TracksChangesEntityBase.OnPropertyChanged(System.Reflection.PropertyInfo)
000000001206bc50 000007fe999e92bc Umbraco.Core.Models.EntityBase.TracksChangesEntityBase.SetPropertyValueAndDetectChanges[[System.__Canon, mscorlib]](System.Func`2<System.__Canon,System.__Canon>, System.__Canon, System.Reflection.PropertyInfo)
000000001206bc90 000007fe99b611c0 Umbraco.Core.Models.ContentType.set_AllowedTemplates(System.Collections.Generic.IEnumerable`1<Umbraco.Core.Models.ITemplate>)
000000001206bf20 000007fef85ba7f3 [DebuggerU2MCatchHandlerFrame: 000000001206bf20]
000000001206c238 000007fef85ba7f3 [HelperMethodFrame_PROTECTOBJ: 000000001206c238] System.RuntimeMethodHandle.InvokeMethod(System.Object, System.Object[], System.Signature, Boolean)
000000001206c3b0 000007fef72b3b4c System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(System.Object, System.Object[], System.Object[])
000000001206c420 000007fef72b1273 System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
000000001206c4a0 000007fef73782cc System.Reflection.RuntimePropertyInfo.SetValue(System.Object, System.Object, System.Object[])
000000001206c4f0 000007fe99b6222d Umbraco.Core.Models.DeepCloneHelper.DeepCloneRefProperties(Umbraco.Core.Models.IDeepCloneable, Umbraco.Core.Models.IDeepCloneable)
000000001206c5a0 000007fe99b6256d Umbraco.Core.Models.ContentTypeCompositionBase.DeepClone()
000000001206c5f0 000007fe999eeb84 Umbraco.Core.Models.ContentTypeCompositionBase.<DeepClone>b__2f(Umbraco.Core.Models.IContentTypeComposition)
000000001206c620 000007fef5972134 System.Linq.Enumerable+WhereSelectListIterator`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].MoveNext()
000000001206c680 000007fef72e55b8 System.Collections.Generic.List`1[[System.__Canon, mscorlib]]..ctor(System.Collections.Generic.IEnumerable`1<System.__Canon>)
000000001206c6f0 000007fef5975180 System.Linq.Enumerable.ToList[[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1<System.__Canon>)
000000001206c730 000007fe99b626eb Umbraco.Core.Models.ContentTypeCompositionBase.DeepClone()
000000001206c780 000007fe999cefaa Umbraco.Core.Persistence.Caching.RuntimeCacheProvider.GetById(System.Type, System.Guid)
000000001206c7e0 000007fe999d00fb Umbraco.Core.Persistence.Repositories.RepositoryBase`2[[System.Int32, mscorlib],[System.__Canon, mscorlib]].TryGetFromCache(Int32)
000000001206c880 000007fe999cfe5c Umbraco.Core.Persistence.Repositories.RepositoryBase`2[[System.Int32, mscorlib],[System.__Canon, mscorlib]].Get(Int32)
000000001206c900 000007fe999d24dd Umbraco.Core.Persistence.Repositories.ContentRepository.CreateContentFromDto(Umbraco.Core.Models.Rdbms.DocumentDto, System.Guid)
000000001206c9d0 000007fe999d0a10 Umbraco.Core.Persistence.Repositories.ContentRepository.PerformGet(Int32)
000000001206ca60 000007fe999cfe9b Umbraco.Core.Persistence.Repositories.RepositoryBase`2[[System.Int32, mscorlib],[System.__Canon, mscorlib]].Get(Int32)
000000001206cae0 000007fe999c6069 Umbraco.Core.Services.ContentService.GetById(Int32)
000000001206cb40 000007fe99b88228 Havit.XyzPortal.Services.ContentManagement.EpoUrlProvider.GetUrl(Umbraco.Core.ApplicationContext, Int32, System.Uri, Umbraco.Web.Routing.UrlProviderMode)
000000001206cba0 000007fe99b86452 Umbraco.Web.Routing.UrlProvider+<>c__DisplayClass3.<GetUrl>b__0(Umbraco.Web.Routing.IUrlProvider)
000000001206cbe0 000007fef5972012 System.Linq.Enumerable+WhereSelectArrayIterator`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].MoveNext()
000000001206cc20 000007fef5964e47 System.Linq.Enumerable.FirstOrDefault[[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1<System.__Canon>, System.Func`2<System.__Canon,Boolean>)
000000001206cc80 000007fe99b8684c Umbraco.Web.Routing.UrlProvider.GetUrl(Int32, System.Uri, Umbraco.Web.Routing.UrlProviderMode)
000000001206ccd0 000007fe99b7c580 Umbraco.Web.Templates.TemplateUtilities.ParseInternalLinks(System.String)
000000001206cd60 000007fe99d1e99e Havit.XyzPortal.UmbracoCMS.UmContentApiController.TraverseResourceDictionary(System.Collections.Generic.List`1<Havit.XyzPortal.Services.Resources.DataObjects.ResourceDictionaryDTO>, Umbraco.Core.Models.IContent, Boolean)
000000001206ce20 000007fe99d1e74d Havit.XyzPortal.UmbracoCMS.UmContentApiController.TraverseResourceDictionary(System.Collections.Generic.List`1<Havit.XyzPortal.Services.Resources.DataObjects.ResourceDictionaryDTO>, Umbraco.Core.Models.IContent, Boolean)
000000001206cee0 000007fe99d1e74d Havit.XyzPortal.UmbracoCMS.UmContentApiController.TraverseResourceDictionary(System.Collections.Generic.List`1<Havit.XyzPortal.Services.Resources.DataObjects.ResourceDictionaryDTO>, Umbraco.Core.Models.IContent, Boolean)
000000001206cfa0 000007fe99d1b003 Havit.XyzPortal.UmbracoCMS.UmContentApiController.Resources(System.Nullable`1<Boolean>)
000000001206d000 000007fe99d1aed1 Havit.XyzPortal.UmbracoCMS.UmContentApiController.Resources()
000000001206d040 000007fe99e1d25f DynamicClass.lambda_method(System.Runtime.CompilerServices.Closure, System.Object, System.Object[])
000000001206d070 000007fe999c6555 System.Web.Http.Controllers.ReflectedHttpActionDescriptor+ActionExecutor+<>c__DisplayClass13.<GetExecutor>b__c(System.Object, System.Object[])
000000001206d0b0 000007fe999c663f System.Web.Http.Controllers.ReflectedHttpActionDescriptor+ActionExecutor.Execute(System.Object, System.Object[])
000000001206d0e0 000007fe999c7ec8 System.Threading.Tasks.TaskHelpers.RunSynchronously[[System.__Canon, mscorlib]](System.Func`1<System.Threading.Tasks.Task`1<System.__Canon>>, System.Threading.CancellationToken)
000000001206d130 000007fe999c7c19 System.Web.Http.Controllers.ApiControllerActionInvoker+<>c__DisplayClass3.<InvokeActionAsync>b__0()
000000001206d180 000007fe999c7ec8 System.Threading.Tasks.TaskHelpers.RunSynchronously[[System.__Canon, mscorlib]](System.Func`1<System.Threading.Tasks.Task`1<System.__Canon>>, System.Threading.CancellationToken)
000000001206d1d0 000007fe999c8188 System.Web.Http.Controllers.ApiControllerActionInvoker.InvokeActionAsync(System.Web.Http.Controllers.HttpActionContext, System.Threading.CancellationToken)
000000001206d220 000007fe999c82a3 System.Web.Http.ApiController+<>c__DisplayClass3.<ExecuteAsync>b__2()
000000001206d250 000007fe999c84c5 System.Web.Http.ApiController+<>c__DisplayClass3.<ExecuteAsync>b__1()
000000001206d2a0 000007fe999c84ff System.Threading.Tasks.TaskHelpersExtensions+<>c__DisplayClass32`1[[System.__Canon, mscorlib]].<Then>b__31(System.Threading.Tasks.Task)
000000001206d2d0 000007fe999c88a4 System.Threading.Tasks.TaskHelpersExtensions.ThenImpl[[System.__Canon, mscorlib],[System.__Canon, mscorlib]](System.__Canon, System.Func`2<System.__Canon,System.Threading.Tasks.Task`1<System.__Canon>>, System.Threading.CancellationToken, Boolean)
000000001206d340 000007fe999c7614 System.Web.Http.ApiController+<>c__DisplayClass3.<ExecuteAsync>b__0()
000000001206d3a0 000007fe999c05df System.Web.Http.ApiController.ExecuteAsync(System.Web.Http.Controllers.HttpControllerContext, System.Threading.CancellationToken)
000000001206d410 000007fe999bb3a6 System.Web.Http.Dispatcher.HttpControllerDispatcher.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)
000000001206d4a0 000007fefb2ee33f System.Net.Http.HttpMessageInvoker.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)
000000001206d4f0 000007fe999bbd55 System.Web.Http.Dispatcher.HttpRoutingDispatcher.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)
000000001206d550 000007fe999be00f System.Web.Http.HttpServer.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)
000000001206d5a0 000007fefb2ee33f System.Net.Http.HttpMessageInvoker.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)
000000001206d5f0 000007fe999bb84f System.Web.Http.WebHost.HttpControllerHandler.BeginProcessRequest(System.Web.HttpContextBase, System.AsyncCallback, System.Object)
000000001206d670 000007fee9865ca2 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
000000001206d750 000007fee982d110 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
000000001206d7f0 000007fee984a78a System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)
000000001206d940 000007fee982d2a3 System.Web.HttpApplication.BeginProcessRequestNotification(System.Web.HttpContext, System.AsyncCallback)
000000001206d990 000007fee98271de System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)
000000001206da30 000007fee9830161 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
000000001206dc40 000007fee982fb92 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
000000001206dc90 000007fee9f86ec1 DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)
000000001206e478 000007fef861b42e [InlinedCallFrame: 000000001206e478] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatus ByRef)
000000001206e478 000007fee98d919b [InlinedCallFrame: 000000001206e478] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatus ByRef)
000000001206e450 000007fee98d919b DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)
000000001206e520 000007fee983034f System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
000000001206e730 000007fee982fb92 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
000000001206e780 000007fee9f86ec1 DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)
000000001206e978 000007fef861b683 [ContextTransitionFrame: 000000001206e978]
…a protože nemáme k dispozici převod offsetu na řádky zdrojového kódu mscorlib.dll, vydali jsme se přes !U /d <addr> na disassembly aktuálních instrukcí:
0:041> !U /d 000007fef7371fc0 preJIT generated code System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.Boolean, mscorlib]].Insert(System.__Canon, Boolean, Boolean) Begin 000007fef7371dd0, size 29a. Cold region begin 000007fef80c24e4, size 173 Hot region: 000007fe`f7371dd0 53 push rbx 000007fe`f7371dd1 55 push rbp 000007fe`f7371dd2 56 push rsi 000007fe`f7371dd3 57 push rdi 000007fe`f7371dd4 4154 push r12 000007fe`f7371dd6 4155 push r13 000007fe`f7371dd8 4156 push r14 000007fe`f7371dda 4157 push r15 000007fe`f7371ddc 4883ec48 sub rsp,48h 000007fe`f7371de0 410fb6c1 movzx eax,r9b 000007fe`f7371de4 88442428 mov byte ptr [rsp+28h],al 000007fe`f7371de8 450fb6e8 movzx r13d,r8b 000007fe`f7371dec 44886c2429 mov byte ptr [rsp+29h],r13b 000007fe`f7371df1 4c8be2 mov r12,rdx 000007fe`f7371df4 488bd9 mov rbx,rcx 000007fe`f7371df7 48895c2420 mov qword ptr [rsp+20h],rbx 000007fe`f7371dfc 4d85e4 test r12,r12 000007fe`f7371dff 0f84e607d500 je mscorlib_ni+0x12a25eb (000007fe`f80c25eb) 000007fe`f7371e05 488b4308 mov rax,qword ptr [rbx+8] 000007fe`f7371e09 4885c0 test rax,rax 000007fe`f7371e0c 0f8463010000 je mscorlib_ni+0x551f75 (000007fe`f7371f75) 000007fe`f7371e12 488b7b18 mov rdi,qword ptr [rbx+18h] 000007fe`f7371e16 488b03 mov rax,qword ptr [rbx] 000007fe`f7371e19 488b4830 mov rcx,qword ptr [rax+30h] 000007fe`f7371e1d 488b01 mov rax,qword ptr [rcx] 000007fe`f7371e20 488b4018 mov rax,qword ptr [rax+18h] 000007fe`f7371e24 4885c0 test rax,rax 000007fe`f7371e27 750f jne mscorlib_ni+0x551e38 (000007fe`f7371e38) 000007fe`f7371e29 488d153a4c1100 lea rdx,[mscorlib_ni+0x666a6a (000007fe`f7486a6a)] 000007fe`f7371e30 488b0b mov rcx,qword ptr [rbx] 000007fe`f7371e33 e82053eaff call mscorlib_ni+0x3f7158 (000007fe`f7217158) (mscorlib_ni) 000007fe`f7371e38 803f00 cmp byte ptr [rdi],0 000007fe`f7371e3b 498bd4 mov rdx,r12 000007fe`f7371e3e 488bcf mov rcx,rdi 000007fe`f7371e41 4c8bd8 mov r11,rax 000007fe`f7371e44 ff10 call qword ptr [rax] 000007fe`f7371e46 8be8 mov ebp,eax 000007fe`f7371e48 81e5ffffff7f and ebp,7FFFFFFFh 000007fe`f7371e4e 4c8b4308 mov r8,qword ptr [rbx+8] 000007fe`f7371e52 498b4808 mov rcx,qword ptr [r8+8] 000007fe`f7371e56 81fd00000080 cmp ebp,80000000h 000007fe`f7371e5c 7509 jne mscorlib_ni+0x551e67 (000007fe`f7371e67) 000007fe`f7371e5e 83f9ff cmp ecx,0FFFFFFFFh 000007fe`f7371e61 0f843407d500 je mscorlib_ni+0x12a259b (000007fe`f80c259b) 000007fe`f7371e67 8bc5 mov eax,ebp 000007fe`f7371e69 99 cdq 000007fe`f7371e6a f7f9 idiv eax,ecx 000007fe`f7371e6c 448bfa mov r15d,edx 000007fe`f7371e6f 4533f6 xor r14d,r14d 000007fe`f7371e72 4963f7 movsxd rsi,r15d 000007fe`f7371e75 483bf1 cmp rsi,rcx 000007fe`f7371e78 0f831807d500 jae mscorlib_ni+0x12a2596 (000007fe`f80c2596) 000007fe`f7371e7e 418b74b010 mov esi,dword ptr [r8+rsi*4+10h] 000007fe`f7371e83 85f6 test esi,esi 000007fe`f7371e85 0f8d15010000 jge mscorlib_ni+0x551fa0 (000007fe`f7371fa0) 000007fe`f7371e8b 8b4344 mov eax,dword ptr [rbx+44h] 000007fe`f7371e8e 85c0 test eax,eax 000007fe`f7371e90 0f8fd506d500 jg mscorlib_ni+0x12a256b (000007fe`f80c256b) 000007fe`f7371e96 8b5338 mov edx,dword ptr [rbx+38h] 000007fe`f7371e99 488b4310 mov rax,qword ptr [rbx+10h] 000007fe`f7371e9d 488b4808 mov rcx,qword ptr [rax+8] 000007fe`f7371ea1 3bd1 cmp edx,ecx 000007fe`f7371ea3 0f849e000000 je mscorlib_ni+0x551f47 (000007fe`f7371f47) 000007fe`f7371ea9 8b7b38 mov edi,dword ptr [rbx+38h] 000007fe`f7371eac 8d4701 lea eax,[rdi+1] 000007fe`f7371eaf 894338 mov dword ptr [rbx+38h],eax 000007fe`f7371eb2 488b4b10 mov rcx,qword ptr [rbx+10h] 000007fe`f7371eb6 4863f7 movsxd rsi,edi 000007fe`f7371eb9 488b4108 mov rax,qword ptr [rcx+8] 000007fe`f7371ebd 483bf0 cmp rsi,rax 000007fe`f7371ec0 0f83d006d500 jae mscorlib_ni+0x12a2596 (000007fe`f80c2596) 000007fe`f7371ec6 488d0476 lea rax,[rsi+rsi*2] 000007fe`f7371eca 488d4cc110 lea rcx,[rcx+rax*8+10h] 000007fe`f7371ecf 896908 mov dword ptr [rcx+8],ebp 000007fe`f7371ed2 488b5308 mov rdx,qword ptr [rbx+8] 000007fe`f7371ed6 4963ef movsxd rbp,r15d 000007fe`f7371ed9 488b4208 mov rax,qword ptr [rdx+8] 000007fe`f7371edd 483be8 cmp rbp,rax 000007fe`f7371ee0 0f83b006d500 jae mscorlib_ni+0x12a2596 (000007fe`f80c2596) 000007fe`f7371ee6 8b44aa10 mov eax,dword ptr [rdx+rbp*4+10h] 000007fe`f7371eea 89410c mov dword ptr [rcx+0Ch],eax 000007fe`f7371eed 498bd4 mov rdx,r12 000007fe`f7371ef0 e81351eaff call mscorlib_ni+0x3f7008 (000007fe`f7217008) (mscorlib_ni) 000007fe`f7371ef5 488b4b10 mov rcx,qword ptr [rbx+10h] 000007fe`f7371ef9 488b4108 mov rax,qword ptr [rcx+8] 000007fe`f7371efd 483bf0 cmp rsi,rax 000007fe`f7371f00 0f839006d500 jae mscorlib_ni+0x12a2596 (000007fe`f80c2596) 000007fe`f7371f06 488d0476 lea rax,[rsi+rsi*2] 000007fe`f7371f0a 44886cc120 mov byte ptr [rcx+rax*8+20h],r13b 000007fe`f7371f0f 488b4b08 mov rcx,qword ptr [rbx+8] 000007fe`f7371f13 488b4108 mov rax,qword ptr [rcx+8] 000007fe`f7371f17 483be8 cmp rbp,rax 000007fe`f7371f1a 0f837606d500 jae mscorlib_ni+0x12a2596 (000007fe`f80c2596) 000007fe`f7371f20 897ca910 mov dword ptr [rcx+rbp*4+10h],edi 000007fe`f7371f24 8b433c mov eax,dword ptr [rbx+3Ch] 000007fe`f7371f27 ffc0 inc eax 000007fe`f7371f29 89433c mov dword ptr [rbx+3Ch],eax 000007fe`f7371f2c 4183fe64 cmp r14d,64h 000007fe`f7371f30 0f8fae05d500 jg mscorlib_ni+0x12a24e4 (000007fe`f80c24e4) 000007fe`f7371f36 4883c448 add rsp,48h 000007fe`f7371f3a 415f pop r15 000007fe`f7371f3c 415e pop r14 000007fe`f7371f3e 415d pop r13 000007fe`f7371f40 415c pop r12 000007fe`f7371f42 5f pop rdi 000007fe`f7371f43 5e pop rsi 000007fe`f7371f44 5d pop rbp 000007fe`f7371f45 5b pop rbx 000007fe`f7371f46 c3 ret 000007fe`f7371f47 488bcb mov rcx,rbx 000007fe`f7371f4a e8d1010000 call mscorlib_ni+0x552120 (000007fe`f7372120) (System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.Boolean, mscorlib]].Resize(), mdToken: 00000000060021a7) 000007fe`f7371f4f 488b4308 mov rax,qword ptr [rbx+8] 000007fe`f7371f53 488b4808 mov rcx,qword ptr [rax+8] 000007fe`f7371f57 81fd00000080 cmp ebp,80000000h 000007fe`f7371f5d 7509 jne mscorlib_ni+0x551f68 (000007fe`f7371f68) 000007fe`f7371f5f 83f9ff cmp ecx,0FFFFFFFFh 000007fe`f7371f62 0f843306d500 je mscorlib_ni+0x12a259b (000007fe`f80c259b) 000007fe`f7371f68 8bc5 mov eax,ebp 000007fe`f7371f6a 99 cdq 000007fe`f7371f6b f7f9 idiv eax,ecx 000007fe`f7371f6d 448bfa mov r15d,edx 000007fe`f7371f70 e934ffffff jmp mscorlib_ni+0x551ea9 (000007fe`f7371ea9) 000007fe`f7371f75 33d2 xor edx,edx 000007fe`f7371f77 488bcb mov rcx,rbx 000007fe`f7371f7a e8f1000000 call mscorlib_ni+0x552070 (000007fe`f7372070) (System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.Boolean, mscorlib]].Initialize(Int32), mdToken: 00000000060021a4) 000007fe`f7371f7f e98efeffff jmp mscorlib_ni+0x551e12 (000007fe`f7371e12) 000007fe`f7371f84 488d0449 lea rax,[rcx+rcx*2] 000007fe`f7371f88 8b74c21c mov esi,dword ptr [rdx+rax*8+1Ch] 000007fe`f7371f8c 85f6 test esi,esi 000007fe`f7371f8e 0f8ccc000000 jl mscorlib_ni+0x552060 (000007fe`f7372060) 000007fe`f7371f94 666666660f1f840000000000 nop word ptr [rax+rax] 000007fe`f7371fa0 488b4b10 mov rcx,qword ptr [rbx+10h] 000007fe`f7371fa4 4863fe movsxd rdi,esi 000007fe`f7371fa7 488b4108 mov rax,qword ptr [rcx+8] 000007fe`f7371fab 483bf8 cmp rdi,rax 000007fe`f7371fae 0f83e205d500 jae mscorlib_ni+0x12a2596 (000007fe`f80c2596) 000007fe`f7371fb4 488d147f lea rdx,[rdi+rdi*2] 000007fe`f7371fb8 8b44d118 mov eax,dword ptr [rcx+rdx*8+18h] 000007fe`f7371fbc 3bc5 cmp eax,ebp 000007fe`f7371fbe 7419 je mscorlib_ni+0x551fd9 (000007fe`f7371fd9) >>> 000007fe`f7371fc0 41ffc6 inc r14d 000007fe`f7371fc3 488b5310 mov rdx,qword ptr [rbx+10h] 000007fe`f7371fc7 4863ce movsxd rcx,esi 000007fe`f7371fca 488b4208 mov rax,qword ptr [rdx+8] 000007fe`f7371fce 483bc8 cmp rcx,rax 000007fe`f7371fd1 0f83bf05d500 jae mscorlib_ni+0x12a2596 (000007fe`f80c2596) 000007fe`f7371fd7 ebab jmp mscorlib_ni+0x551f84 (000007fe`f7371f84) 000007fe`f7371fd9 4c8b6b18 mov r13,qword ptr [rbx+18h] 000007fe`f7371fdd 488b44d110 mov rax,qword ptr [rcx+rdx*8+10h] 000007fe`f7371fe2 4889442430 mov qword ptr [rsp+30h],rax 000007fe`f7371fe7 488b03 mov rax,qword ptr [rbx] 000007fe`f7371fea 488b4830 mov rcx,qword ptr [rax+30h] 000007fe`f7371fee 488b01 mov rax,qword ptr [rcx] 000007fe`f7371ff1 488b4020 mov rax,qword ptr [rax+20h] 000007fe`f7371ff5 4885c0 test rax,rax 000007fe`f7371ff8 750f jne mscorlib_ni+0x552009 (000007fe`f7372009) 000007fe`f7371ffa 488d15754a1100 lea rdx,[mscorlib_ni+0x666a76 (000007fe`f7486a76)] 000007fe`f7372001 488b0b mov rcx,qword ptr [rbx] 000007fe`f7372004 e84f51eaff call mscorlib_ni+0x3f7158 (000007fe`f7217158) (mscorlib_ni) 000007fe`f7372009 41807d0000 cmp byte ptr [r13],0 000007fe`f737200e 4d8bc4 mov r8,r12 000007fe`f7372011 488b542430 mov rdx,qword ptr [rsp+30h] 000007fe`f7372016 498bcd mov rcx,r13 000007fe`f7372019 4c8bd8 mov r11,rax 000007fe`f737201c ff10 call qword ptr [rax] 000007fe`f737201e 0fb6c8 movzx ecx,al 000007fe`f7372021 85c9 test ecx,ecx 000007fe`f7372023 749b je mscorlib_ni+0x551fc0 (000007fe`f7371fc0) 000007fe`f7372025 8a442428 mov al,byte ptr [rsp+28h] 000007fe`f7372029 0fb6c0 movzx eax,al 000007fe`f737202c 85c0 test eax,eax 000007fe`f737202e 0f856c05d500 jne mscorlib_ni+0x12a25a0 (000007fe`f80c25a0) 000007fe`f7372034 488b4b10 mov rcx,qword ptr [rbx+10h] 000007fe`f7372038 488b4108 mov rax,qword ptr [rcx+8] 000007fe`f737203c 483bf8 cmp rdi,rax 000007fe`f737203f 0f835105d500 jae mscorlib_ni+0x12a2596 (000007fe`f80c2596) 000007fe`f7372045 488d047f lea rax,[rdi+rdi*2] 000007fe`f7372049 8a542429 mov dl,byte ptr [rsp+29h] 000007fe`f737204d 8854c120 mov byte ptr [rcx+rax*8+20h],dl 000007fe`f7372051 8b433c mov eax,dword ptr [rbx+3Ch] 000007fe`f7372054 ffc0 inc eax 000007fe`f7372056 89433c mov dword ptr [rbx+3Ch],eax 000007fe`f7372059 e9d8feffff jmp mscorlib_ni+0x551f36 (000007fe`f7371f36) 000007fe`f737205e 6690 xchg ax,ax 000007fe`f7372060 448a6c2429 mov r13b,byte ptr [rsp+29h] 000007fe`f7372065 e921feffff jmp mscorlib_ni+0x551e8b (000007fe`f7371e8b) Cold region: 000007fe`f80c24e4 488d7b18 lea rdi,[rbx+18h] 000007fe`f80c24e8 488b0f mov rcx,qword ptr [rdi] 000007fe`f80c24eb e8b098a6ff call mscorlib_ni+0xd0bda0 (000007fe`f7b2bda0) (System.Collections.HashHelpers.IsWellKnownEqualityComparer(System.Object), mdToken: 00000000060020f7) 000007fe`f80c24f0 0fb6c8 movzx ecx,al 000007fe`f80c24f3 85c9 test ecx,ecx 000007fe`f80c24f5 0f843bfa2aff je mscorlib_ni+0x551f36 (000007fe`f7371f36) 000007fe`f80c24fb 488b0f mov rcx,qword ptr [rdi] 000007fe`f80c24fe e81d99a6ff call mscorlib_ni+0xd0be20 (000007fe`f7b2be20) (System.Collections.HashHelpers.GetRandomizedEqualityComparer(System.Object), mdToken: 00000000060020f8) 000007fe`f80c2503 488bf0 mov rsi,rax 000007fe`f80c2506 488b03 mov rax,qword ptr [rbx] 000007fe`f80c2509 488b4830 mov rcx,qword ptr [rax+30h] 000007fe`f80c250d 488b01 mov rax,qword ptr [rcx] 000007fe`f80c2510 488b4028 mov rax,qword ptr [rax+28h] 000007fe`f80c2514 4885c0 test rax,rax 000007fe`f80c2517 750f jne mscorlib_ni+0x12a2528 (000007fe`f80c2528) 000007fe`f80c2519 488d15c04c3cff lea rdx,[mscorlib_ni+0x6671e0 (000007fe`f74871e0)] 000007fe`f80c2520 488b0b mov rcx,qword ptr [rbx] 000007fe`f80c2523 e8304c15ff call mscorlib_ni+0x3f7158 (000007fe`f7217158) (mscorlib_ni) 000007fe`f80c2528 488bd6 mov rdx,rsi 000007fe`f80c252b 488bc8 mov rcx,rax 000007fe`f80c252e e8354c15ff call mscorlib_ni+0x3f7168 (000007fe`f7217168) (mscorlib_ni) 000007fe`f80c2533 488bd0 mov rdx,rax 000007fe`f80c2536 488bcf mov rcx,rdi 000007fe`f80c2539 e8ca4a15ff call mscorlib_ni+0x3f7008 (000007fe`f7217008) (mscorlib_ni) 000007fe`f80c253e 488b4310 mov rax,qword ptr [rbx+10h] 000007fe`f80c2542 488b5008 mov rdx,qword ptr [rax+8] 000007fe`f80c2546 41b001 mov r8b,1 000007fe`f80c2549 488bcb mov rcx,rbx 000007fe`f80c254c 488d051dfc2aff lea rax,[mscorlib_ni+0x552170 (000007fe`f7372170)] 000007fe`f80c2553 4883c448 add rsp,48h 000007fe`f80c2557 415f pop r15 000007fe`f80c2559 415e pop r14 000007fe`f80c255b 415d pop r13 000007fe`f80c255d 415c pop r12 000007fe`f80c255f 5f pop rdi 000007fe`f80c2560 5e pop rsi 000007fe`f80c2561 5d pop rbp 000007fe`f80c2562 5b pop rbx 000007fe`f80c2563 48ffe0 jmp rax 000007fe`f80c2566 e9cbf92aff jmp mscorlib_ni+0x551f36 (000007fe`f7371f36) 000007fe`f80c256b 8b7b40 mov edi,dword ptr [rbx+40h] 000007fe`f80c256e 488b5310 mov rdx,qword ptr [rbx+10h] 000007fe`f80c2572 4863cf movsxd rcx,edi 000007fe`f80c2575 488b4208 mov rax,qword ptr [rdx+8] 000007fe`f80c2579 483bc8 cmp rcx,rax 000007fe`f80c257c 7318 jae mscorlib_ni+0x12a2596 (000007fe`f80c2596) 000007fe`f80c257e 488d0449 lea rax,[rcx+rcx*2] 000007fe`f80c2582 8b4cc21c mov ecx,dword ptr [rdx+rax*8+1Ch] 000007fe`f80c2586 894b40 mov dword ptr [rbx+40h],ecx 000007fe`f80c2589 8b4344 mov eax,dword ptr [rbx+44h] 000007fe`f80c258c ffc8 dec eax 000007fe`f80c258e 894344 mov dword ptr [rbx+44h],eax 000007fe`f80c2591 e91cf92aff jmp mscorlib_ni+0x551eb2 (000007fe`f7371eb2) 000007fe`f80c2596 e8d54a15ff call mscorlib_ni+0x3f7070 (000007fe`f7217070) (mscorlib_ni) 000007fe`f80c259b e8b04b15ff call mscorlib_ni+0x3f7150 (000007fe`f7217150) (mscorlib_ni) 000007fe`f80c25a0 b90e000000 mov ecx,0Eh 000007fe`f80c25a5 e83e9915ff call mscorlib_ni+0x3fbee8 (000007fe`f721bee8) (System.ThrowHelper.GetResourceName(System.ExceptionResource), mdToken: 0000000006000261) 000007fe`f80c25aa 488bc8 mov rcx,rax 000007fe`f80c25ad e8665f15ff call mscorlib_ni+0x3f8518 (000007fe`f7218518) (System.Environment.GetResourceFromDefault(System.String), mdToken: 0000000006000c8a) 000007fe`f80c25b2 488bd8 mov rbx,rax 000007fe`f80c25b5 488d0ddcac44ff lea rcx,[mscorlib_ni+0x6ed298 (000007fe`f750d298)] 000007fe`f80c25bc e8574a15ff call mscorlib_ni+0x3f7018 (000007fe`f7217018) (mscorlib_ni) 000007fe`f80c25c1 488bf8 mov rdi,rax 000007fe`f80c25c4 488bd3 mov rdx,rbx 000007fe`f80c25c7 488bcf mov rcx,rdi 000007fe`f80c25ca e8518e1eff call mscorlib_ni+0x48b420 (000007fe`f72ab420) (System.Exception..ctor(System.String), mdToken: 000000000600001d) 000007fe`f80c25cf c7878c00000001151380 mov dword ptr [rdi+8Ch],80131501h 000007fe`f80c25d9 c7878c00000057000780 mov dword ptr [rdi+8Ch],80070057h 000007fe`f80c25e3 488bcf mov rcx,rdi 000007fe`f80c25e6 e8954a15ff call mscorlib_ni+0x3f7080 (000007fe`f7217080) (mscorlib_ni) 000007fe`f80c25eb b905000000 mov ecx,5 000007fe`f80c25f0 e8e39815ff call mscorlib_ni+0x3fbed8 (000007fe`f721bed8) (System.ThrowHelper.GetArgumentName(System.ExceptionArgument), mdToken: 0000000006000260) 000007fe`f80c25f5 488bd8 mov rbx,rax 000007fe`f80c25f8 488d0d01a144ff lea rcx,[mscorlib_ni+0x6ec700 (000007fe`f750c700)] 000007fe`f80c25ff e8144a15ff call mscorlib_ni+0x3f7018 (000007fe`f7217018) (mscorlib_ni) 000007fe`f80c2604 488bf8 mov rdi,rax 000007fe`f80c2607 488d15f2e9d5fe lea rdx,[mscorlib_ni+0x1000 (000007fe`f6e21000)] 000007fe`f80c260e b9a8650070 mov ecx,700065A8h 000007fe`f80c2613 e8604a15ff call mscorlib_ni+0x3f7078 (000007fe`f7217078) (mscorlib_ni) 000007fe`f80c2618 488bc8 mov rcx,rax 000007fe`f80c261b e8f85e15ff call mscorlib_ni+0x3f8518 (000007fe`f7218518) (System.Environment.GetResourceFromDefault(System.String), mdToken: 0000000006000c8a) 000007fe`f80c2620 488bd0 mov rdx,rax 000007fe`f80c2623 488bcf mov rcx,rdi 000007fe`f80c2626 e8b58d1eff call mscorlib_ni+0x48b3e0 (000007fe`f72ab3e0) (System.SystemException..ctor(System.String), mdToken: 0000000006000515) 000007fe`f80c262b 488d8f98000000 lea rcx,[rdi+98h] 000007fe`f80c2632 488bd3 mov rdx,rbx 000007fe`f80c2635 e8ce4915ff call mscorlib_ni+0x3f7008 (000007fe`f7217008) (mscorlib_ni) 000007fe`f80c263a c7878c00000057000780 mov dword ptr [rdi+8Ch],80070057h 000007fe`f80c2644 c7878c00000003400080 mov dword ptr [rdi+8Ch],80004003h 000007fe`f80c264e 488bcf mov rcx,rdi 000007fe`f80c2651 e82a4a15ff call mscorlib_ni+0x3f7080 (000007fe`f7217080) (mscorlib_ni) 000007fe`f80c2656 90 nop
Tohle už je trochu pocitové luštění, přeci-jenom čistý assembler je lepší psát, než interpretovat. Z instrukcí pro inkrementaci, porovnávání a skoky jsme však dospěli k závěru, že se nacházíme právě uvězněni uvnitř cyklu for v metodě Insert. Hypotéza je, že došlo k poškození spojového seznamu entries a ty nejspíš tvoří cyklus, jehož nekonečné procházení nás vězní.
No dobrá. Myslíme si, že víme, co se děje, ale proč?
Znovu procházíme odspoda zdrojové kódy metod, přes než call-stack prochází. Už tušíme, co chceme hledat (vícenásobný přístup na jeden slovník, který by však měl být pro každou instanci entity samostatný) a dostáváme se do kritického místa:
// class Entity : TracksChangesEntityBase
private IDictionary<string, bool> _propertyChangedInfo = new Dictionary<string, bool>();
public virtual object DeepClone()
{
Entity output = (Entity) base.MemberwiseClone();
DeepCloneHelper.DeepCloneRefProperties(this, output);
output.ResetDirtyProperties(false);
return output;
}
// TracksChangesEntityBase
public virtual void ResetDirtyProperties(bool rememberPreviouslyChangedProperties)
{
if (rememberPreviouslyChangedProperties)
{
this._lastPropertyChangedInfo = this._propertyChangedInfo.ToDictionary<KeyValuePair<string, bool>, string, bool>(v => v.Key, v => v.Value);
}
this._propertyChangedInfo = new Dictionary<string, bool>();
}
Ukazuje se, že slovník změněných properties _propertyChangedInfo se zakládá nový pouze při vytvoření nové instance entity a při volání ResetDirtyProperties(). Metoda DeepClone() volaná po vyzvednutí originálu z cache však nejprve vytvoří MemberwiseClone() shallow-kopii objektu, která referencuje v _propertyChangedInfo stále původní Dictionary<>, pak začne klonovat referencované properties (avšak pod trackingem původního dosud neřešeného slovníku!!!) a až potom se provede ResetDirtyProperties(), který způsobí vytvoření nové instance slovníku pro _propertyChangedInfo.
Pokud se nám tedy sejde více threadů ve správný okamžik, dojde k simultálnímu zápisu do jednoho slovníku z více threadů, který není pro tuto operaci thread-safe. V našem případě tím dojde k nadrbání vnitřní struktury hash-tabulky (nejspíš k cyklu entries) a výsledkem bylo uvíznutí threadů v nekonečných cyklech for.
…jdeme nahlásit bug v UmbracoCMS.
Jako work-around budeme muset zatím přidat nějaké vlastní zámky do míst, která vedou na problematický DeepClone() a zajistí pro začátek vzájemnou výlučnost takových volání.
Koukám, že už je to v Umbraco reportováno a včera opraveno.
Pro slabo-poweshellisty, jako jsem já, si zapisuji postup, jak si z PS připojit session na cloudové Office365:
Podle potřeby: >Set-ExecutionPolicy Unrestricted >$LiveCred = Get-Credential >$Session = New-PSSession -ConfigurationName Microsoft.Exchange -ConnectionUri https://ps.outlook .com/powershell/ -Credential $LiveCred -Authentication Basic -AllowRedirection >Import-PSSession $Session >...
Přihlašovací údaje je samozřejmě potřeba zadat ty z Office365.
Dnes jsem narazil na situaci, kdy jsem v powershellu neviděl subscriptions, které jsem měl dříve k dispozici. Nepomáhalo ani Add-AzureAccount, ani odebrání (všech) accountů a jejich opětovné přidání.
Jako řešení zafungovalo smazání složky C:\Users\USERNAME\AppData\Roaming\Windows Azure Powershell, ve které jsou standardně uloženy “Subscription Data Files”.
Problémem rychlého prozkoumávání velkých memory-dumpů v WinDbg/SOS je, že většinu zkoumání provádíme nad jednotlivými instancemi objektů. Vytipujeme si závadný typ (!dumpheap -stat) a pro pár instancí (!dumpheap -mt <MT>) zkoumáme, odkud pocházejí (!GCRoot <ObjAddr>). Pokud nemáme dost štěstí, po pár pokusech (které mohou být navíc při velkých memory-dumpech dosti časově náročné), nás to přestane bavit.
Nástrojem, jak provést v takovém případě hromadnou analýzu a pohlédnout na heap určitým agregovaným pohledem, je například CLR Profiler a jeho Heap Graph:
Ukazuje nám, jak na sebe jednotlivé typy navzájem referencují, a to vše v poměru k velikosti paměti (included, tedy včetně grafu referencovaných instancí). Vše je seskupeno po typech, nezabýváme se tedy jednotlivými instancemi.
Z WinDbg/SOS je potřeba si vytvořit LOG-soubor pro CLR profiler pomocí příkazu
!TraverseHeap C:\output-path\name.log
…to samotné může nad velkým memory-dumpem hooodně trvat. Podle stroje a dumpu až hodiny. Na rozdíl od čekání na !GCRoot však dostanete výstup, který vás k cíli téměř jistě navede.
Následně již soubor načteme do CLR Profileru pomocí File / Open log file…
…zase čekáme a čekáme :-))
A na dialogu Summary for zvolíme Heap Graph
…čekáme a čekáme, až dostaneme třeba:
Cache není nikdy dost ;-)
Mimochodem CLR Profiler nám dá i další zajímavé histogramy, které nám pomohou k pochopení poměrů v analyzovaném memory-dumpu. O nich možná někdy příště…
Práci s WinDBG/SOS lze zpříjemnit malým trikem. Pokud za název příkazu (většina to podporuje) připojíte přepínač /d, bude výstup klikatelný (spustí příkaz, který odpovídá prozkoumání daného cíle dle jeho typu):
Pokud se nám nechce /d za každý příkaz psát, můžeme ho zapnout globálně:
.prefer_dml 1
Vypnout lze samozřejmě nulou.
Oficiálně se to celé jmenuje „Debugger Mark Up Language“ (DML).
HAVIT Knowledge Base 