runtime: Test failure tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh

Run: runtime-coreclr gcstress0x3-gcstress0xc 20210627.1

Failed test:

CoreCLR Linux x64 Checked gcstress0x3 @ Ubuntu.1804.Amd64.Open

- tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh

Error message:

Fatal error. System.AccessViolationException: Attempted to read or write protected memory. This is often an indication that other memory is corrupt.
at Microsoft.Diagnostics.Tracing.TraceEvent.CopyBlob(IntPtr, IntPtr, Int32)
at Microsoft.Diagnostics.Tracing.TraceEvent.Clone()
at Microsoft.Diagnostics.Tracing.Parsers.ExternalTraceEventParser.<.ctor>b__0_0(Microsoft.Diagnostics.Tracing.TraceEvent)
at Microsoft.Diagnostics.Tracing.TraceEventDispatcher.Lookup(EVENT_RECORD*)
at Microsoft.Diagnostics.Tracing.EventPipeEventSource.DispatchEventRecord(EVENT_RECORD*)
at Microsoft.Diagnostics.Tracing.EventPipeEventSource.EventCache_OnEvent(Microsoft.Diagnostics.Tracing.EventPipeEventHeader ByRef)
at Microsoft.Diagnostics.Tracing.EventPipe.EventCache.SortAndDispatch(Int64)
at Microsoft.Diagnostics.Tracing.EventPipe.EventCache.ProcessSequencePointBlock(Byte[])
at Microsoft.Diagnostics.Tracing.EventPipeSequencePointBlock.ReadBlockContents(FastSerialization.PinnedStreamReader)
at Microsoft.Diagnostics.Tracing.EventPipeBlock.FromStream(FastSerialization.Deserializer)
at FastSerialization.Deserializer.ReadObjectDefinition(FastSerialization.Tags, FastSerialization.StreamLabel)
at FastSerialization.Deserializer.ReadObject()
at Microsoft.Diagnostics.Tracing.EventPipeEventSource.Process()
at Tracing.Tests.Common.IpcTraceTest+<>c__DisplayClass8_0.<Validate>b__1()
at System.Threading.Tasks.Task.InnerInvoke()
at System.Threading.Tasks.Task+<>c.<.cctor>b__284_0(System.Object)
at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread, System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
at System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread)
at System.Threading.Tasks.Task.ExecuteEntryUnsafe(System.Threading.Thread)
at System.Threading.ThreadPoolWorkQueue.Dispatch()
at System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()
at System.Threading.Thread.StartCallback()
/datadisks/disk1/work/AA440922/w/B06F0997/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh: line 394: 26241 Aborted                 (core dumped) $LAUNCHER $ExePath "${CLRTestExecutionArguments[@]}"

Return code:      1
Raw output file:      /datadisks/disk1/work/AA440922/w/B06F0997/uploads/Reports/tracing.eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.output.txt
Raw output:
BEGIN EXECUTION
/datadisks/disk1/work/AA440922/p/corerun rundownvalidation.dll ''
0.0s: ==TEST STARTING==
33.6s: Started sending sentinel events...
33.8s: Connecting to EventPipe...
65.9s: Connected to EventPipe with sessionID '0x7fd1800093a0'
65.9s: Creating EventPipeEventSource...
76.6s: EventPipeEventSource created
80.0s: Dynamic.All callback registered
80.0s: Running optional trace validator
80.9s: Finished running optional trace validator
80.9s: Starting stream processing...
98.9s: Saw new provider 'Microsoft-DotNETCore-SampleProfiler'
131.0s: Saw sentinel event
131.0s: Stopped sending sentinel events
131.3s: Starting event generating action...
131.3s: Stopping event generating action
131.4s: Sending StopTracing command...
169.4s: Saw new provider 'Microsoft-DotNETCore-EventPipe'
169.6s: Saw new provider 'Microsoft-Windows-DotNETRuntimeRundown'
Gathering state for process 26241 corerun
Writing minidump with heap to file /home/helixbot/dotnetbuild/dumps/coredump.26241.dmp
Written 132464640 bytes (32340 pages) to core file
Dump successfully written
Expected: 100
Actual: 134
END EXECUTION - FAILED
Test Harness Exitcode is : 1
To run the test:

set CORE_ROOT=/datadisks/disk1/work/AA440922/p
/datadisks/disk1/work/AA440922/w/B06F0997/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh
Expected: True
Actual:   False


Stack trace
   at tracing_eventpipe._rundownvalidation_rundownvalidation_rundownvalidation_._rundownvalidation_rundownvalidation_rundownvalidation_sh() in tracing.eventpipe.XUnitWrapper.dll:token 0x6000024+0x295

Runfo Tracking Issue: tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh

Build Definition Kind Run Name Console Core Dump Test Results Run Client
1626538 runtime PR 65398 Mono Android x64 Release @ Ubuntu.1804.Amd64.Android.29.Open console.log runclient.py
1626376 runtime PR 65489 CoreCLR Linux arm Checked no_tiered_compilation @ (Ubuntu.1804.Arm32.Open)Ubuntu.1804.Armarch.Open@mcr.microsoft.com/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm32v7-bfcd90a-20200121150440 console.log core dump runclient.py
1626136 runtime PR 64358 CoreCLR Linux arm Checked no_tiered_compilation @ (Ubuntu.1804.Arm32.Open)Ubuntu.1804.Armarch.Open@mcr.microsoft.com/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm32v7-bfcd90a-20200121150440 console.log core dump runclient.py
1625363 runtime PR 65489 CoreCLR Linux arm Checked no_tiered_compilation @ (Ubuntu.1804.Arm32.Open)Ubuntu.1804.Armarch.Open@mcr.microsoft.com/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm32v7-bfcd90a-20200121150440 console.log core dump runclient.py
1625267 runtime PR 64358 CoreCLR Linux arm Checked no_tiered_compilation @ (Ubuntu.1804.Arm32.Open)Ubuntu.1804.Armarch.Open@mcr.microsoft.com/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm32v7-bfcd90a-20200121150440 console.log core dump runclient.py
1623185 runtime PR 64358 CoreCLR Linux arm Checked no_tiered_compilation @ (Ubuntu.1804.Arm32.Open)Ubuntu.1804.Armarch.Open@mcr.microsoft.com/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm32v7-bfcd90a-20200121150440 console.log core dump runclient.py
1622882 runtime PR 64358 CoreCLR Linux arm Checked no_tiered_compilation @ (Ubuntu.1804.Arm32.Open)Ubuntu.1804.Armarch.Open@mcr.microsoft.com/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm32v7-bfcd90a-20200121150440 console.log core dump runclient.py
1614899 runtime PR 64358 CoreCLR Linux arm Checked no_tiered_compilation @ (Ubuntu.1804.Arm32.Open)Ubuntu.1804.Armarch.Open@mcr.microsoft.com/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm32v7-bfcd90a-20200121150440 console.log core dump runclient.py
1612319 runtime PR 64358 CoreCLR Linux arm Checked no_tiered_compilation @ (Ubuntu.1804.Arm32.Open)Ubuntu.1804.Armarch.Open@mcr.microsoft.com/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm32v7-bfcd90a-20200121150440 console.log core dump runclient.py

Build Result Summary

Day Hit Count Week Hit Count Month Hit Count
0 0 9

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Comments: 25 (22 by maintainers)

Most upvoted comments

I add it to the exclude list as well.

Looks like this issue has diverged from its original report (that was a CoreCLR crash) and is now most likely the same underlying issue as https://github.com/dotnet/runtime/issues/59296.

@josalem, that’s what it looks like to me. In general, its very tricky to use types with finalizers correctly, if the type exposes details which are supposed to be protected by the finalizer (such as the PinningHandle property). For instance, this is why we moved to using SafeHandles internally for FileStreams, and why use of the Handle property on a FileStream is so strongly discouraged. Audits for correctness tend to fail to find issues, failures tend to be extremely hard to isolate, and the behavior of code will change unpredictably from version of .NET to version of .NET.

@josalem From what you’re reporting here, this doesn’t look like a bug in the GC proper. This looks like a bug in the PerfView repo.

In particular, the EventMarker object isn’t kept alive through the call to the OnEvent call in SortAndDispatch, and the implementation of the OnEvent method (EventPipeEventSource.EventCache_OnEvent) which takes a ref parameter which would generally keep the object alive, uses the ref, to produce a raw pointer to pass to EventPipeEventSource.DispatchEventRecord but does not attempt to keep the ref alive any further. The end result of this, is that the EventMarker object can be freed by the GC, and in the presence of GC stress, this sort of fault is vastly more likely to occur than in normal execution.

I expect that the fix is to add a call to GC.KeepAlive(eventMarker) after the call to OnEvent?.Invoke(ref eventMarker.Header) in EventCache.SortAndDispatch, but this code is rather convoluted, so I’m not convinced that will fix all possible problems.

The big problem with using finalizers is that the runtime is free to execute them much, MUCH earlier than a developer might expect. I’ve event seen cases where a finalizer can execute before a method has finished its constructor.