Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

BinderTracingTest.Basic timeout #45660

Closed
jkotas opened this issue Dec 6, 2020 · 6 comments · Fixed by #45666
Closed

BinderTracingTest.Basic timeout #45660

jkotas opened this issue Dec 6, 2020 · 6 comments · Fixed by #45666
Assignees
@sywhang
Labels
area-Tracing-coreclr blocking-clean-ci Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'

Comments

@jkotas
Copy link
Member

jkotas commented Dec 6, 2020 

BEGIN EXECUTION
 "C:\h\w\B29209EB\p\corerun.exe" BinderTracingTest.Basic.dll 
[7:25:56 PM] Running LoadFile...
[7:25:57 PM] Running LoadBytes...
[7:25:58 PM] Running LoadFromStream...
[7:25:58 PM] Running LoadFromAssemblyPath...
[7:25:59 PM] Launching process for LoadFromAssemblyName...
[7:26:00 PM] Running LoadFromAssemblyName...

[7:26:01 PM] Launching process for LoadFrom...
[7:26:02 PM] Running LoadFrom...

[7:26:03 PM] Launching process for PlatformAssembly...
[7:26:05 PM] Running PlatformAssembly...

[7:26:06 PM] Launching process for PlatformAssembly_Cached...
[7:26:07 PM] Running PlatformAssembly_Cached...

[7:26:08 PM] Launching process for Reflection...
[7:26:09 PM] Running Reflection...

[7:26:10 PM] Launching process for Reflection_Cached...
[7:26:11 PM] Running Reflection_Cached...

[7:26:12 PM] Launching process for Reflection_CustomALC...
[7:26:13 PM] Running Reflection_CustomALC...

cmdLine:C:\h\w\B29209EB\w\AFD70968\e\Loader\binding\tracing\BinderTracingTest.Basic\BinderTracingTest.Basic.cmd Timed Out (timeout in milliseconds: 600000 from variable __TestTimeout, start: 12/6/2020 7:25:55 PM, end: 12/6/2020 7:35:55 PM)
@Dotnet-GitSync-Bot Dotnet-GitSync-Bot added the untriaged New issue has not been triaged by the area owner label Dec 6, 2020
@Dotnet-GitSync-Bot
Copy link
Collaborator

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

@jkotas
Copy link
Member Author

jkotas commented Dec 6, 2020

Failed in #45652

@jkotas
Copy link
Member Author

jkotas commented Dec 6, 2020

@hoyosjs @sywhang This seems to be still timing out even after the fix for #37132

@jkotas jkotas added area-Tracing-coreclr blocking-clean-ci Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms' labels Dec 6, 2020
@jkotas jkotas mentioned this issue Dec 6, 2020
Merged
@sywhang sywhang self-assigned this Dec 7, 2020
@sywhang sywhang removed the untriaged New issue has not been triaged by the area owner label Dec 7, 2020
@sywhang
Copy link
Contributor

sywhang commented Dec 7, 2020

Taking a look now. Thanks

@hoyosjs
Copy link
Member

hoyosjs commented Dec 7, 2020

@sywhang seems to be the deadlock case:

   5  Id: 1b58.ed0 Suspend: 0 Teb: 000000ce`4307e000 Unfrozen
 # Child-SP          RetAddr               Call Site
00 000000ce`43dfbe18 00007ffb`a7a38a3f     ntdll!NtWaitForMultipleObjects+0x14
01 000000ce`43dfbe20 00007ffb`7da6b32e     KERNELBASE!WaitForMultipleObjectsEx+0xef
02 000000ce`43dfc120 00007ffb`7da6b838     coreclr!Thread::DoAppropriateAptStateWait+0x10e [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.cpp @ 3311] 
03 000000ce`43dfc1f0 00007ffb`7da7486c     coreclr!Thread::DoAppropriateWaitWorker+0x370 [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.cpp @ 3443] 
04 000000ce`43dfc460 00007ffb`7da6b436     coreclr!`Thread::DoAppropriateWait'::`11'::__Body::Run+0x94 [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.cpp @ 3160] 
05 000000ce`43dfc4c0 00007ffb`7dd06ead     coreclr!Thread::DoAppropriateWait+0xb6 [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.cpp @ 3162] 
06 000000ce`43dfc540 00007ffb`7da5ce0f     coreclr!CLREventBase::WaitEx+0x2b9 [F:\workspace\_work\1\s\src\coreclr\src\vm\synch.cpp @ 466] 
07 000000ce`43dfc680 00007ffb`7da5cb89     coreclr!AwareLock::EnterEpilogHelper+0x267 [F:\workspace\_work\1\s\src\coreclr\src\vm\syncblk.cpp @ 2620] 
08 000000ce`43dfc780 00007ffb`7da5caeb     coreclr!AwareLock::EnterEpilog+0x4d [F:\workspace\_work\1\s\src\coreclr\src\vm\syncblk.cpp @ 2501] 
09 000000ce`43dfc7d0 00007ffb`7dbf772b     coreclr!AwareLock::Enter+0x20f [F:\workspace\_work\1\s\src\coreclr\src\vm\syncblk.cpp @ 2403] 
0a (Inline Function) --------`--------     coreclr!Object::EnterObjMonitor+0x9 [F:\workspace\_work\1\s\src\coreclr\src\vm\object.h @ 277] 
0b 000000ce`43dfc8c0 00007ffb`7dbfdf40     coreclr!JIT_MonEnter_Helper+0x157 [F:\workspace\_work\1\s\src\coreclr\src\vm\jithelpers.cpp @ 3665] 
0c 000000ce`43dfcae0 00007ffb`7c98c931     coreclr!JIT_MonReliableEnter_Portable+0x560 [F:\workspace\_work\1\s\src\coreclr\src\vm\jithelpers.cpp @ 3713] 
0d 000000ce`43dfcd20 00007ffb`7c888275     System_Private_CoreLib!System.Diagnostics.Tracing.EventSource.Initialize(System.Guid, System.String, System.String[])+0x201 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 1490] 
0e 000000ce`43dfcdc0 00007ffb`7c889017     System_Private_CoreLib!System.Threading.Tasks.TplEventSource..ctor()+0xd5 [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/TplEventSource.cs @ 51] 
0f 000000ce`43dfce30 00007ffb`7deccf33     System_Private_CoreLib!System.Threading.Tasks.TplEventSource..cctor()+0x17 [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/TplEventSource.cs @ 48] 
10 000000ce`43dfce60 00007ffb`7dada147     coreclr!CallDescrWorkerInternal+0x83
11 000000ce`43dfcea0 00007ffb`7dad9c48     coreclr!`DispatchCallDebuggerWrapper'::`6'::__Body::Run+0x7b [F:\workspace\_work\1\s\src\coreclr\src\vm\callhelpers.cpp @ 160] 
12 000000ce`43dfcef0 00007ffb`7dad9de0     coreclr!DispatchCallDebuggerWrapper+0x20 [F:\workspace\_work\1\s\src\coreclr\src\vm\callhelpers.cpp @ 164] 
13 000000ce`43dfcf50 00007ffb`7d9f6247     coreclr!DispatchCallSimple+0x148 [F:\workspace\_work\1\s\src\coreclr\src\vm\callhelpers.cpp @ 222] 
14 000000ce`43dfd080 00007ffb`7d9e4053     coreclr!MethodTable::RunClassInitEx+0x483 [F:\workspace\_work\1\s\src\coreclr\src\vm\methodtable.cpp @ 3154] 
15 000000ce`43dfd2e0 00007ffb`7d9dfc65     coreclr!MethodTable::DoRunClassInitThrowing+0x3c7 [F:\workspace\_work\1\s\src\coreclr\src\vm\methodtable.cpp @ 3341] 
16 000000ce`43dfded0 00007ffb`7da21ff4     coreclr!MethodTable::CheckRunClassInitThrowing+0x3b5 [F:\workspace\_work\1\s\src\coreclr\src\vm\methodtable.cpp @ 3481] 
17 000000ce`43dfe020 00007ffb`7da28d0b     coreclr!DynamicHelperFixup+0xb2c [F:\workspace\_work\1\s\src\coreclr\src\vm\prestub.cpp @ 3234] 
18 000000ce`43dfe3c0 00007ffb`7dece30a     coreclr!DynamicHelperWorker+0x1ab [F:\workspace\_work\1\s\src\coreclr\src\vm\prestub.cpp @ 3542] 
19 000000ce`43dfe5a0 00007ffb`7c9800ee     coreclr!DelayLoad_Helper+0x7a
1a 000000ce`43dfe660 00007ffb`7c98be7f     System_Private_CoreLib!System.Diagnostics.Tracing.ActivityTracker.OnStart(System.String, System.String, Int32, System.Guid ByRef, System.Guid ByRef, System.Diagnostics.Tracing.EventActivityOptions, Boolean)+0x6e [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/ActivityTracker.cs @ 64] 
1b 000000ce`43dfe710 00007ffb`7c86d905     System_Private_CoreLib!System.Diagnostics.Tracing.EventSource.WriteEventWithRelatedActivityIdCore(Int32, System.Guid*, Int32, EventData*)+0x17f [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 1231] 
1c 000000ce`43dfe840 00007ffb`7c86cce0     System_Private_CoreLib!System.Threading.PortableThreadPoolEventSource.WriteThreadEvent(Int32, UInt32)+0x95 [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPoolEventSource.cs @ 103] 
1d 000000ce`43dfe8c0 00007ffb`7c84dce1     System_Private_CoreLib!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()+0x90 [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.cs @ 42] 
1e 000000ce`43dfe940 00007ffb`7c859dc0     System_Private_CoreLib!System.Threading.ThreadHelper.ThreadStart_Context(System.Object)+0xa1 [/_/src/coreclr/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 49] 
1f 000000ce`43dfe980 00007ffb`7c84de48     System_Private_CoreLib!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+0x80 [/_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs @ 188] 
20 000000ce`43dfe9f0 00007ffb`7deccf33     System_Private_CoreLib!System.Threading.ThreadHelper.ThreadStart()+0x58 [/_/src/coreclr/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 99] 

.  0  Id: 1b58.1b64 Suspend: 0 Teb: 000000ce`4306e000 Unfrozen
 # Child-SP          RetAddr               Call Site
00 000000ce`4337b4c8 00007ffb`ab4b585f     ntdll!NtWaitForAlertByThreadId+0x14
01 000000ce`4337b4d0 00007ffb`ab4b5766     ntdll!RtlpUnWaitCriticalSection+0x5cf
02 000000ce`4337b500 00007ffb`ab4b55f7     ntdll!RtlpUnWaitCriticalSection+0x4d6
03 000000ce`4337b570 00007ffb`ab474c54     ntdll!RtlpUnWaitCriticalSection+0x367
04 000000ce`4337b640 00007ffb`ab474b80     ntdll!RtlEnterCriticalSection+0x114
05 000000ce`4337b670 00007ffb`7d8ca7c3     ntdll!RtlEnterCriticalSection+0x40
06 000000ce`4337b6a0 00007ffb`7d883cb1     coreclr!CrstBase::Enter+0x26b [F:\workspace\_work\1\s\src\coreclr\src\vm\crst.cpp @ 327] 
07 000000ce`4337b710 00007ffb`7d9e3f7c     coreclr!ListLockEntryBase<void *>::FinishDeadlockAwareEnter+0x21 [F:\workspace\_work\1\s\src\coreclr\src\vm\listlock.h @ 209] 
08 (Inline Function) --------`--------     coreclr!ListLockEntryBase<void *>::LockHolder::DeadlockAwareAcquire+0x34 [F:\workspace\_work\1\s\src\coreclr\src\vm\listlock.h @ 234] 
09 000000ce`4337b740 00007ffb`7d9dfc65     coreclr!MethodTable::DoRunClassInitThrowing+0x2f0 [F:\workspace\_work\1\s\src\coreclr\src\vm\methodtable.cpp @ 3316] 
0a 000000ce`4337c330 00007ffb`7da21ff4     coreclr!MethodTable::CheckRunClassInitThrowing+0x3b5 [F:\workspace\_work\1\s\src\coreclr\src\vm\methodtable.cpp @ 3481] 
0b 000000ce`4337c480 00007ffb`7da28d0b     coreclr!DynamicHelperFixup+0xb2c [F:\workspace\_work\1\s\src\coreclr\src\vm\prestub.cpp @ 3234] 
0c 000000ce`4337c820 00007ffb`7dece30a     coreclr!DynamicHelperWorker+0x1ab [F:\workspace\_work\1\s\src\coreclr\src\vm\prestub.cpp @ 3542] 
0d 000000ce`4337ca00 00007ffb`7c87808a     coreclr!DelayLoad_Helper+0x7a
0e 000000ce`4337cac0 00007ffb`7c877901     System_Private_CoreLib!System.Threading.Tasks.Task.ScheduleAndStart(Boolean)+0xea [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 1671] 
0f 000000ce`4337cb20 00007ffb`7c984c57     System_Private_CoreLib!System.Threading.Tasks.Task.InternalStartNew(System.Threading.Tasks.Task, System.Delegate, System.Object, System.Threading.CancellationToken, System.Threading.Tasks.TaskScheduler, System.Threading.Tasks.TaskCreationOptions, System.Threading.Tasks.InternalTaskOptions)+0x71 [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 1148] 
10 000000ce`4337cba0 00007ffb`7c984af1     System_Private_CoreLib!System.Diagnostics.Tracing.EventPipeEventDispatcher.StartDispatchTask()+0x127 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs @ 148] 
11 000000ce`4337cc90 00007ffb`7c9847c6     System_Private_CoreLib!System.Diagnostics.Tracing.EventPipeEventDispatcher.CommitDispatchConfiguration()+0x1e1 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs @ 135] 
12 000000ce`4337cd90 00007ffb`7c994c4c     System_Private_CoreLib!System.Diagnostics.Tracing.EventPipeEventDispatcher.SendCommand(System.Diagnostics.Tracing.EventListener, System.Diagnostics.Tracing.EventCommand, Boolean, System.Diagnostics.Tracing.EventLevel, System.Diagnostics.Tracing.EventKeywords)+0xc6 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs @ 59] 
13 000000ce`4337cdf0 00007ffb`7c994bb1     System_Private_CoreLib!System.Diagnostics.Tracing.EventListener.EnableEvents(System.Diagnostics.Tracing.EventSource, System.Diagnostics.Tracing.EventLevel, System.Diagnostics.Tracing.EventKeywords, System.Collections.Generic.IDictionary`2<System.String,System.String>)+0x8c [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 3881] 
14 000000ce`4337ce70 00007ffb`1e4783ad     System_Private_CoreLib!System.Diagnostics.Tracing.EventListener.EnableEvents(System.Diagnostics.Tracing.EventSource, System.Diagnostics.Tracing.EventLevel, System.Diagnostics.Tracing.EventKeywords)+0x11 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 3853] 
15 000000ce`4337cea0 00000230`d4458728     BinderTracingTest_Basic!Unknown+0x5d
16 000000ce`4337cea8 00000230`d444c008     0x00000230`d4458728
17 000000ce`4337ceb0 00000000`00000005     0x00000230`d444c008
18 000000ce`4337ceb8 00000000`00000004     0x5
19 000000ce`4337cec0 00000230`d444c008     0x4
1a 000000ce`4337cec8 00000230`d444c0c0     0x00000230`d444c008
1b 000000ce`4337ced0 000000ce`4337cf40     0x00000230`d444c0c0
1c 000000ce`4337ced8 00007ffb`7c991ded     0x000000ce`4337cf40
1d 000000ce`4337cee0 00007ffb`7c995a20     System_Private_CoreLib!System.Diagnostics.Tracing.EventSource.AddListener(System.Diagnostics.Tracing.EventListener)+0xcd [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 3318] 
1e 000000ce`4337cf50 00007ffb`7c9958af     System_Private_CoreLib!System.Diagnostics.Tracing.EventListener+<>c.<.ctor>b__10_0(System.Object, System.Diagnostics.Tracing.EventSourceCreatedEventArgs)+0x20 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 3778] 
1f 000000ce`4337cf80 00007ffb`7c994a3f     System_Private_CoreLib!System.Diagnostics.Tracing.EventListener.CallBackForExistingEventSources(Boolean, System.EventHandler`1<System.Diagnostics.Tracing.EventSourceCreatedEventArgs>)+0x19f [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 4212] 
20 000000ce`4337d010 00007ffb`1e477d23     System_Private_CoreLib!System.Diagnostics.Tracing.EventListener..ctor()+0x5f [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 3779] 
21 000000ce`4337d050 00000230`d4458728     BinderTracingTest_Basic!Unknown+0x83

@sywhang
Copy link
Contributor

sywhang commented Dec 7, 2020

@hoyosjs Thanks. I narrowed it down to the check being used in PortableThreadPoolThread being incorrect. I will send out a fix soon.

@sywhang sywhang mentioned this issue Dec 7, 2020
Merged
@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Dec 7, 2020
@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Dec 7, 2020
@ghost ghost locked as resolved and limited conversation to collaborators Jan 6, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@sywhang sywhang

Labels
area-Tracing-coreclr blocking-clean-ci Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Make PortableThreadPool to check events correctly before firing them sywhang/runtime
4 participants
@jkotas @hoyosjs @sywhang @Dotnet-GitSync-Bot