search

aspnet / MusicStore

[Archived] MusicStore test application that uses ASP.NET/EF Core. Project moved to https://github.com/aspnet/AspNetCore
1.3k stars 878 forks source link

MusicStore app consumes >3GB memory with 300 connections - WorkStationGC #622

Closed sivagms closed 8 years ago

sivagms commented 8 years ago

Please take a look at the memory dump /CC @SajayAntony

DavidObando commented 8 years ago

The minidump is 5.15 GB. SOSEX is also having trouble creating a heap index (it's been running for over 18 hours now) although it doesn't appear to be stuck. Will update again when there's progress.

DavidObando commented 8 years ago

The dump is unusable by the tools I've tried so far as unfortunately it was taken during garbage collection. Indexing the heap isn't possible with this dump. Will talk to @sivagms regarding getting another dump.

rynowak commented 8 years ago

This might be the same issue I was running into investigating https://github.com/aspnet/Mvc/issues/3516 - I'd be interested to see this when you get the data.

sajayantony commented 8 years ago

@martinpf can you help David get another process dump?

sivagms commented 8 years ago

i'll get a new dump

DavidObando commented 8 years ago

@sivagms do we have a new dump for this?

sivagms commented 8 years ago

@mnltejaswini

sivagms commented 8 years ago

shared the dump location in email

DavidObando commented 8 years ago

Just a heads up: after opening the dump I was surprised to see there were almost 11 thousand threads there. Not sure why.

rynowak commented 8 years ago

Any callstacks of those?

DavidObando commented 8 years ago

Almost all of them have this:

# Child-SP          RetAddr           Call Site
00 000000f1`1b932218 00007ffa`d2d613ed ntdll!ZwWaitForMultipleObjects+0xa [o:\blue.obj.amd64fre\minkernel\ntdll\daytona\objfre\amd64\usrstubs.asm @ 894]
01 000000f1`1b932220 00007ffa`b18139b3 KERNELBASE!WaitForMultipleObjectsEx+0xe1 [d:\blue\minkernel\kernelbase\synch.c @ 1471]
02 (Inline Function) --------`-------- coreclr!WaitForMultipleObjectsEx_SO_TOLERANT+0x18 [f:\dd\ndp\clr\src\vm\threads.cpp @ 4278]
03 (Inline Function) --------`-------- coreclr!Thread::DoAppropriateAptStateWait+0xe8 [f:\dd\ndp\clr\src\vm\threads.cpp @ 4312]
04 000000f1`1b932500 00007ffa`b1813765 coreclr!Thread::DoAppropriateWaitWorker+0x21b [f:\dd\ndp\clr\src\vm\threads.cpp @ 4452]
05 000000f1`1b9325b0 00007ffa`b182db0b coreclr!Thread::DoAppropriateWait+0x7d [f:\dd\ndp\clr\src\vm\threads.cpp @ 4119]
06 000000f1`1b932630 00007ffa`b18d44fa coreclr!CLREventBase::WaitEx+0x57 [f:\dd\ndp\clr\src\vm\synch.cpp @ 754]
07 (Inline Function) --------`-------- coreclr!CLREventBase::Wait+0xf [f:\dd\ndp\clr\src\vm\synch.cpp @ 672]
08 000000f1`1b932680 00007ffa`b18d440a coreclr!AwareLock::EnterEpilogHelper+0xca [f:\dd\ndp\clr\src\vm\syncblk.cpp @ 3118]
09 000000f1`1b932740 00007ffa`b18d48cf coreclr!AwareLock::EnterEpilog+0x62 [f:\dd\ndp\clr\src\vm\syncblk.cpp @ 3063]
0a 000000f1`1b9327a0 00007ffa`b18ceae9 coreclr!AwareLock::Contention+0x273 [f:\dd\ndp\clr\src\vm\syncblk.cpp @ 3413]
0b 000000f1`1b932860 00007ffa`525fce32 coreclr!JITutil_MonContention+0xb1 [f:\dd\ndp\clr\src\vm\jithelpers.cpp @ 5195]
0c 000000f1`1b932a00 000000ec`95ff36e8 0x00007ffa`525fce32
0d 000000f1`1b932a08 000000f0`c00e7da0 0x000000ec`95ff36e8
0e 000000f1`1b932a10 000000ec`961490a8 0x000000f0`c00e7da0
0f 000000f1`1b932a18 00007ffa`b123c3c8 0x000000ec`961490a8
10 000000f1`1b932a20 00000000`00000000 mscorlib_ni+0x4cc3c8

Currently investigating.

DavidObando commented 8 years ago

The output of !mk is a bit better:

           SP               IP
00:U 000000f11b932218 00007ffad5b80c6a ntdll!ZwWaitForMultipleObjects+0xa [o:\blue.obj.amd64fre\minkernel\ntdll\daytona\objfre\amd64\usrstubs.asm @ 894]
01:U 000000f11b932220 00007ffad2d613ed KERNELBASE!WaitForMultipleObjectsEx+0xe1 [d:\blue\minkernel\kernelbase\synch.c @ 1471]
02:U 000000f11b932500 00007ffab18139b3 coreclr!Thread::DoAppropriateWaitWorker+0x21b [f:\dd\ndp\clr\src\vm\threads.cpp @ 4452]
03:U 000000f11b9325b0 00007ffab1813765 coreclr!Thread::DoAppropriateWait+0x7d [f:\dd\ndp\clr\src\vm\threads.cpp @ 4119]
04:U 000000f11b932630 00007ffab182db0b coreclr!CLREventBase::WaitEx+0x57 [f:\dd\ndp\clr\src\vm\synch.cpp @ 754]
05:U 000000f11b932680 00007ffab18d44fa coreclr!AwareLock::EnterEpilogHelper+0xca [f:\dd\ndp\clr\src\vm\syncblk.cpp @ 3118]
06:U 000000f11b932740 00007ffab18d440a coreclr!AwareLock::EnterEpilog+0x62 [f:\dd\ndp\clr\src\vm\syncblk.cpp @ 3063]
07:U 000000f11b9327a0 00007ffab18d48cf coreclr!AwareLock::Contention+0x273 [f:\dd\ndp\clr\src\vm\syncblk.cpp @ 3413]
08:U 000000f11b932860 00007ffab18ceae9 coreclr!JITutil_MonContention+0xb1 [f:\dd\ndp\clr\src\vm\jithelpers.cpp @ 5195]
09:M 000000f11b932a00 00007ffa525fce32 *** ERROR: Module load completed but symbols could not be loaded for Microsoft.Extensions.Logging.Console.dll
Microsoft.Extensions.Logging.Console.ConsoleLogger.WriteMessage(Microsoft.Extensions.Logging.LogLevel, System.String, Int32, System.String)(+0xa2 Native)
0a:U 000000f11b932a08 000000ec95ff36e8 CLRStub@000000ec95ff36e8
0b:U 000000f11b932a10 000000f0c00e7da0 CLRStub@000000f0c00e7da0
0c:U 000000f11b932a18 000000ec961490a8 CLRStub@000000ec961490a8
0d:M 000000f11b932a20 00007ffab123c3c8 System.String.FormatHelper(System.IFormatProvider, System.String, System.ParamsArray)(+0x0 IL,+0x78 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\String.cs @ 3098,13]
0e:M 000000f11b932b10 00007ffa525fcab6 Microsoft.Extensions.Logging.Console.ConsoleLogger.Log[[System.__Canon, mscorlib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>)(+0x41 IL,+0x86 Native)
0f:M 000000f11b932c30 00007ffa525fc935 *** ERROR: Module load completed but symbols could not be loaded for Microsoft.Extensions.Logging.dll
Microsoft.Extensions.Logging.Logger.Log[[System.__Canon, mscorlib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>)(+0x1a IL,+0xd5 Native)
10:M 000000f11b932d80 00007ffa53d8b867 *** ERROR: Module load completed but symbols could not be loaded for Microsoft.EntityFrameworkCore.dll
Microsoft.EntityFrameworkCore.Internal.InterceptingLogger`1[[System.__Canon, mscorlib]].Log[[System.__Canon, mscorlib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__C(+0x0 IL,+0x77 Native)
11:M 000000f11b932ea0 00007ffa53d8b7c7 Microsoft.EntityFrameworkCore.Infrastructure.SensitiveDataLogger`1[[System.__Canon, mscorlib]].Microsoft.Extensions.Logging.ILogger.Log[[System.__Canon, mscorlib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon(+0x0 IL,+0x77 Native)
12:M 000000f11b932fc0 00007ffa53d8b6a4 Microsoft.EntityFrameworkCore.Internal.CoreLoggerExtensions.LogError[[System.__Canon, mscorlib]](Microsoft.Extensions.Logging.ILogger, Microsoft.EntityFrameworkCore.Infrastructure.CoreLoggingEventId, System.Func`1<System.__Canon>, System.Exception, System(+0x0 IL,+0x134 Native)
13:M 000000f11b933050 00007ffa528698d7 Microsoft.EntityFrameworkCore.Query.Internal.AsyncLinqOperatorProvider+ExceptionInterceptor`1+EnumeratorExceptionInterceptor+<MoveNext>d__5[[System.__Canon, mscorlib]].MoveNext()(+0x16e IL,+0x3f7 Native)
14:M 000000f11b9352d0 00007ffab16b97e8 System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(System.Threading.Tasks.Task)(+0x0 IL,+0x3889d8 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Runtime\CompilerServices\TaskAwaiter.cs @ 163,13]
15:M 000000f11b935310 00007ffab1330e05 System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task)(+0x0 IL,+0x45 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Runtime\CompilerServices\TaskAwaiter.cs @ 143,13]
16:M 000000f11b935340 00007ffa5286976d Microsoft.EntityFrameworkCore.Query.Internal.AsyncLinqOperatorProvider+ExceptionInterceptor`1+EnumeratorExceptionInterceptor+<MoveNext>d__5[[System.__Canon, mscorlib]].MoveNext()(+0x112 IL,+0x28d Native)
17:M 000000f11b9353d0 00007ffab12f1903 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)(+0x15 IL,+0x83 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\ExecutionContext.cs @ 93,17]
18:M 000000f11b935440 00007ffab135a5c1 System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run()(+0x24 IL,+0x91 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs @ 1071,25]
19:M 000000f11b935490 00007ffab13205f2 System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action, Boolean, System.Threading.Tasks.Task ByRef)(+0x1c IL,+0x62 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\TaskContinuation.cs @ 807,17]
1a:M 000000f11b9354e0 00007ffab12e2a75 System.Threading.Tasks.Task.FinishContinuations()(+0x94 IL,+0x175 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 3612,21]
1b:M 000000f11b935580 00007ffab12e0cd6 System.Threading.Tasks.Task.Finish(Boolean)(+0x26 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 2256,9]
1c:M 000000f11b9355e0 00007ffab148ec64 System.Threading.Tasks.Task`1[[System.Boolean, mscorlib]].TrySetException(System.Object)(+0x2a IL,+0x54 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\future.cs @ 602,17]
1d:M 000000f11b935620 00007ffab135b323 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Boolean, mscorlib]].SetException(System.Exception)(+0x26 IL,+0x43 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs @ 663,13]
1e:M 000000f11b935660 00007ffa53a5031a Microsoft.EntityFrameworkCore.Query.Internal.TaskResultAsyncEnumerable`1+Enumerator+<MoveNext>d__3[[System.__Canon, mscorlib]].MoveNext()(+0xb2 IL,+0x1ca Native)
1f:M 000000f11b937930 00007ffa53a50297 Microsoft.EntityFrameworkCore.Query.Internal.TaskResultAsyncEnumerable`1+Enumerator+<MoveNext>d__3[[System.__Canon, mscorlib]].MoveNext()(+0x147 Native)
20:M 000000f11b937ba0 00007ffab1325403 System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].TrySetException(System.Object)(+0x2a IL,+0x73 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\future.cs @ 602,17]
21:M 000000f11b937bf0 00007ffab13fbdd8 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.__Canon, mscorlib]].SetException(System.Exception)(+0x29 IL,+0x48 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs @ 663,13]
22:M 000000f11b937c30 00007ffa53a4dad0 Microsoft.EntityFrameworkCore.Query.Internal.AsyncLinqOperatorProvider+<_FirstOrDefault>d__75`1[[System.__Canon, mscorlib]].MoveNext()(+0xd1 IL,+0x2e0 Native)
23:M 000000f11b939f00 00007ffa53a4d94a Microsoft.EntityFrameworkCore.Query.Internal.AsyncLinqOperatorProvider+<_FirstOrDefault>d__75`1[[System.__Canon, mscorlib]].MoveNext()(+0x7e IL,+0x15a Native)
24:M 000000f11b93a200 00007ffa5286a9bc *** ERROR: Module load completed but symbols could not be loaded for Microsoft.EntityFrameworkCore.Relational.dll
Microsoft.EntityFrameworkCore.Query.Internal.AsyncQueryingEnumerable+AsyncEnumerator+<MoveNext>d__8.MoveNext()(+0x45b IL,+0x7dc Native)
25:M 000000f11b93c4d0 00007ffa5286a42d Microsoft.EntityFrameworkCore.Query.Internal.AsyncQueryingEnumerable+AsyncEnumerator+<MoveNext>d__8.MoveNext()(+0x159 IL,+0x24d Native)
26:M 000000f11b93c770 00007ffab13591d4 System.Threading.Tasks.Task`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].TrySetException(System.Object)(+0x2a IL,+0x54 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\future.cs @ 602,17]
27:M 000000f11b93c7b0 00007ffab132f423 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].SetException(System.Exception)(+0x26 IL,+0x43 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs @ 663,13]
28:M 000000f11b93c7f0 00007ffa524f5d2f Microsoft.EntityFrameworkCore.Storage.RelationalConnection+<OpenAsync>d__32.MoveNext()(+0x146 IL,+0x2df Native)
29:M 000000f11b93ead0 00007ffa524f5c85 Microsoft.EntityFrameworkCore.Storage.RelationalConnection+<OpenAsync>d__32.MoveNext()(+0x10f IL,+0x235 Native)
2a:M 000000f11b93eda0 00007ffab144794d System.Threading.Tasks.TaskCompletionSource`1[[System.__Canon, mscorlib]].TrySetException(System.Exception)(+0xe IL,+0x1d Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\TaskCompletionSource.cs @ 161,13]
2b:M 000000f11b93ede0 00007ffab1447bc3 System.Threading.Tasks.TaskCompletionSource`1[[System.__Canon, mscorlib]].SetException(System.Exception)(+0xe IL,+0x13 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\TaskCompletionSource.cs @ 243,13]
2c:M 000000f11b93ee10 00007ffa525d820e System.Data.SqlClient.SqlConnection+OpenAsyncRetry.Retry(System.Threading.Tasks.Task`1<System.Data.ProviderBase.DbConnectionInternal>)(+0x49 IL,+0xae Native) [f:\dd\ndp\fxcore\Open\src\System.Data.SqlClient\src\System\Data\SqlClient\SqlConnection.cs @ 854,29]
2d:M 000000f11b93ee80 00007ffab12e1357 System.Threading.Tasks.Task.Execute()(+0x10 IL,+0x47 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 2491,21]
2e:M 000000f11b93ef30 00007ffab12e18eb System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)(+0xd6 IL,+0x23b Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 2813,21]
2f:M 000000f11b93efe0 00007ffab12e166a System.Threading.Tasks.Task.ExecuteEntry(Boolean)(+0x58 IL,+0x9a Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 2749,17]
30:M 000000f11b93f020 00007ffab1357627 System.Threading.ThreadPoolWorkQueue.Dispatch()(+0xa4 IL,+0x1c7 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\ThreadPool.cs @ 815,29]
31:U 000000f11b93f0c0 00007ffab1bb2503 coreclr!CallDescrWorkerInternal+0x83 [f:\dd\ndp\clr\src\vm\amd64\CallDescrWorkerAMD64.asm @ 101]
32:U 000000f11b93f100 00007ffab185b907 coreclr!MethodDescCallSite::CallTargetWorker+0x20f [f:\dd\ndp\clr\src\vm\callhelpers.cpp @ 653]
33:U 000000f11b93f210 00007ffab19abc96 coreclr!QueueUserWorkItemManagedCallback+0x2a [f:\dd\ndp\clr\src\vm\comthreadpool.cpp @ 510]
34:U 000000f11b93f300 00007ffab1817921 coreclr!ManagedThreadBase_DispatchMiddle+0x89 [f:\dd\ndp\clr\src\vm\threads.cpp @ 10144]
35:U 000000f11b93f460 00007ffab1817c6c coreclr!ManagedThreadBase_DispatchOuter+0xb4 [f:\dd\ndp\clr\src\vm\threads.cpp @ 10399]
36:U 000000f11b93f510 00007ffab1817d06 coreclr!ManagedThreadBase::ThreadPool+0x32 [f:\dd\ndp\clr\src\vm\threads.cpp @ 10505]
37:U 000000f11b93f570 00007ffab193be50 coreclr!ManagedPerAppDomainTPCount::DispatchWorkItem+0xe4 [f:\dd\ndp\clr\src\vm\threadpoolrequest.cpp @ 760]
38:U 000000f11b93f6c0 00007ffab193523a coreclr!ThreadpoolMgr::ExecuteWorkRequest+0x13a [f:\dd\ndp\clr\src\vm\win32threadpool.cpp @ 1891]
39:U 000000f11b93f710 00007ffab1935d25 coreclr!ThreadpoolMgr::WorkerThreadStart+0x4cd [f:\dd\ndp\clr\src\vm\win32threadpool.cpp @ 2361]
3a:U 000000f11b93f7b0 00007ffab181243c coreclr!Thread::intermediateThreadProc+0x80 [f:\dd\ndp\clr\src\vm\threads.cpp @ 2859]
3b:U 000000f11b93f7f0 00007ffad33d13d2 kernel32!BaseThreadInitThunk+0x22 [d:\9147\base\win32\client\thread.c @ 78]
3c:U 000000f11b93f820 00007ffad5b054e4 ntdll!RtlUserThreadStart+0x34 [d:\blue\minkernel\ntdll\rtlstrt.c @ 1026]
DavidObando commented 8 years ago

The threads appear to be waiting on this lock.

DavidObando commented 8 years ago 
0:10940> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner
  206 000000ecb18a8d18        21853         1 000000eeda9536b0 178046305   000000ec96031050 System.Object
-----------------------------
Total           14516
CCW             1
RCW             1
ComClassFactory 0
Free            14016

Shows we only have one active lock. It points to thread 6305.

0:6305> !mk
Thread 6305:
           SP               IP
00:U 000000ef38271a58 00007ffad5b806fa ntdll!ZwWaitForSingleObject+0xa [o:\blue.obj.amd64fre\minkernel\ntdll\daytona\objfre\amd64\usrstubs.asm @ 198]
01:U 000000ef38271a60 00007ffad2d61118 KERNELBASE!WaitForSingleObjectEx+0x94 [d:\blue\minkernel\kernelbase\synch.c @ 1301]
02:U 000000ef38271b00 00007ffab182da5f coreclr!CLREventWaitHelper2+0x13 [f:\dd\ndp\clr\src\vm\synch.cpp @ 631]
03:U 000000ef38271b40 00007ffab182da87 coreclr!CLREventWaitHelper+0x1f [f:\dd\ndp\clr\src\vm\synch.cpp @ 657]
04:U 000000ef38271ba0 00007ffab182db1a coreclr!CLREventBase::WaitEx+0x66 [f:\dd\ndp\clr\src\vm\synch.cpp @ 761]
05:U 000000ef38271bf0 00007ffab18093ee coreclr!Thread::RareDisablePreemptiveGC+0x182 [f:\dd\ndp\clr\src\vm\threadsuspend.cpp @ 3356]
06:U 000000ef38271c30 00007ffab1809b73 coreclr!Thread::PulseGCMode+0x43 [f:\dd\ndp\clr\src\vm\threadsuspend.cpp @ 3873]
07:U 000000ef38271c60 00007ffab1815d31 coreclr!CommonTripThread+0x3d [f:\dd\ndp\clr\src\vm\threads.cpp @ 8285]
08:U 000000ef38271c90 00007ffab198874f coreclr!FC_GCPoll+0x97 [f:\dd\ndp\clr\src\vm\fcall.cpp @ 139]
09:U 000000ef38271de0 00007ffab1b8c89c coreclr!ArrayNative::ArrayCopy+0x4e4 [f:\dd\ndp\clr\src\classlibnative\bcltype\arraynative.cpp @ 1071]
0a:M 000000ef38271fb0 00007ffab125d4c3 System.Array.Copy(System.Array, System.Array, Int32)(+0x53 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Array.cs @ 282,9]
0b:M 000000ef38272010 00007ffab124246e System.Text.StringBuilder.set_Length(Int32)(+0x9b IL,+0xae Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Text\StringBuilder.cs @ 501,25]
0c:M 000000ef38272060 00007ffab1241d98 System.Text.StringBuilderCache.Acquire(Int32)(+0x27 IL,+0x48 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Text\StringBuilderCache.cs @ 61,25]
0d:M 000000ef382720a0 00007ffab123c38f System.String.FormatHelper(System.IFormatProvider, System.String, System.ParamsArray)(+0x0 IL,+0x3f Native) [f:\dd\ndp\clr\src\mscorlib\src\System\String.cs @ 3098,13]
0e:M 000000ef38272100 00007ffa525fcf5b Microsoft.Extensions.Logging.Console.ConsoleLogger.WriteMessage(Microsoft.Extensions.Logging.LogLevel, System.String, Int32, System.String)(+0x1cb Native)
0f:U 000000ef38272108 00007ffab1621830 mscorlib_ni+0x8b1830
10:U 000000ef38272110 000000ec961490a8 CLRStub@000000ec961490a8
11:U 000000ef38272118 000000ec961491b8 CLRStub@000000ec961491b8
12:U 000000ef38272120 000000ec96031108 CLRStub@000000ec96031108
13:U 000000ef38272128 000000ef38272100 CLRStub@000000ef38272100
14:U 000000ef38272130 0000000000001fa0 CLRStub@0000000000001fa0
15:U 000000ef38272138 000000ec96031050 CLRStub@000000ec96031050
16:U 000000ef38272140 000000f0c0103960 CLRStub@000000f0c0103960
17:M 000000ef38272210 00007ffa525fcab6 Microsoft.Extensions.Logging.Console.ConsoleLogger.Log[[System.__Canon, mscorlib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>)(+0x41 IL,+0x86 Native)
18:M 000000ef38272330 00007ffa525fc935 Microsoft.Extensions.Logging.Logger.Log[[System.__Canon, mscorlib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__Canon,System.Exception,System.String>)(+0x1a IL,+0xd5 Native)
19:M 000000ef38272480 00007ffa53d8b867 Microsoft.EntityFrameworkCore.Internal.InterceptingLogger`1[[System.__Canon, mscorlib]].Log[[System.__Canon, mscorlib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon, System.Exception, System.Func`3<System.__C(+0x0 IL,+0x77 Native)
1a:M 000000ef382725a0 00007ffa53d8b7c7 Microsoft.EntityFrameworkCore.Infrastructure.SensitiveDataLogger`1[[System.__Canon, mscorlib]].Microsoft.Extensions.Logging.ILogger.Log[[System.__Canon, mscorlib]](Microsoft.Extensions.Logging.LogLevel, Microsoft.Extensions.Logging.EventId, System.__Canon(+0x0 IL,+0x77 Native)
1b:M 000000ef382726c0 00007ffa53d8b6a4 Microsoft.EntityFrameworkCore.Internal.CoreLoggerExtensions.LogError[[System.__Canon, mscorlib]](Microsoft.Extensions.Logging.ILogger, Microsoft.EntityFrameworkCore.Infrastructure.CoreLoggingEventId, System.Func`1<System.__Canon>, System.Exception, System(+0x0 IL,+0x134 Native)
1c:M 000000ef38272750 00007ffa528698d7 Microsoft.EntityFrameworkCore.Query.Internal.AsyncLinqOperatorProvider+ExceptionInterceptor`1+EnumeratorExceptionInterceptor+<MoveNext>d__5[[System.__Canon, mscorlib]].MoveNext()(+0x16e IL,+0x3f7 Native)
1d:M 000000ef382749d0 00007ffab16b97e8 System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(System.Threading.Tasks.Task)(+0x0 IL,+0x3889d8 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Runtime\CompilerServices\TaskAwaiter.cs @ 163,13]
1e:M 000000ef38274a10 00007ffab1330e05 System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task)(+0x0 IL,+0x45 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Runtime\CompilerServices\TaskAwaiter.cs @ 143,13]
1f:M 000000ef38274a40 00007ffa5286976d Microsoft.EntityFrameworkCore.Query.Internal.AsyncLinqOperatorProvider+ExceptionInterceptor`1+EnumeratorExceptionInterceptor+<MoveNext>d__5[[System.__Canon, mscorlib]].MoveNext()(+0x112 IL,+0x28d Native)
20:M 000000ef38274ad0 00007ffab12f1903 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)(+0x15 IL,+0x83 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\ExecutionContext.cs @ 93,17]
21:M 000000ef38274b40 00007ffab135a5c1 System.Runtime.CompilerServices.AsyncMethodBuilderCore+MoveNextRunner.Run()(+0x24 IL,+0x91 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs @ 1071,25]
22:M 000000ef38274b90 00007ffab13205f2 System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Action, Boolean, System.Threading.Tasks.Task ByRef)(+0x1c IL,+0x62 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\TaskContinuation.cs @ 807,17]
23:M 000000ef38274be0 00007ffab12e2a75 System.Threading.Tasks.Task.FinishContinuations()(+0x94 IL,+0x175 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 3612,21]
24:M 000000ef38274c80 00007ffab12e0cd6 System.Threading.Tasks.Task.Finish(Boolean)(+0x26 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 2256,9]
25:M 000000ef38274ce0 00007ffab148ec64 System.Threading.Tasks.Task`1[[System.Boolean, mscorlib]].TrySetException(System.Object)(+0x2a IL,+0x54 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\future.cs @ 602,17]
26:M 000000ef38274d20 00007ffab135b323 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Boolean, mscorlib]].SetException(System.Exception)(+0x26 IL,+0x43 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs @ 663,13]
27:M 000000ef38274d60 00007ffa53a5031a Microsoft.EntityFrameworkCore.Query.Internal.TaskResultAsyncEnumerable`1+Enumerator+<MoveNext>d__3[[System.__Canon, mscorlib]].MoveNext()(+0xb2 IL,+0x1ca Native)
28:M 000000ef38277030 00007ffa53a50297 Microsoft.EntityFrameworkCore.Query.Internal.TaskResultAsyncEnumerable`1+Enumerator+<MoveNext>d__3[[System.__Canon, mscorlib]].MoveNext()(+0x147 Native)
29:M 000000ef382772a0 00007ffab1325403 System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].TrySetException(System.Object)(+0x2a IL,+0x73 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\future.cs @ 602,17]
2a:M 000000ef382772f0 00007ffab13fbdd8 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.__Canon, mscorlib]].SetException(System.Exception)(+0x29 IL,+0x48 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs @ 663,13]
2b:M 000000ef38277330 00007ffa53a4dad0 Microsoft.EntityFrameworkCore.Query.Internal.AsyncLinqOperatorProvider+<_FirstOrDefault>d__75`1[[System.__Canon, mscorlib]].MoveNext()(+0xd1 IL,+0x2e0 Native)
2c:M 000000ef38279600 00007ffa53a4d94a Microsoft.EntityFrameworkCore.Query.Internal.AsyncLinqOperatorProvider+<_FirstOrDefault>d__75`1[[System.__Canon, mscorlib]].MoveNext()(+0x7e IL,+0x15a Native)
2d:M 000000ef38279900 00007ffa5286a9bc Microsoft.EntityFrameworkCore.Query.Internal.AsyncQueryingEnumerable+AsyncEnumerator+<MoveNext>d__8.MoveNext()(+0x45b IL,+0x7dc Native)
2e:M 000000ef3827bbd0 00007ffa5286a42d Microsoft.EntityFrameworkCore.Query.Internal.AsyncQueryingEnumerable+AsyncEnumerator+<MoveNext>d__8.MoveNext()(+0x159 IL,+0x24d Native)
2f:M 000000ef3827be70 00007ffab13591d4 System.Threading.Tasks.Task`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].TrySetException(System.Object)(+0x2a IL,+0x54 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\future.cs @ 602,17]
30:M 000000ef3827beb0 00007ffab132f423 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.Threading.Tasks.VoidTaskResult, mscorlib]].SetException(System.Exception)(+0x26 IL,+0x43 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs @ 663,13]
31:M 000000ef3827bef0 00007ffa524f5d2f Microsoft.EntityFrameworkCore.Storage.RelationalConnection+<OpenAsync>d__32.MoveNext()(+0x146 IL,+0x2df Native)
32:M 000000ef3827e1d0 00007ffa524f5c85 Microsoft.EntityFrameworkCore.Storage.RelationalConnection+<OpenAsync>d__32.MoveNext()(+0x10f IL,+0x235 Native)
33:M 000000ef3827e4a0 00007ffab144794d System.Threading.Tasks.TaskCompletionSource`1[[System.__Canon, mscorlib]].TrySetException(System.Exception)(+0xe IL,+0x1d Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\TaskCompletionSource.cs @ 161,13]
34:M 000000ef3827e4e0 00007ffab1447bc3 System.Threading.Tasks.TaskCompletionSource`1[[System.__Canon, mscorlib]].SetException(System.Exception)(+0xe IL,+0x13 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\TaskCompletionSource.cs @ 243,13]
35:M 000000ef3827e510 00007ffa525d820e System.Data.SqlClient.SqlConnection+OpenAsyncRetry.Retry(System.Threading.Tasks.Task`1<System.Data.ProviderBase.DbConnectionInternal>)(+0x49 IL,+0xae Native) [f:\dd\ndp\fxcore\Open\src\System.Data.SqlClient\src\System\Data\SqlClient\SqlConnection.cs @ 854,29]
36:M 000000ef3827e580 00007ffab12e1357 System.Threading.Tasks.Task.Execute()(+0x10 IL,+0x47 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 2491,21]
37:M 000000ef3827e630 00007ffab12e18eb System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)(+0xd6 IL,+0x23b Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 2813,21]
38:M 000000ef3827e6e0 00007ffab12e166a System.Threading.Tasks.Task.ExecuteEntry(Boolean)(+0x58 IL,+0x9a Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\Tasks\Task.cs @ 2749,17]
39:M 000000ef3827e720 00007ffab1357627 System.Threading.ThreadPoolWorkQueue.Dispatch()(+0xa4 IL,+0x1c7 Native) [f:\dd\ndp\clr\src\mscorlib\src\System\Threading\ThreadPool.cs @ 815,29]
3a:U 000000ef3827e7c0 00007ffab1bb2503 coreclr!CallDescrWorkerInternal+0x83 [f:\dd\ndp\clr\src\vm\amd64\CallDescrWorkerAMD64.asm @ 101]
3b:U 000000ef3827e800 00007ffab185b907 coreclr!MethodDescCallSite::CallTargetWorker+0x20f [f:\dd\ndp\clr\src\vm\callhelpers.cpp @ 653]
3c:U 000000ef3827e910 00007ffab19abc96 coreclr!QueueUserWorkItemManagedCallback+0x2a [f:\dd\ndp\clr\src\vm\comthreadpool.cpp @ 510]
3d:U 000000ef3827ea00 00007ffab1817921 coreclr!ManagedThreadBase_DispatchMiddle+0x89 [f:\dd\ndp\clr\src\vm\threads.cpp @ 10144]
3e:U 000000ef3827eb60 00007ffab1817c6c coreclr!ManagedThreadBase_DispatchOuter+0xb4 [f:\dd\ndp\clr\src\vm\threads.cpp @ 10399]
3f:U 000000ef3827ec10 00007ffab1817d06 coreclr!ManagedThreadBase::ThreadPool+0x32 [f:\dd\ndp\clr\src\vm\threads.cpp @ 10505]
40:U 000000ef3827ec70 00007ffab193be50 coreclr!ManagedPerAppDomainTPCount::DispatchWorkItem+0xe4 [f:\dd\ndp\clr\src\vm\threadpoolrequest.cpp @ 760]
41:U 000000ef3827edc0 00007ffab193523a coreclr!ThreadpoolMgr::ExecuteWorkRequest+0x13a [f:\dd\ndp\clr\src\vm\win32threadpool.cpp @ 1891]
42:U 000000ef3827ee10 00007ffab1935d25 coreclr!ThreadpoolMgr::WorkerThreadStart+0x4cd [f:\dd\ndp\clr\src\vm\win32threadpool.cpp @ 2361]
43:U 000000ef3827eeb0 00007ffab181243c coreclr!Thread::intermediateThreadProc+0x80 [f:\dd\ndp\clr\src\vm\threads.cpp @ 2859]
44:U 000000ef3827fd70 00007ffad33d13d2 kernel32!BaseThreadInitThunk+0x22 [d:\9147\base\win32\client\thread.c @ 78]
45:U 000000ef3827fda0 00007ffad5b054e4 ntdll!RtlUserThreadStart+0x34 [d:\blue\minkernel\ntdll\rtlstrt.c @ 1026]

Does anyone here speak CLR?

I'm curious to know if this shows up with servergc too, this dump is using workstationgc.

0:6305> !eeversion
4.6.24027.0 free
Workstation mode
In plan phase of garbage collection
SOS Version: 4.6.24027.0 retail build
DavidObando commented 8 years ago

@sivagms you told me the application wasn't processing requests when the dump was taken, correct? Can I assume it was just sitting there waiting for work?

sivagms commented 8 years ago

no, all the requests were failing

rynowak commented 8 years ago

It seems like we're doing a lot of work inside that lock.

If we remove the console logger does the issue go away? That seems likely, but I'd think we still want to fix this.

rynowak commented 8 years ago

/cc @Eilon @DamianEdwards - if console logger is the problem do we care about this for RC2?

DamianEdwards commented 8 years ago

It's on by default in our templates, we'll need to so something

kichalla commented 8 years ago

Is the idea to enable Console/Debug logging only for development scenarios in the templates? (as they are for development only scenarios?)

Eilon commented 8 years ago

We use ConsoleLogger in production for Azure streaming logs scenarios, no? Or don't we?

kichalla commented 8 years ago

We use ConsoleLogger in production for Azure streaming logs scenarios, no? Or don't we?

I didn't have any idea that Azure streaming logs work this way. Its seems like a bigger issue. (I was under the assumption that ConsoleLogger is for development scenarios as there is all this logic of having different colors etc. causing us to introduce lock)

DamianEdwards commented 8 years ago

Perhaps we need some config options for the console logger to enable the sync-lock or the colors or both, then we can use the environment name to determine whether the colors and lock are enabled or not. I'm hesitant to suggest we attempt to make the console logger log asynchronously as that would shoot the complexity up dramatically and open up a big box of design decisions to make.

rynowak commented 8 years ago

The locking has more to do with writing each log message along with it's scope/event-name/id information in one 'chunk' and not allowing them to interleave. Removing support for colors would make this simpler but wouldn't really fix the problem on its own.

This code was not written in a performance sensitive way - like most code we write - until we find evidence that it's important to do so. We should make the obvious fixes here before adding any dials and switches. That entails reducing allocations by going through Console.Out (which is a TextWriter) and making sure all state is computed outside of the lock.

DamianEdwards commented 8 years ago

Agreed. That said, I have a sneaking feeling that any global lock in this code path will result in bad behavior in stress runs, no matter how much we optimize the logger.

rynowak commented 8 years ago

Agreed. That said, I have a sneaking feeling that any global lock in this code path will result in bad behavior in stress runs, no matter how much we optimize the logger.

https://github.com/dotnet/corefx/blob/master/src/System.Console/src/System/Console.cs#L143

:trollface: Console is always surrounded with a global lock - we can try to make it so that it's not the first bottleneck you hit, but eventually your server will hit a bottleneck. I think we're saying the same thing

DamianEdwards commented 8 years ago

Ya. Here be dragons. We may need to step up our development of guidance and/or solutions for logging in Azure, etc. that don't require using the console logger so we can relegate to a dev-only scenario.

sivagms commented 8 years ago

FYI, for the same load the memory issue doesn't show up with ServerGC. the process uses just about 150MB memory.

DavidObando commented 8 years ago

Resolved with aspnet/Logging@00aed0a.