Tag Archives: DebugDiag

.NET Memory Internals & Advanced Debugging – záznam, dema a slides [WUG Brno 05/2016]

Slides a dema z mé přednášky pro WUG Brno z 31.5.2016:

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

Dotčená témata

  • StackOverflow troubleshooting
  • Stack
  • Windows Debugger, SOS, DebugDiag
  • Heap
  • Garbage Collector
  • Prozkoumávání haldy, rootů, finalization queue
  • GC Root identification (static fields)
  • Debugging dema

Advanced Debugging Stories .NET – záznam, dema a slides [WUG Praha 4/2016]

Slides a dema z mé přednášky pro setkání WUG Praha z 12.4.2016:

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

Dotčená témata a nástroje

  • Windows Debugger + SOS.dll extension
  • Memory Dump Analysis, Crash Dump Analysis
  • DebugDiag, ClrProfiler
  • Microsoft Diagnostics Runtime
  • Stack analysis
  • Heap analysis, Garbage Collection, Finalization
  • StackOverflow

[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

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.

Debugging Story: Race-condition v Umbraco CMS (DeepClone)

Ř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í.

Symptom

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.

Analysis

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ř.

  • kolik je zhruba čeho v paměti (kolik zabírá managed heap, jaké typy v něm zabírají nejvíce paměti, …)
  • kolik je threadů a co dělají (call-stacky, waity/locky, …)
  • jestli zrovna běží úkolid garbage-collectorem,
  • atp.

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:

  1. Přichází web-request na službu poskytující front-endu data o resources. Náš REST-API UmContentApiController vrací front-endu strukturu všech resources, které UmbracoCMS v má (UmContentApiController.Resources()).
  2. Během sestavování výstupu pro jednotlivé resources vyhodnocuje případné symbolické odkazy v nich a překládá je na reálné URL adresy jednotlivých cílových objektů – TemplateUtilities.ParseInternalLinks()
  3. Pro každý nalezený symbolický odkaz je známo ID cílového objektu a přes UrlProvider.GetUrl() se Umbraco snaží vyhodnotit cílové URL. Dělá to voláním metody GetUrl() na každém zaregistrovaném UrlProvideru, jedním z nichž je náš EpoUrlProvider.
  4. V EpoUrlProvider.GetUrl() se hned na začátku získává z ID entita reprezentující cílový content (jehož URL se má sestavit), volá se tedy ContentService.GetById(), které přes ContentRepository (transient) dojde až na RuntimeCacheProvider.GetById(), který když v cache objekt najde, chce vrátit jeho DeepClone().
  5. DeepClone() dělá kopii objektu a to tak, že nejprve vytvoří shallow-copy a následně klonuje jednotlivé referencované objekty. V jednom z nich (ContentType) se tak dostane až na setter property AllowedTemplates. V něm (a všech obdobných properties na potomcích třídy TracksChangesEntityBase) je setter ošetřen tak, že při ukládání nové hodnoty porovná s hodnotou původní, a pokud je honota změněna, uloží do slovníku informaci, že property daného jména je Changed/Dirty (vše pomocí metody SetPropertyValueAndDetectChanges() a OnPropertyChanged():
    // 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:

  • System.__Canon je interní záležitost .NET frameworku, která se vyskytuje v určitých runtime situacích u generik,

Deeper Analysis

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í.

Cause

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.

Závěr

…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í.

Update

Koukám, že už je to v Umbraco reportováno a včera opraveno.