Test failure tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh

[v-wenyuxu]

Failed in: runtime-coreclr jitstress-isas-x86 20230513.1

Failed tests:

coreclr osx x64 Checked jitstress_isas_nohwintrinsic @ OSX.1200.Amd64.Open
    - tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh

�Error message:

 
cmdLine:/private/tmp/helix/working/B5D80A8D/w/B72A0988/e/tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh Timed Out (timeout in milliseconds: 1800000 from variable __TestTimeout, start: 5/13/2023 3:12:28 PM, end: 5/13/2023 3:42:29 PM)

Return code:      -100
Raw output file:      /tmp/helix/working/B5D80A8D/w/B72A0988/uploads/Reports/tracing.runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.output.txt
Raw output:
BEGIN EXECUTION
/tmp/helix/working/B5D80A8D/p/corerun -p System.Reflection.Metadata.MetadataUpdater.IsSupported=false -p System.Runtime.Serialization.EnableUnsafeBinaryFormatterSerialization=true nativeruntimeeventsource.dll ''
(Listener) [58, (Microsoft-Windows-DotNETRuntime, YieldProcessorMeasurement)]

cmdLine:/private/tmp/helix/working/B5D80A8D/w/B72A0988/e/tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh Timed Out (timeout in milliseconds: 1800000 from variable __TestTimeout, start: 5/13/2023 3:12:28 PM, end: 5/13/2023 3:42:29 PM)
Printing stacktrace from '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/cores/crashdump_66231.dmp.crashreport.json'
Invoking llvm-symbolizer --pretty-print
Errors while running llvm-symbolizer --pretty-print
System.ComponentModel.Win32Exception (2): An error occurred trying to start process 'llvm-symbolizer' with working directory '/private/tmp/helix/working/B5D80A8D/w/B72A0988/e'. No such file or directory
   at System.Diagnostics.Process.ForkAndExecProcess(ProcessStartInfo startInfo, String resolvedFilename, String[] argv, String[] envp, String cwd, Boolean setCredentials, UInt32 userId, UInt32 groupId, UInt32[] groups, Int32& stdinFd, Int32& stdoutFd, Int32& stderrFd, Boolean usesTerminal, Boolean throwOnNoExec)
   at System.Diagnostics.Process.StartCore(ProcessStartInfo startInfo)
   at CoreclrTestLib.CoreclrTestWrapperLib.TryPrintStackTraceFromCrashReport(String crashReportJsonFile, TextWriter outputWriter)
Test Harness Exitcode is : -100
To run the test:
> set CORE_ROOT=/tmp/helix/working/B5D80A8D/p
> /private/tmp/helix/working/B5D80A8D/w/B72A0988/e/tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh
Expected: True
Actual:   False

�Stack trace:

    at tracing_runtimeeventsource._nativeruntimeeventsource_nativeruntimeeventsource_._nativeruntimeeventsource_nativeruntimeeventsource_sh()
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)

Queued	Pipeline	Pipeline_Configuration	OS	Arch	Test	Outcome	Properties	BuildReason
2023-05-14T21:18:35.529Z	runtime	Checked-no_tiered_compilation	osx.1200.amd64.open	x64	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	Failed	{"System.JobAttempt":"1","System.StageName":"Build","System.JobName":"__default","Project":"public","Reason":"Schedule","System.PhaseAttempt":"1","System.JobId":"e3709b8d-3156-5bab-add0-5fb59fdfbeb2","BuildId":"273302","configuration":"Checked-no_tiered_compilation","architecture":"x64","AzurePipelinesTestRunId":"5400816","BuildNumber":"20230514.10","System.StageAttempt":"1","DefinitionId":"129","System.PhaseName":"run_test_p0_coreclr__osx_x64_checked","DefinitionName":"runtime","CollectionUri":"https://dev.azure.com/dnceng-public/","operatingSystem":"OSX.1200.Amd64.Open"}	Schedule
2023-05-14T09:53:29.668Z	runtime-extra-platforms	Release	ubuntu.1804.amd64.android.29.open.rt	x64	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	Failed	{"System.JobName":"__default","Project":"public","BuildNumber":"20230514.1","architecture":"x64","Reason":"Schedule","System.StageAttempt":"1","System.PhaseName":"build_android_x64_Release_AllSubsets_Mono_RuntimeTests","BuildId":"273180","System.StageName":"Build","AzurePipelinesTestRunId":"5398024","DefinitionName":"runtime-extra-platforms","System.PhaseAttempt":"1","DefinitionId":"154","CollectionUri":"https://dev.azure.com/dnceng-public/","operatingSystem":"Ubuntu.1804.Amd64.Android.29.Open","System.JobId":"353cbaf6-57aa-5b05-dc8e-ce12fdf7e230","System.JobAttempt":"1","configuration":"Release"}	Schedule
2023-05-14T05:58:25.066Z	runtime-coreclr jitstress	Checked-zapdisable	osx.1200.amd64.open	x64	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	Failed	{"BuildNumber":"20230513.2","System.PhaseName":"run_test_p1__osx_x64_checked","System.JobAttempt":"1","System.JobId":"bf644a0b-2dbe-5a03-d8c6-a86fdd97c823","Project":"public","System.StageAttempt":"1","configuration":"Checked-zapdisable","architecture":"x64","BuildId":"273133","DefinitionName":"runtime-coreclr jitstress","Reason":"Schedule","DefinitionId":"109","System.JobName":"__default","operatingSystem":"OSX.1200.Amd64.Open","System.StageName":"Build","System.PhaseAttempt":"1","AzurePipelinesTestRunId":"5396234","CollectionUri":"https://dev.azure.com/dnceng-public/"}	Schedule
2023-05-14T03:07:42.671Z	runtime-coreclr outerloop	Checked-no_tiered_compilation	osx.1200.amd64.open	x64	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	Failed	{"System.JobAttempt":"1","System.JobName":"__default","System.PhaseAttempt":"1","configuration":"Checked-no_tiered_compilation","System.StageAttempt":"1","BuildId":"273123","operatingSystem":"OSX.1200.Amd64.Open","BuildNumber":"20230513.3","System.StageName":"Build","Project":"public","AzurePipelinesTestRunId":"5395188","CollectionUri":"https://dev.azure.com/dnceng-public/","DefinitionName":"runtime-coreclr outerloop","architecture":"x64","System.JobId":"bf644a0b-2dbe-5a03-d8c6-a86fdd97c823","Reason":"Schedule","DefinitionId":"108","System.PhaseName":"run_test_p1__osx_x64_checked"}	Schedule
2023-05-13T19:18:17.993Z	runtime-coreclr outerloop	Checked-no_tiered_compilation	ubuntu.1804.amd64.open.rt	x64	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	Failed	{"DefinitionName":"runtime-coreclr outerloop","System.StageAttempt":"1","operatingSystem":"(Alpine.315.Amd64.Open)Ubuntu.1804.Amd64.Open@mcr.microsoft.com/dotnet-buildtools/prereqs:alpine-3.15-helix-amd64","DefinitionId":"108","BuildNumber":"20230513.2","System.StageName":"Build","Reason":"Schedule","BuildId":"272910","CollectionUri":"https://dev.azure.com/dnceng-public/","System.JobName":"__default","configuration":"Checked-no_tiered_compilation","System.PhaseName":"run_test_p1__linux_musl_x64_checked","System.JobAttempt":"1","architecture":"x64","System.JobId":"958a2a9a-ade5-50b3-3ce6-ea69efbcce9c","Project":"public","AzurePipelinesTestRunId":"5391072","System.PhaseAttempt":"1"}	Schedule
2023-05-13T06:00:02.081Z	runtime-coreclr jitstress	Checked-zapdisable	osx.1200.amd64.open	x64	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	Failed	{"BuildId":"272661","System.JobId":"bf644a0b-2dbe-5a03-d8c6-a86fdd97c823","CollectionUri":"https://dev.azure.com/dnceng-public/","Project":"public","configuration":"Checked-zapdisable","System.JobName":"__default","operatingSystem":"OSX.1200.Amd64.Open","System.PhaseName":"run_test_p1__osx_x64_checked","System.StageAttempt":"1","DefinitionId":"109","DefinitionName":"runtime-coreclr jitstress","System.JobAttempt":"1","AzurePipelinesTestRunId":"5383424","architecture":"x64","System.StageName":"Build","BuildNumber":"20230512.3","Reason":"Schedule","System.PhaseAttempt":"1"}	Schedule
2023-03-13T10:12:59.384Z	runtime-coreclr outerloop	Checked	ubuntu.1804.amd64.open.rt	x64	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	Failed	{"DefinitionName":"runtime-coreclr outerloop","AzurePipelinesTestRunId":"3781174","BuildId":"202124","Reason":"Schedule","operatingSystem":"(Alpine.315.Amd64.Open)Ubuntu.1804.Amd64.Open@mcr.microsoft.com/dotnet-buildtools/prereqs:alpine-3.15-helix-amd64","DefinitionId":"108","System.StageName":"Build","BuildNumber":"20230313.1","System.JobId":"92e17f34-a5d5-5d2c-e1e5-826eb9786835","System.JobAttempt":"1","System.StageAttempt":"1","System.JobName":"__default","Project":"public","configuration":"Checked","architecture":"x64","CollectionUri":"https://dev.azure.com/dnceng-public/","System.PhaseName":"run_test_p1_R2R_CG2_linux_musl_x64_checked","System.PhaseAttempt":"1"}	Schedule
2023-01-17T06:11:55.274Z	runtime-coreclr jitstress	Checked-jitstress2	osx.1200.amd64.open	x64	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	Failed	{"architecture":"x64","System.JobAttempt":"1","Reason":"Schedule","System.PhaseName":"run_test_p1__osx_x64_checked","System.StageName":"Build","configuration":"Checked-jitstress2","System.JobId":"bf644a0b-2dbe-5a03-d8c6-a86fdd97c823","System.StageAttempt":"1","DefinitionId":"109","DefinitionName":"runtime-coreclr jitstress","BuildNumber":"20230116.4","System.PhaseAttempt":"1","CollectionUri":"https://dev.azure.com/dnceng-public/","BuildId":"139245","operatingSystem":"OSX.1200.Amd64.Open","Project":"public","AzurePipelinesTestRunId":"3023292","System.JobName":"__default"}	Schedule

Error Message

Fill the error message using known issues guidance.

{
  "ErrorMessage": "nativeruntimeeventsource.sh Timed Out",
  "BuildRetry": false,
  "ErrorPattern": "",
  "ExcludeConsoleLog": false
}

Report

Build	Definition	Test	Pull Request
277844	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh
276933	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#86346
276875	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#85254
276735	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#86380
276756	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#86384
276648	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#86342
276580	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#86374
276408	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh
276409	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#86339
276313	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#85871
276319	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh
276249	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#86339
276121	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#85493
275947	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#86177
275889	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh
275750	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#85871
275569	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#74623
275701	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#86342
275732	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh
275542	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#85871
275054	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#86294
275162	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#86316
275152	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#81632
275101	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh	#86314
275007	dotnet/runtime	tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource.sh

Summary

24-Hour Hit Count	7-Day Hit Count	1-Month Count
7	25	25

[BruceForstall]

@n77y @davmason Looks like this test changed in #85563

[BruceForstall]

cc @tommcdon

[BruceForstall]

Also hung/crashed in ilasm round-trip tests:

https://dev.azure.com/dnceng-public/public/_build/results?buildId=272937&view=ms.vss-test-web.build-test-results-tab&runId=5391338&resultId=119664&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab

coreclr linux x64 Checked ilasmroundtrip @ Ubuntu.1804.Amd64.Open

[tommcdon]

@davmason - this looks like a deadlock between System.Diagnostics.Tracing.EventPipeEventDispatcher.SendCommand and System.Diagnostics.Tracing.EventSource.Initialize taking the EventListener.EventListenersLock lock.

System.Diagnostics.Tracing.EventSource.Initialize thread:

      "unmanaged_name" : "__psynch_cvwait",
      "unmanaged_name" : "_pthread_cond_wait",
      "unmanaged_name" : "CorUnix::CPalSynchronizationManager::ThreadNativeWait(CorUnix::_ThreadNativeWaitData*, unsigned int, CorUnix::ThreadWakeupReason*, unsigned int*)",
      "unmanaged_name" : "CorUnix::CPalSynchronizationManager::BlockThread(CorUnix::CPalThread*, unsigned int, bool, bool, CorUnix::ThreadWakeupReason*, unsigned int*)",
      "unmanaged_name" : "CorUnix::InternalWaitForMultipleObjectsEx(CorUnix::CPalThread*, unsigned int, void* const*, int, unsigned int, int, int)",
      "unmanaged_name" : "WaitForMultipleObjectsEx",
      "unmanaged_name" : "Thread::DoAppropriateWaitWorker(int, void**, int, unsigned int, WaitMode)",
      "unmanaged_name" : "Thread::DoAppropriateWait(int, void**, int, unsigned int, WaitMode, PendingSync*)",
      "unmanaged_name" : "CLREventBase::WaitEx(unsigned int, WaitMode, PendingSync*)",
      "unmanaged_name" : "AwareLock::EnterEpilogHelper(Thread*, int)",
      "unmanaged_name" : "AwareLock::Enter()",
      "unmanaged_name" : "JIT_MonEnter_Helper(Object*, unsigned char*, void*)",
      "unmanaged_name" : "JIT_MonReliableEnter_Portable",
      "method_name" : "System.Diagnostics.Tracing.EventSource.Initialize(System.Guid, System.String, System.String[])",
      "method_name" : "System.Buffers.ArrayPoolEventSource..ctor()",
      "method_name" : "System.Buffers.ArrayPoolEventSource..cctor()",
      "unmanaged_name" : "CallDescrWorkerWithHandler(CallDescrData*, int)",
      "unmanaged_name" : "DispatchCallDebuggerWrapper(CallDescrData*, int)",
      "unmanaged_name" : "DispatchCallSimple(unsigned long*, unsigned int, unsigned long long, unsigned int)",
      "unmanaged_name" : "MethodTable::RunClassInitEx(OBJECTREF*)",
      "unmanaged_name" : "MethodTable::DoRunClassInitThrowing()",
      "unmanaged_name" : "MethodTable::CheckRunClassInitThrowing()",
      "unmanaged_name" : "JIT_GetSharedNonGCStaticBase_Helper",
      "method_name" : "System.Buffers.SharedArrayPool`1[[System.Char, System.Private.CoreLib]].Rent(Int32)",
      "method_name" : "Tracing.Tests.Listener.OnEventWritten(System.Diagnostics.Tracing.EventWrittenEventArgs)",
      "method_name" : "System.Diagnostics.Tracing.EventSource.DispatchToAllListeners(System.Diagnostics.Tracing.EventWrittenEventArgs)",
      "method_name" : "System.Diagnostics.Tracing.EventPipeEventDispatcher.DispatchEventsToEventListeners()",
      "method_name" : "System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)",
      "method_name" : "System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread)",
      "method_name" : "System.Threading.Thread.StartCallback()",
      "unmanaged_name" : "CallDescrWorkerWithHandler(CallDescrData*, int)",
      "unmanaged_name" : "DispatchCallSimple(unsigned long*, unsigned int, unsigned long long, unsigned int)",
      "unmanaged_name" : "ThreadNative::KickOffThread_Worker(void*)",
      "unmanaged_name" : "ManagedThreadBase_DispatchOuter(ManagedThreadCallState*)",
      "unmanaged_name" : "ManagedThreadBase::KickOff(void (*)(void*), void*)",
      "unmanaged_name" : "ThreadNative::KickOffThread(void*)",
      "unmanaged_name" : "CorUnix::CPalThread::ThreadEntry(void*)",
      "unmanaged_name" : "_pthread_start",

System.Diagnostics.Tracing.EventPipeEventDispatcher.SendCommand thread:

      "unmanaged_name" : "__psynch_cvwait",
      "unmanaged_name" : "_pthread_cond_wait",
      "unmanaged_name" : "CorUnix::CPalSynchronizationManager::ThreadNativeWait(CorUnix::_ThreadNativeWaitData*, unsigned int, CorUnix::ThreadWakeupReason*, unsigned int*)",
      "unmanaged_name" : "CorUnix::CPalSynchronizationManager::BlockThread(CorUnix::CPalThread*, unsigned int, bool, bool, CorUnix::ThreadWakeupReason*, unsigned int*)",
      "unmanaged_name" : "CorUnix::InternalWaitForMultipleObjectsEx(CorUnix::CPalThread*, unsigned int, void* const*, int, unsigned int, int, int)",
      "unmanaged_name" : "WaitForMultipleObjectsEx",
      "unmanaged_name" : "Thread::DoAppropriateWaitWorker(int, void**, int, unsigned int, WaitMode)",
      "unmanaged_name" : "Thread::DoAppropriateWait(int, void**, int, unsigned int, WaitMode, PendingSync*)",
      "unmanaged_name" : "CLREventBase::WaitEx(unsigned int, WaitMode, PendingSync*)",
      "unmanaged_name" : "Thread::Block(int, PendingSync*)",
      "unmanaged_name" : "SyncBlock::Wait(int)",
      "unmanaged_name" : "ObjectNative::WaitTimeout(int, Object*)",
      "method_name" : "System.Threading.Monitor.Wait(System.Object, Int32)",
      "method_name" : "System.Threading.ManualResetEventSlim.Wait(Int32, System.Threading.CancellationToken)",
      "method_name" : "System.Threading.Tasks.Task.SpinThenBlockingWait(Int32, System.Threading.CancellationToken)",
      "method_name" : "System.Threading.Tasks.Task.InternalWaitCore(Int32, System.Threading.CancellationToken)",
      "method_name" : "System.Threading.Tasks.Task.Wait(Int32, System.Threading.CancellationToken)",
      "method_name" : "System.Threading.Tasks.Task.Wait()",
      "method_name" : "System.Diagnostics.Tracing.EventPipeEventDispatcher.StopDispatchTask()",
      "method_name" : "System.Diagnostics.Tracing.EventPipeEventDispatcher.CommitDispatchConfiguration()",
      "method_name" : "System.Diagnostics.Tracing.EventPipeEventDispatcher.RemoveEventListener(System.Diagnostics.Tracing.EventListener)",
      "method_name" : "System.Diagnostics.Tracing.EventPipeEventDispatcher.SendCommand(System.Diagnostics.Tracing.EventListener, System.Diagnostics.Tracing.EventCommand, Boolean, System.Diagnostics.Tracing.EventLevel, System.Diagnostics.Tracing.EventKeywords)",
      "method_name" : "System.Diagnostics.Tracing.EventListener.CallDisableEventsIfNecessary(System.Diagnostics.Tracing.EventDispatcher, System.Diagnostics.Tracing.EventSource)",
      "method_name" : "System.Diagnostics.Tracing.EventListener.RemoveReferencesToListenerInEventSources(System.Diagnostics.Tracing.EventListener)",
      "method_name" : "System.Diagnostics.Tracing.EventListener.Dispose()",
      "method_name" : "Tracing.Tests.Listener.Dispose()",
      "method_name" : "Tracing.Tests.NativeRuntimeEventSourceTest.Main()",
      "unmanaged_name" : "mach_msg_trap",
      "unmanaged_name" : "mach_msg",
      "unmanaged_name" : "MachMessage::Receive(unsigned int)",
      "unmanaged_name" : "SEHExceptionThread(void*)",
      "unmanaged_name" : "_pthread_start",

[BruceForstall]

@tommcdon @davmason Any progress? This failure seems pretty pervasive. Maybe we can get the test temporarily disabled?