[Mono] Eventpipe Runtime Test Failures on iOS Simulator

[naricc]

Several runtime tests related to eventpipe are failing on iOS Simulator:

tracing/eventpipe/buffersize/buffersize/buffersize.sh
tracing/eventpipe/providervalidation/providervalidation/providervalidation.sh
tracing/eventpipe/bigevent/bigevent/bigevent.sh
tracing/eventpipe/reverse/reverse/reverse.sh
tracing/eventpipe/providervalidation/providervalidation/providervalidation.sh
tracing/eventpipe/processenvironment/processenvironment/processenvironment.sh
tracing/eventpipe/processinfo2/processinfo2/processinfo2.sh
tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh
tracing/eventpipe/diagnosticport/diagnosticport/diagnosticport.sh
tracing/eventpipe/pauseonstart/pauseonstart/pauseonstart.sh
tracing/eventpipe/reverseouter/reverseouter/reverseouter.sh
tracing/eventpipe/processinfo/processinfo/processinfo.sh

I'm not sure if these all have the same underlyign cause or not. Example stack trace from processinfo2:

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

[JulieLeeMSFT]

Please check if this outerloop failure is also related.

Failed in run: runtime-coreclr outerloop 20230120.4

Failed tests:

coreclr linux arm Checked no_tiered_compilation @ (Alpine.314.Arm32.Open)[email protected]/dotnet-buildtools/prereqs:alpine-3.14-helix-arm32v7
  - tracing/eventpipe/pauseonstart/pauseonstart/pauseonstart.sh

Error message:

Return code:      1
Raw output file:      /root/helix/work/workitem/uploads/Reports/tracing.eventpipe/pauseonstart/pauseonstart/pauseonstart.output.txt
Raw output:
BEGIN EXECUTION
/root/helix/work/correlation/corerun -p System.Reflection.Metadata.MetadataUpdater.IsSupported=false pauseonstart.dll ''
0.0s: ::== Running test: TEST_RuntimeResumesExecutionWithCommand
0.0s: Server name is '/tmp/DOTNET_TRACE_TESTS_hjsyhtko.0pm'
0.4s: running sub-process: /root/helix/work/correlation/corerun /root/helix/work/workitem/e/tracing/eventpipe/pauseonstart/pauseonstart/pauseonstart.dll 0
0.8s: subprocess started: True
0.8s: subprocess PID: 3417
1.3s: { Magic=System.Byte[]; ClrInstanceId=2ad6b0e2-df1c-4f4d-8839-8b1b914b2eae; ProcessId=3417; Unused=0; }
1.3s: Sent: { Header={ Magic=System.Byte[]; Size=20; CommandSet=4; CommandId=1; Reserved=0 }; }
1.3s: received: { Header={ Magic=System.Byte[]; Size=24; CommandSet=255; CommandId=0; Reserved=0 }; Payload=[ 0x00 0x00 0x00 0x00  ]}
1.3s: Sending 'exit' to subprocess stdin
2.0s: ================= Subprocess Exited =================
2.0s: SubProcess exited - Exit code: 0
2.0s: ----------------------------------------
2.0s: Subprocess stdout:
1.6s: Subprocess started!  Waiting for input...
1.6s: Received 'exit'.  Exiting...
2.0s: Subprocess stderr:
2.0s: ----------------------------------------
2.0s: Test passed: True
2.0s:
2.1s: ::== Running test: TEST_TracesHaveRelevantEvents
2.1s: Server name is '/tmp/DOTNET_TRACE_TESTS_c2fdodyv.tea'
2.1s: running sub-process: /root/helix/work/correlation/corerun /root/helix/work/workitem/e/tracing/eventpipe/pauseonstart/pauseonstart/pauseonstart.dll 0
2.1s: subprocess started: True
2.1s: subprocess PID: 3442
2.1s: Standard Diagnostics Server connection not created yet -> try again in 100 ms
2.2s: { Magic=System.Byte[]; ClrInstanceId=ce6904d4-699c-4d3c-a9d9-93674c5de5e8; ProcessId=3442; Unused=0; }
2.2s: Starting EventPipeSession over standard connection
2.4s: Started EventPipeSession over standard connection with session id: 0xf6df49b0
2.4s: Send ResumeRuntime Diagnostics IPC Command
2.4s: Sent: { Header={ Magic=System.Byte[]; Size=20; CommandSet=4; CommandId=1; Reserved=0 }; }
2.4s: received: { Header={ Magic=System.Byte[]; Size=24; CommandSet=255; CommandId=0; Reserved=0 }; Payload=[ 0x00 0x00 0x00 0x00  ]}
4.4s: Stopping EventPipeSession over standard connection
4.7s: Stopped EventPipeSession over standard connection
4.7s: Sending 'exit' to subprocess stdin
4.7s: ================= Subprocess Exited =================
4.7s: SubProcess exited - Exit code: 0
4.7s: ----------------------------------------
4.7s: Subprocess stdout:
1.0s: Subprocess started!  Waiting for input...
2.6s: Received 'exit'.  Exiting...
4.7s: Subprocess stderr:
4.7s: ----------------------------------------
5.0s: isStartupEventPresent: True
5.0s: Test passed: True
5.0s:
5.0s: ::== Running test: TEST_MultipleSessionsCanBeStartedWhilepaused
5.1s: Server name is '/tmp/DOTNET_TRACE_TESTS_5nhgjs3v.cee'
5.1s: running sub-process: /root/helix/work/correlation/corerun /root/helix/work/workitem/e/tracing/eventpipe/pauseonstart/pauseonstart/pauseonstart.dll 0
5.1s: subprocess started: True
5.1s: subprocess PID: 3495
5.1s: Standard Diagnostics Server connection not created yet -> try again in 100 ms
5.2s: { Magic=System.Byte[]; ClrInstanceId=3674e836-2adc-463d-86fc-48a62e52412c; ProcessId=3495; Unused=0; }
5.2s: Starting EventPipeSession over standard connection
5.2s: Started EventPipeSession over standard connection with session id: 0xf6fca9b0
5.2s: Starting EventPipeSession over standard connection
5.2s: Started EventPipeSession over standard connection with session id: 0xf6e29600
5.2s: Starting EventPipeSession over standard connection
5.2s: Started EventPipeSession over standard connection with session id: 0xf6e29660
5.2s: Send ResumeRuntime Diagnostics IPC Command
5.2s:

Stack trace:

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

cc @mdh1418 @tommcdon.

[JulieLeeMSFT]

Failed again in Link.

coreclr linux arm Checked no_tiered_compilation @ (Alpine.314.Arm32.Open)[email protected]/dotnet-buildtools/prereqs:alpine-3.14-helix-arm32v7

Link:

coreclr linux arm Checked no_tiered_compilation @ (Alpine.314.Arm32.Open)[email protected]/dotnet-buildtools/prereqs:alpine-3.14-helix-arm32v7

[mdh1418]

I dont think the error message is the right point of failure.

This seems to be the test failures

10.1s: ::== Running test: TEST_ProcessInfoBeforeAndAfterSuspension
       10.2s: Server name is '/tmp/DOTNET_TRACE_TESTS_lsmipwas.rcd'
       10.2s: running sub-process: /root/helix/work/correlation/corerun /root/helix/work/workitem/e/tracing/eventpipe/pauseonstart/pauseonstart/pauseonstart.dll 0
       10.2s: subprocess started: True
       10.2s: subprocess PID: 3575
       10.2s: Standard Diagnostics Server connection not created yet -> try again in 100 ms
       10.3s: { Magic=System.Byte[]; ClrInstanceId=c0640859-356c-4b56-8d3c-1577b6529b9b; ProcessId=3575; Unused=0; }
       10.3s: Get ProcessInfo while process is suspended
       10.3s: Sent: { Header={ Magic=System.Byte[]; Size=20; CommandSet=4; CommandId=4; Reserved=0 }; }
       10.3s: received: { Header={ Magic=System.Byte[]; Size=206; CommandSet=255; CommandId=0; Reserved=0 }; Payload=[ 0xF7 0x0D 0x00 0x00 0x00 0x00 0x00 0x00 0x59 0x08 0x64 0xC0 0x6C 0x35 0x56 0x4B 0x8D 0x3C 0x15 0x77 0xB6 0x52 0x9B 0x9B 0x25 0x00 0x00 0x00 0x2F 0x00 0x72 0x00 0x6F 0x00 0x6F 0x00 0x74 0x00 0x2F 0x00 0x68 0x00 0x65 0x00 0x6C 0x00 0x69 0x00 0x78 0x00 0x2F 0x00 0x77 0x00 0x6F 0x00 0x72 0x00 0x6B 0x00 0x2F 0x00 0x63 0x00 0x6F 0x00 0x72 0x00 0x72 0x00 0x65 0x00 0x6C 0x00 0x61 0x00 0x74 0x00 0x69 0x00 0x6F 0x00 0x6E 0x00 0x2F 0x00 0x63 0x00 0x6F 0x00 0x72 0x00 0x65 0x00 0x72 0x00 0x75 0x00 0x6E 0x00 0x00 0x00 0x06 0x00 0x00 0x00 0x4C 0x00 0x69 0x00 0x6E 0x00 0x75 0x00 0x78 0x00 0x00 0x00 0x06 0x00 0x00 0x00 0x61 0x00 0x72 0x00 0x6D 0x00 0x33 0x00 0x32 0x00 0x00 0x00 0x0D 0x00 0x00 0x00 0x70 0x00 0x61 0x00 0x75 0x00 0x73 0x00 0x65 0x00 0x6F 0x00 0x6E 0x00 0x73 0x00 0x74 0x00 0x61 0x00 0x72 0x00 0x74 0x00 0x00 0x00 0x09 0x00 0x00 0x00 0x38 0x00 0x2E 0x00 0x30 0x00 0x2E 0x00 0x30 0x00 0x2D 0x00 0x63 0x00 0x69 0x00 0x00 0x00  ]}
       10.3s: { Magic=System.Byte[]; ClrInstanceId=c0640859-356c-4b56-8d3c-1577b6529b9b; ProcessId=3575; Unused=0; }
       10.3s: Starting EventPipeSession over standard connection
       10.3s: Started EventPipeSession over standard connection with session id: 0xf73d89b0
       10.3s: Send ResumeRuntime Diagnostics IPC Command
       10.3s: Sent: { Header={ Magic=System.Byte[]; Size=20; CommandSet=4; CommandId=1; Reserved=0 }; }
       10.3s: received: { Header={ Magic=System.Byte[]; Size=24; CommandSet=255; CommandId=0; Reserved=0 }; Payload=[ 0x00 0x00 0x00 0x00  ]}
       10.3s: { Magic=System.Byte[]; ClrInstanceId=c0640859-356c-4b56-8d3c-1577b6529b9b; ProcessId=3575; Unused=0; }
       10.3s: awaiting resume
       10.3s: Creating source
       10.4s: resumed
       10.4s: Stopping EventPipeSession over standard connection
       10.4s: stopping processing
       10.4s: Await reader task
       10.4s: Stopped EventPipeSession over standard connection
       10.5s: Get ProcessInfo after resumption: attempt 0
       10.5s: Sent: { Header={ Magic=System.Byte[]; Size=20; CommandSet=4; CommandId=4; Reserved=0 }; }
       10.5s: received: { Header={ Magic=System.Byte[]; Size=206; CommandSet=255; CommandId=0; Reserved=0 }; Payload=[ 0xF7 0x0D 0x00 0x00 0x00 0x00 0x00 0x00 0x59 0x08 0x64 0xC0 0x6C 0x35 0x56 0x4B 0x8D 0x3C 0x15 0x77 0xB6 0x52 0x9B 0x9B 0x25 0x00 0x00 0x00 0x2F 0x00 0x72 0x00 0x6F 0x00 0x6F 0x00 0x74 0x00 0x2F 0x00 0x68 0x00 0x65 0x00 0x6C 0x00 0x69 0x00 0x78 0x00 0x2F 0x00 0x77 0x00 0x6F 0x00 0x72 0x00 0x6B 0x00 0x2F 0x00 0x63 0x00 0x6F 0x00 0x72 0x00 0x72 0x00 0x65 0x00 0x6C 0x00 0x61 0x00 0x74 0x00 0x69 0x00 0x6F 0x00 0x6E 0x00 0x2F 0x00 0x63 0x00 0x6F 0x00 0x72 0x00 0x65 0x00 0x72 0x00 0x75 0x00 0x6E 0x00 0x00 0x00 0x06 0x00 0x00 0x00 0x4C 0x00 0x69 0x00 0x6E 0x00 0x75 0x00 0x78 0x00 0x00 0x00 0x06 0x00 0x00 0x00 0x61 0x00 0x72 0x00 0x6D 0x00 0x33 0x00 0x32 0x00 0x00 0x00 0x0D 0x00 0x00 0x00 0x70 0x00 0x61 0x00 0x75 0x00 0x73 0x00 0x65 0x00 0x6F 0x00 0x6E 0x00 0x73 0x00 0x74 0x00 0x61 0x00 0x72 0x00 0x74 0x00 0x00 0x00 0x09 0x00 0x00 0x00 0x38 0x00 0x2E 0x00 0x30 0x00 0x2E 0x00 0x30 0x00 0x2D 0x00 0x63 0x00 0x69 0x00 0x00 0x00  ]}
       10.5s: { Magic=System.Byte[]; ClrInstanceId=c0640859-356c-4b56-8d3c-1577b6529b9b; ProcessId=3575; Unused=0; }
       10.5s: Get ProcessInfo after resumption: attempt 1
       ...
       10.6s: Get ProcessInfo after resumption: attempt 108
       10.6s: Sent: { Header={ Magic=System.Byte[]; Size=20; CommandSet=4; CommandId=4; Reserved=0 }; }
       11.2s: ================= Subprocess Exited =================
       11.2s: - Exit code: 139
       11.2s: Subprocess stdout: 
        0.4s: [createdump] Gathering state for process 3575 corerun
        0.4s: [createdump] Crashing thread 00000dfb signal 0000000b
        0.8s: [createdump] Writing minidump with heap to file /home/helixbot/dotnetbuild/dumps/coredump.3575.dmp
        0.8s: [createdump] Written 20885504 bytes (5099 pages) to core file
        0.8s: [createdump] Target process is alive
        0.8s: [createdump] Dump successfully written in 434ms
       11.2s: Subprocess stderr: 
        0.8s: [createdump] waitpid() returned successfully (wstatus 00000000)
       11.4s: System.Exception: After resuming, the commandline should be the correct value. Observed: Before='/root/helix/work/correlation/corerun' After='/root/helix/work/correlation/corerun'
         at Tracing.Tests.PauseOnStartValidation.PauseOnStartValidation.<>c__DisplayClass5_0.<<TEST_ProcessInfoBeforeAndAfterSuspension>b__0>d.MoveNext()
      --- End of stack trace from previous location ---
         at Tracing.Tests.Common.Utils.RunSubprocess(Assembly currentAssembly, Dictionary`2 environment, Func`1 beforeExecution, Func`2 duringExecution, Func`1 afterExecution)
       11.4s: Calling process.Kill()
       11.4s: ----------------------------------------
       11.4s: Subprocess stdout: 
        0.4s: [createdump] Gathering state for process 3575 corerun
        0.4s: [createdump] Crashing thread 00000dfb signal 0000000b
        0.8s: [createdump] Writing minidump with heap to file /home/helixbot/dotnetbuild/dumps/coredump.3575.dmp
        0.8s: [createdump] Written 20885504 bytes (5099 pages) to core file
        0.8s: [createdump] Target process is alive
        0.8s: [createdump] Dump successfully written in 434ms
       11.4s: Subprocess stderr: 
        0.8s: [createdump] waitpid() returned successfully (wstatus 00000000)
       11.4s: ----------------------------------------
       11.4s: Test passed: False

I believe that has been resolved from #80889
which was merged probably after the outerloop runs.

[mdh1418]

I believe this issue is different from the linux failures primarily because runtime tests are not running on iOS device/sim arm64, we have a PR open trying to address that

[JulieLeeMSFT]

Thanks @mdh1418 for checking this out.

I believe that has been resolved from #80889
which was merged probably after the outerloop runs.