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í:
- Machine.Config, Web.Config or Global.asax are modified
- The bin directory or its contents is modified
- 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)
- The physical path of the virtual directory is modified
- The CAS policy is modified
- The web service is restarted
- (.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:
- KB911272 – https://support.microsoft.com/en-us/kb/911272/
- KB950573 – https://support2.microsoft.com/default.aspx?scid=kb;EN-US;950573
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.
HAVIT Knowledge Base 