November Happy Hour will be moved to Thursday December 5th.
November Happy Hour will be moved to Thursday December 5th.
It sounds to me like your application is recycleing itself due to inactivity.
First, check settings for your application pool in IIS.
Precess Model -> Idle time-out(minutes), default value is 20 minutes. If application pool have not recived any request for 20 minutes it is recyckled.
You can also genereate a log entry for every time IIS recycle your applicationpool
Recycling -> Generate Recycle Event Log Entry
You will find event log entries in Event Viever
Custom Views -> Server Roles -> Web Server (IIS)
Thanks Christian for your suggestion.
My app-pools do recycle after 20 minutes of inactivity as far as I can tell from configuration. I have set true every logging option under recycling for them, but I find no recycle events logged apart from ones that correspond to a recycle that occurs regularly as planned according to schedule. I conclude that my app-pools only recycle due to their recycle-schedule.
While the problematic downtime that I am observing does consistently overlap these "healthy", scheduled recycle events, I also have occurances that do not.
So I have been looking for other danger signs and found -- using DebugDiag tool to do an analysis of a memory dump -- that a very high number of "objects" are "ready for finalization". By taking mem dumps some hours apart, I've seen this number increase from a couple of thousand objects (already high), to over a million.
So now I'm looking to figure out which objects the c# destructor fails to kill.
With the site being fairly big, I've got a lot of ground to cover. So any advice will be greatly appreciated...
hi,
there are more reasons behind the scene why iis decides to "reboot" your app process, not just scheduled recycle. I would run Perf Counters and see what halleha with memory over time to detect, maybe you have memory leak, GC is under pressure and runtime decides to give up. if so, then analysis or mem leak and finding GC roots should be fairly easy. please post further analysis (if you have) as I'm quite interested in issues like these.. thx
+ if you have dumpz it should be easy to get finalization queue (or f-reachable) content and appropriate types. more info - http://blogs.microsoft.co.il/sasha/2012/02/25/finalization-queue-or-f-reachable-queue-find-out-with-sos/
I've been looking further into this, but still haven't arrived at a conclusion. I've tried using WinDbg and sos.dll to see if I can find a cause for a memory leak. In case anyone is interested in following this, I'm posting some more data below. I still appreciate very much any input you may have.
First I try !FinalizeQueue on my dev env immediately after recycling iis app-pool.
0:056> !FinalizeQueue
SYMSRV: BYINDEX: 0x13
C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\sym
clr.pdb
4FC858030CE049CABE3D609AEB004ABB2
SYMSRV: PATH: C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\sym\clr.pdb\4FC858030CE049CABE3D609AEB004ABB2\clr.pdb
SYMSRV: RESULT: 0x00000000
DBGHELP: C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\sym\clr.pdb\4FC858030CE049CABE3D609AEB004ABB2\clr.pdb cached to C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\sym\clr.pdb\4FC858030CE049CABE3D609AEB004ABB2\clr.pdb
DBGHELP: clr - public symbols
C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\sym\clr.pdb\4FC858030CE049CABE3D609AEB004ABB2\clr.pdb
SyncBlocks to be cleaned up: 0
Free-Threaded Interfaces to be released: 0
MTA Interfaces to be released: 0
STA Interfaces to be released: 0
----------------------------------
------------------------------
Heap 0
generation 0 has 1585 finalizable objects (000000799330f128->00000079933122b0)
generation 1 has 1509 finalizable objects (000000799330c200->000000799330f128)
generation 2 has 19000 finalizable objects (00000079932e7040->000000799330c200)
Ready for finalization 0 objects (00000079933122b0->00000079933122b0)
------------------------------
Heap 1
generation 0 has 758 finalizable objects (0000007993b00cf0->0000007993b024a0)
generation 1 has 1298 finalizable objects (0000007993afe460->0000007993b00cf0)
generation 2 has 17540 finalizable objects (0000007993adc040->0000007993afe460)
Ready for finalization 0 objects (0000007993b024a0->0000007993b024a0)
------------------------------
Heap 2
generation 0 has 817 finalizable objects (000000799409a510->000000799409be98)
generation 1 has 1495 finalizable objects (0000007994097658->000000799409a510)
generation 2 has 17603 finalizable objects (0000007994075040->0000007994097658)
Ready for finalization 0 objects (000000799409be98->000000799409be98)
------------------------------
Heap 3
generation 0 has 2036 finalizable objects (0000007993dd12f0->0000007993dd5290)
generation 1 has 1790 finalizable objects (0000007993dcdb00->0000007993dd12f0)
generation 2 has 18264 finalizable objects (0000007993daa040->0000007993dcdb00)
Ready for finalization 0 objects (0000007993dd5290->0000007993dd5290)
Statistics for all finalizable objects (including all objects ready for finalization):
MT Count TotalSize Class Name
00007ffb45847e00 1 24 System.Web.Configuration.ImpersonateTokenRef
00007ffba36e0638 1 32 System.Threading.Gen2GcCallback
00007ffb4c25a700 1 32 System.Threading.ThreadLocal`1+FinalizationHelper[[System.Collections.Concurrent.ConcurrentBag`1+ThreadLocalList[[EPiServer.Data.SchemaUpdates.ISchemaValidator, EPiServer.Data]], System]]
00007ffb4c2590e0 1 32 System.Threading.ThreadLocal`1+FinalizationHelper[[System.Collections.Concurrent.ConcurrentBag`1+ThreadLocalList[[EPiServer.Data.SchemaUpdates.ISchemaUpdater, EPiServer.Data]], System]]
00007ffb470c5f48 1 32 System.Net.SafeLocalFree
00007ffb46f67bf8 1 32 Microsoft.Win32.SafeHandles.SafeProcessHandle
00007ffb46d70ed0 1 32 Bid+AutoInit
00007ffb456095e8 1 32 System.Web.PerfInstanceDataHandle
00007ffba3725988 1 40 System.Threading.RegisteredWaitHandleSafe
00007ffb4ed12340 1 40 System.Threading.ThreadLocal`1[[Mediachase.Commerce.Core.SiteContext, Mediachase.Commerce]]
00007ffb4c45b758 1 40 System.Threading.ThreadLocal`1[[StructureMap.Pipeline.IObjectCache, StructureMap]]
00007ffb4c341748 1 40 System.Threading.ThreadLocal`1[[Mediachase.Commerce.Catalog.ICatalogSystem, Mediachase.Commerce]]
00007ffb4c25a108 1 40 System.Threading.ThreadLocal`1[[System.Collections.Concurrent.ConcurrentBag`1+ThreadLocalList[[EPiServer.Data.SchemaUpdates.ISchemaValidator, EPiServer.Data]], System]]
...
...omitted...
...
00007ffb4bced4e0 67 39128 Mediachase.Commerce.Catalog.Dto.CatalogEntryDto+CatalogAssociationDataTable
00007ffb4bce77c0 67 39664 Mediachase.Commerce.Catalog.Dto.CatalogEntryDto+CatalogItemAssetDataTable
00007ffb4bcf09d8 67 41272 Mediachase.Commerce.Catalog.Dto.CatalogEntryDto+SalePriceDataTable
00007ffb4bcebc60 67 41272 Mediachase.Commerce.Catalog.Dto.CatalogEntryDto+CatalogItemSeoDataTable
00007ffb4bce5de8 67 43416 Mediachase.Commerce.Catalog.Dto.CatalogEntryDto+CatalogEntryDataTable
00007ffb4bce3b30 67 43416 Mediachase.Commerce.Catalog.Dto.CatalogEntryDto+VariationDataTable
00007ffb4bc29538 208 46592 Mediachase.Commerce.Catalog.Dto.CatalogNodeDto
00007ffb46eb2280 279 60264 System.Data.SqlClient.SqlConnection
00007ffb46fba690 289 76296 System.Data.SqlClient.SqlCommand
00007ffb46d17dc0 169 86528 System.Data.DataTable
00007ffba36f02b0 1692 121824 System.Reflection.Emit.DynamicResolver
00007ffb4bccea50 208 123136 Mediachase.Commerce.Catalog.Dto.CatalogNodeDto+CatalogItemAssetDataTable
00007ffb4bcce1d0 208 128128 Mediachase.Commerce.Catalog.Dto.CatalogNodeDto+CatalogItemSeoDataTable
00007ffb4bccd8f0 208 136448 Mediachase.Commerce.Catalog.Dto.CatalogNodeDto+CatalogNodeDataTable
00007ffb4bc29938 2277 491832 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto
00007ffba36bc170 10492 671488 System.Threading.ReaderWriterLock
00007ffb4bce0898 2277 1311552 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto+NodeEntryRelationDataTable
00007ffb4bce0058 2277 1311552 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto+CatalogNodeRelationDataTable
00007ffb4bce1998 2277 1347984 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto+CatalogItemAssetDataTable
00007ffb4bce1118 2277 1347984 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto+CatalogEntryRelationDataTable
00007ffb46d1ab50 56550 12214800 System.Data.DataColumn
Total 83695 objects
Repeat after five minutes
...omitted...
00007ffba36bc170 24129 1544256 System.Threading.ReaderWriterLock
00007ffb4bce0898 5606 3229056 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto+NodeEntryRelationDataTable
00007ffb4bce0058 5606 3229056 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto+CatalogNodeRelationDataTable
00007ffb4bce1998 5606 3318752 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto+CatalogItemAssetDataTable
00007ffb4bce1118 5606 3318752 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto+CatalogEntryRelationDataTable
00007ffb46d1ab50 124743 26944488 System.Data.DataColumn
Total 183137 objects
Everything seems to have doubled up nicely. Again after a couple of hours
...omitted...
00007ffba36bc170 148363 9495232 System.Threading.ReaderWriterLock
00007ffb48740058 18315 10549440 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto+NodeEntryRelationDataTable
00007ffb4873f130 18315 10549440 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto+CatalogNodeRelationDataTable
00007ffb48741168 18315 10842480 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto+CatalogItemAssetDataTable
00007ffb487408d8 18315 10842480 Mediachase.Commerce.Catalog.Dto.CatalogRelationDto+CatalogEntryRelationDataTable
00007ffb46d61350 926768 200181888 System.Data.DataColumn
Total 1260290 objects
Some thoughts:
1. In these three and all other cases I only ever see 0 objects "Ready for finalization", while a ton of objects are finalizable. So my finalizer is tip-top, but the garbage-collector is slacking off?
1.a In my previous post I wrote that I had a whole bunch of objects "Ready for finalization". That was due to the DebugDiag tool. When I use WinDbg on the same memory dump, I get this nice 0.
2. System.Threading.ReaderWriterLock having this many instances waiting around seems bad?
3. System.Data.DataColumn seems to be used a whole bunch in Episerver's Commerce stuff. Given the object counts I see from the above memory analyses:
3.a Am I hitting Mediachase.Commerce.Catalog so eagerly the GB/finalizer can't keep up?
3.b Or are these objects just used frequently and show up here because my GB/finalizer is stuck/deadlocked?
Regarding threads and stuck, I'm not sure what to make of the following.
0:030> !Threads
ThreadCount: 65
UnstartedThread: 0
BackgroundThread: 31
PendingThread: 0
DeadThread: 34
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
6 1 3360 0000001b8be23ee0 28220 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
13 2 bf8 0000001b8becfbc0 2b220 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 MTA (Finalizer)
15 3 23c8 0000001b8bf24710 102a220 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 MTA (Threadpool Worker)
16 4 2eb4 0000001b8bf39210 21220 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
17 9 31ec 0000001fd6c4d800 1020220 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn (Threadpool Worker)
22 23 3020 0000001fdce7cbb0 3029220 Preemptive 0000001DBDC2E4A8:0000001DBDC2EA50 0000001b8bf381d0 0 MTA (Threadpool Worker)
23 27 2f18 0000001fdce7db50 202b220 Preemptive 0000001DBDC301C8:0000001DBDC30A50 0000001b8bf381d0 0 MTA
2 30 2bf0 0000001fdce7e320 20220 Preemptive 0000001EBC9ED298:0000001EBC9EF070 0000001b8be152e0 0 Ukn
18 29 2f34 0000001fdce7eaf0 20220 Preemptive 0000001BBE8A3430:0000001BBE8A5318 0000001b8be152e0 0 Ukn
24 40 3088 0000001fe00256b0 21220 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
25 41 2778 0000001fe0025e80 21220 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
26 42 36d4 0000001fe0026650 21220 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
27 43 22dc 0000001fe0022fa0 21220 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
5 13 3148 0000001fdce7b440 20220 Preemptive 0000001EBD0DE428:0000001EBD0DEFC0 0000001b8be152e0 0 Ukn
3 63 1820 0000001fdccc9370 20220 Preemptive 0000001EBCA385B0:0000001EBCA39070 0000001b8be152e0 0 Ukn
4 39 210c 0000001fdcccba80 20220 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
28 288 30d8 0000001fe1a114b0 1029220 Preemptive 0000001EBD08D080:0000001EBD08EFC0 0000001b8bf381d0 0 MTA (Threadpool Worker)
29 333 3244 0000001fe19c9aa0 1029220 Preemptive 0000001EBD0E0730:0000001EBD0E0FC0 0000001b8be152e0 0 MTA (Threadpool Worker)
30 392 14dc 0000001fe1abd7b0 202b220 Preemptive 0000001DBC374560:0000001DBC3755C0 0000001b8bf381d0 1 MTA
31 66 2c64 0000001fe1aa3020 8029220 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 MTA (Threadpool Completion Port)
32 11 309c 0000001fe1ab7080 1029220 Preemptive 0000001CBD8C1DF8:0000001CBD8C1FD0 0000001b8be152e0 0 MTA (Threadpool Worker)
33 381 254c 0000001fe1a08fe0 1029220 Preemptive 0000001EBD0BB638:0000001EBD0BCFC0 0000001b8be152e0 0 MTA (Threadpool Worker)
34 388 367c 0000001fe1a08040 1029220 Preemptive 0000001DBDC13F90:0000001DBDC14A50 0000001b8be152e0 0 MTA (Threadpool Worker)
35 48 1ee0 0000001fe1aa2850 1029220 Preemptive 0000001EBD0B6D88:0000001EBD0B6FC0 0000001b8be152e0 0 MTA (Threadpool Worker)
36 36 1df0 0000001fe1a08810 1029220 Preemptive 0000001DBDC07128:0000001DBDC08A50 0000001b8be152e0 0 MTA (Threadpool Worker)
37 390 10fc 0000001fe1a09f80 1029220 Preemptive 0000001EBD0B8908:0000001EBD0B8FC0 0000001b8be152e0 0 MTA (Threadpool Worker)
38 70 2a10 0000001fe1a07870 1029220 Preemptive 0000001DBDC30F20:0000001DBDC32A50 0000001b8be152e0 0 MTA (Threadpool Worker)
39 71 3208 0000001fe1aa4790 1029220 Preemptive 0000001EBD0B2058:0000001EBD0B2FC0 0000001b8be152e0 0 MTA (Threadpool Worker)
40 32 242c 0000001fe1abc040 1029220 Preemptive 0000001CBD4E5190:0000001CBD4E5CD0 0000001b8be152e0 0 MTA (Threadpool Worker)
41 380 1adc 0000001fe1abb870 1029220 Preemptive 0000001EBD0DBC00:0000001EBD0DCFC0 0000001b8be152e0 0 MTA (Threadpool Worker)
XXXX 382 0 0000001fe1a0a750 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 28 0 0000001fe1a097b0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 368 0 0000001fe1abc810 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 391 0 0000001fe1aba100 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 33 0 0000001fe1aba8d0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 35 0 0000001fe1abb0a0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 37 0 0000001fe1abcfe0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 69 0 0000001fe033adc0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 5 0 0000001fe0339e20 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 51 0 0000001fe033b590 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 389 0 0000001fe033a5f0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 387 0 0000001fe0339650 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 386 0 0000001fe0338e80 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 385 0 0000001fe0337ee0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 384 0 0000001fe03386b0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 383 0 0000001fe0208980 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 379 0 0000001fe020a0f0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 378 0 0000001fe0209920 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 377 0 0000001fe0209150 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 376 0 0000001fe020a8c0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 310 0 0000001fe1ab60e0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 374 0 0000001fe1a0b6f0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 373 0 0000001fe1aa37f0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 372 0 0000001fe1aa2080 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 371 0 0000001fe1aa3fc0 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 370 0 0000001fe1aa4f60 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 369 0 0000001fe1aa5730 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 367 0 0000001fe1a0af20 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 366 0 0000001fe1a0c690 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 365 0 0000001fe1a0ce60 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 364 0 0000001fe0208020 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 363 0 0000001fe0207850 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
42 362 290c 0000001fe1ab68b0 20220 Preemptive 0000001CBD8CA110:0000001CBD8CBFD0 0000001b8be152e0 0 Ukn
XXXX 361 0 0000001fe0204970 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
XXXX 375 0 0000001fe0205140 39820 Preemptive 0000000000000000:0000000000000000 0000001b8be152e0 0 Ukn
0:030> ~~[bf8]s
ntdll!NtWaitForMultipleObjects+0xa:
00007ffb`adcf0c6a c3 ret
0:013> kb
# RetAddr : Args to Child : Call Site
00 00007ffb`aaea13ed : 00000000`00000000 00007ffb`a4c92405 0000001f`00000002 00007ffb`a4ad5ff6 : ntdll!NtWaitForMultipleObjects+0xa
01 00007ffb`a4b254ae : 00000000`00000000 00007ff7`02fbf000 00000000`00000000 00000000`00000001 : KERNELBASE!WaitForMultipleObjectsEx+0xe1
02 00007ffb`a4c7d4c4 : 00007ffb`a4c7d470 0000001f`d653f830 0000001f`d653f748 00000000`00000000 : clr!FinalizerThread::WaitForFinalizerEvent+0xb6
03 00007ffb`a4ad7c9d : 00000000`00000000 00007ffb`a4c7d470 0000001f`d653f748 0000001f`d653f748 : clr!FinalizerThread::FinalizerThreadWorker+0x54
04 00007ffb`a4ad7c18 : 0000001f`d653f748 00007ffb`a4ad6477 0000bb1f`b8812064 0000001f`d653f830 : clr!ManagedThreadBase_DispatchInner+0x39
05 00007ffb`a4ad7b56 : 00000000`00000000 00007ffb`a4ba611b 00007ffb`00000000 00000000`00000000 : clr!ManagedThreadBase_DispatchMiddle+0x6c
06 00007ffb`a4b9602a : ffffffff`ffffffff 0000001b`8becfbc0 00000000`00000000 00000000`00000000 : clr!ManagedThreadBase_DispatchOuter+0x75
07 00007ffb`a4c91d5f : 00000000`00000000 00000000`00000000 0000001b`8b6346c0 00007ffb`a4b95f20 : clr!FinalizerThread::FinalizerThreadStart+0x10a
SYMSRV: BYINDEX: 0x25
C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\sym
kernel32.pdb
A49C2B8068D747D5B88373C92E68D42C2
SYMSRV: PATH: C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\sym\kernel32.pdb\A49C2B8068D747D5B88373C92E68D42C2\kernel32.pdb
SYMSRV: RESULT: 0x00000000
DBGHELP: C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\sym\kernel32.pdb\A49C2B8068D747D5B88373C92E68D42C2\kernel32.pdb cached to C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\sym\kernel32.pdb\A49C2B8068D747D5B88373C92E68D42C2\kernel32.pdb
DBGHELP: KERNEL32 - public symbols
C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\sym\kernel32.pdb\A49C2B8068D747D5B88373C92E68D42C2\kernel32.pdb
08 00007ffb`ada613d2 : 00007ffb`a4c91ce0 0000001b`8b6346c0 00000000`00000000 00000000`00000000 : clr!Thread::intermediateThreadProc+0x86
09 00007ffb`adc754e4 : 00007ffb`ada613b0 00000000`00000000 00000000`00000000 00000000`00000000 : KERNEL32!BaseThreadInitThunk+0x22
0a 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x34
I would suggest to contact developer support service for further assistant. I'd be interested in looking into this, however only when it is escalated to product development
what is memory dynamic in these cases? do you see growth? from the snippets it's hard to see the issue (unfortunately).
also interesting would be to see following counters:
* Process / %Processor Time
* Process / Virtual Bytes
* Process / Private Bytes
* .NET CLR Memory / All counters (<< how much time spent doing GC, memory is managed and ratio of Gen 0/Gen 1 and Gen 2 collections look)
Also interesting what "!threadpool" would output from the dump?!
btw, what are your version numbers (cms & commerce)?
But definitely, as Quan mentioned - this sounds like a good plan for a dev support services to take a closer look.
Versions
EPiServer.CMS v10.10.4
EPiServer.Commerce v10.8.0
Threadpool of the production memory dump
0:000> !threadpool
CPU utilization: 3%
Worker Thread: Total: 10 Running: 1 Idle: 5 MaxLimit: 32767 MinLimit: 4
Work Request in Queue: 0
--------------------------------------
Number of Timers: 2
--------------------------------------
Completion Port Thread:Total: 4 Free: 4 MaxFree: 8 CurrentLimit: 4 MaxLimit: 1000 MinLimit: 4
I have now contacted developer support. Will keep this thread updated as appropriate.
> "3.a Am I hitting Mediachase.Commerce.Catalog so eagerly the GB/finalizer can't keep up?"
do you have code sample at hand how you are doing this?
> "do you have code sample at hand how you are doing this?"
I did not mean to imply that I am doing something that worries me. I was fishing for a response like "Yes, you need to be careful about how you use it because that library will eat your memory if you're not careful".
I looked into your memory dump very briefly, and could not find anything obvious. The sympton as I saw (and you noticed it as well) it was a lot of DTOs were loaded. To idenfity where the problem is to identify which code loaded those DTOs and how, which needs some other profiling tool like dotMemory. I'd suggest to upgrade to Commerce 11 or later, as we made an improvement with loading DTOs there (if you are loading catalog contents, then the DTOs will not be cached)
> "I'd suggest to upgrade to Commerce 11 or later, as we made an improvement with loading DTOs there (if you are loading catalog contents, then the DTOs will not be cached)"
Just to be clear, you are saying that the DTO's are cached in Commerce ~10, but they are not cached in Commerce 11?
I did not say that. If you load the DTOs explicitly (using ICatalogSystem), then those will still be cached. But if you load catalog contents via IContentLoader then the DTOs needed to construct the catalog contents will not be cached.
> "..as we made an improvement with loading DTOs there (if you are loading catalog contents, then the DTOs will not be cached)"
What I'm asking to have confirmed is that the improvement is equal to the thing in the parentheses.
In any case, thanks for your reply Quan. I will discuss options with my colleageus to figure out what I do next.
We are very into "helping the customer". As I said, we highly recommend to upgrade. Even if it does not help solving this specific problem, it will help your site overall. I will continue to look into the memory dump when I have time (or if you have more to share, like a dotMemory profiling), but it's not my top priority right now (have other stuffs to do, as always :) )
Hi Rasmus
I have the same problem as you. Did you find a solution for the problem?
I have a website where I use Episerver CMS 11 and also Commerce. I have an issue on my site where it is occasionally unresponsive for up to a couple of minutes. When recovered from this period of unresponsiveness, I have noticed the following line consistently in my log:
2018-12-13 00:14:15,167 [1] WARN EPiServer.Core.Internal.ContentCacheRemover: Cache cleared
The mystery-cache-clear is logged about 4-8 times per day, and seems to follow no pattern (except on 03:00 every day when I recycle app-pool in IIS). For example, this 24-hour period:
2018-11-11 03:00:27,079
2018-11-11 08:03:05,568
2018-11-11 12:12:04,301
2018-11-11 16:36:37,739
2018-11-11 19:48:09,106
2018-11-11 22:48:15,181
In my dev environment, I can trigger the "Cache cleared" message by running an iisreset.
I have noticed a warning event logged in windows Event Viewer -- under System -- for most of the periods of unresponsiveness, but not all.
Source: WAS, ID: 5011, Message:
A process serving application pool 'MyPool' suffered a fatal communication error with the Windows Process Activation Service. The process id was '3788'. The data field contains the error number.
Source: WAS, ID: 5010, Message:
A process serving application pool 'MyPool' failed to respond to a ping. The process id was '4500'.
My questions:
1. When/why does EPiServer log the "Cache cleared" message?
1.a Is the message logged consistently on startup?
2. My theory is that the EPiServer app is rebooted, and that the cache is cleared on initialization.
2.a Under what conditions can I expect EPi to reboot itself?
2.b Under what conditions can I expect IIS to reboot EPi?
3. Other theories?