Test failure tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh #54801

Activity

1. VincentBu

   added

   os-linuxLinux OS (any supported distro)Linux OS (any supported distro)

   GCStress

   arch-x64

   on Jun 28, 2021
2. ghost added

   area-Tracing-coreclr

   on Jun 28, 2021
3. ghost added

   untriagedNew issue has not been triaged by the area ownerNew issue has not been triaged by the area owner

   on Jun 28, 2021
4. tommcdon commented on Jun 28, 2021

   

   tommcdon

   on Jun 28, 2021

   Member

   More actions

   @davidwrighton @josalem related to #51477?
5. tommcdon

   removed

   untriagedNew issue has not been triaged by the area ownerNew issue has not been triaged by the area owner

   on Jun 28, 2021
6. tommcdon

   added this to the 6.0.0 milestone on Jun 28, 2021
7. VincentBu commented on Jul 12, 2021

   

   VincentBu

   on Jul 12, 2021

   Last edited by VincentBu

   ContributorAuthor

   More actions

   Run runtime-coreclr gcstress0x3-gcstress0xc 20210711.1
   Failed test:

   CoreCLR Linux x64 Checked gcstress0x3 @ Ubuntu.1804.Amd64.Open
   - tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh
   
   CoreCLR windows x86 Checked gcstress0xc @ Windows.10.Amd64.Open
   - Loader\\ContextualReflection\\ContextualReflection\\ContextualReflection.cmd
   
   
   

   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.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__271_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/A4DE0968/w/B9D109D4/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh: line 394: 23695 Aborted                 (core dumped) $LAUNCHER $ExePath "${CLRTestExecutionArguments[@]}"
   
   Return code:      1
   Raw output file:      /datadisks/disk1/work/A4DE0968/w/B9D109D4/uploads/Reports/tracing.eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.output.txt
   Raw output:
   BEGIN EXECUTION
   /datadisks/disk1/work/A4DE0968/p/corerun rundownvalidation.dll ''
   0.0s: ==TEST STARTING==
   22.5s: Started sending sentinel events...
   23.1s: Connecting to EventPipe...
   47.8s: Connected to EventPipe with sessionID '0x7f91ac0093a0'
   47.8s: Creating EventPipeEventSource...
   54.3s: EventPipeEventSource created
   58.2s: Dynamic.All callback registered
   58.2s: Running optional trace validator
   58.8s: Finished running optional trace validator
   58.8s: Starting stream processing...
   87.4s: Saw new provider 'Microsoft-DotNETCore-SampleProfiler'
   123.5s: Saw sentinel event
   123.6s: Stopped sending sentinel events
   124.4s: Starting event generating action...
   124.5s: Stopping event generating action
   124.9s: Sending StopTracing command...
   305.4s: Saw new provider 'Microsoft-DotNETCore-EventPipe'
   305.6s: Saw new provider 'Microsoft-Windows-DotNETRuntimeRundown'
   Gathering state for process 23695 corerun
   Crashing thread 00005cb2 signal 00000006
   Writing minidump with heap to file /home/helixbot/dotnetbuild/dumps/coredump.23695.dmp
   Written 133865472 bytes (32682 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/A4DE0968/p
   /datadisks/disk1/work/A4DE0968/w/B9D109D4/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
   
8. josalem commented on Jul 12, 2021

   

   josalem

   on Jul 12, 2021

   Contributor

   More actions

   related to #51477?

   It's possible. This isn't runtime code; this is Microsoft/PerfView code on the stack. I'd be surprised if there was an AV in TraceEvent that we haven't hit before now given the number of tests that use it. Especially since we haven't changed the version in recent memory.

   This failure has a dump associated with it, so I should be able to dig into it a little more. I've got a few things on my plate, so I'll put this on the stack to investigate.

   (CC @brianrob)

   To elaborate on the issue text, the two mentioned tests have different failures. The error message in the issue text is for the rundown validation test.

   This is the error message for the ContextualReflection test:

   Assert failure(PID 7972 [0x00001f24], Thread: 6620 [0x19dc]): ptrManagedAssemblyLoadContext != NULL
   
   CORECLR! AssemblyNative::GetLoadContextForAssembly + 0xF3 (0x70de4bd3)
   SYSTEM.PRIVATE.CORELIB! <no symbol> + 0x0 (0x6fd61d92)
   SYSTEM.PRIVATE.CORELIB! <no symbol> + 0x0 (0x6fd639cb)
   <no module>! <no symbol> + 0x0 (0x08929ab9)
   <no module>! <no symbol> + 0x0 (0x089289b3)
   <no module>! <no symbol> + 0x0 (0x0520eef8)
   <no module>! <no symbol> + 0x0 (0x0520ba88)
   CORECLR! CallDescrWorkerInternal + 0x34 (0x710ef801)
   CORECLR! CallDescrWorker + 0xAA (0x70df5789)
   CORECLR! CallDescrWorkerWithHandler + 0xDE (0x70df58c7)
       File: D:\workspace\_work\1\s\src\coreclr\vm\assemblynative.cpp Line: 1317
       Image: C:\h\w\A53508CA\p\corerun.exe
   

   I'm not sure if these are related.
9. josalem commented on Jul 12, 2021

   

   josalem

   on Jul 12, 2021

   Contributor

   More actions

   Took a look at the history for the rundown validation test. It's been intermittently failing since last Friday with varying errors. There's the above AV, but there is also the following error:

   Process terminated. Assertion failed.
   at System.Collections.Hashtable.InitHash(Object key, Int32 hashsize, UInt32& seed, UInt32& incr) in System.Private.CoreLib.dll:token 0x60068c4+0x11
   at System.Collections.Hashtable.get_Item(Object key) in System.Private.CoreLib.dll:token 0x60068d0+0xb
   at System.Collections.Hashtable.SyncHashtable.get_Item(Object key) in System.Private.CoreLib.dll:token 0x60068fa+0x0
   at System.Text.EncodingTable.GetCodePageFromName(String name) in System.Private.CoreLib.dll:token 0x60035ec+0xe
   at System.Text.Encoding.GetEncoding(String name) in System.Private.CoreLib.dll:token 0x6003567+0x0
   at System.Text.EncodingHelper.GetEncodingFromCharset() in //src/libraries/Common/src/System/Text/EncodingHelper.Unix.cs:line 15
   at System.ConsolePal.GetConsoleEncoding() in //src/libraries/System.Console/src/System/ConsolePal.Unix.cs:line 728
   at System.ConsolePal.get_OutputEncoding() in //src/libraries/System.Console/src/System/ConsolePal.Unix.cs:line 68
   at System.Console.get_OutputEncoding() in //src/libraries/System.Console/src/System/Console.cs:line 119
   at System.Console.CreateOutputWriter(Stream outputStream) in //src/libraries/System.Console/src/System/Console.cs:line 242
   at System.Console.<get_Out>g__EnsureInitialized|26_0() in //src/libraries/System.Console/src/System/Console.cs:line 212
   at System.Console.get_Out() in /_/src/libraries/System.Console/src/System/Console.cs:line 204
   at Tracing.Tests.Common.Logger..ctor(TextWriter log) in common.dll:token 0x6000007+0x6
   at Tracing.Tests.Common.Logger..cctor() in common.dll:token 0x6000009+0x0
   at Tracing.Tests.Common.IpcTraceTest.RunAndValidateEventCounts(Dictionary2 expectedEventCounts, Action eventGeneratingAction, Nullable1 sessionConfiguration, Func`2 optionalTraceValidator) in common.dll:token 0x600001b+0x0
   at Tracing.Tests.RundownValidation.RundownValidation.Main(String[] args) in rundownvalidation.dll:token 0x6000001+0x38
   

   It's not immediately obvious to me what assert failed, though:
   

   runtime/src/libraries/System.Private.CoreLib/src/System/Collections/Hashtable.cs

   Lines 395 to 408 in 738b09b

   	private uint InitHash(object key, int hashsize, out uint seed, out uint incr)
   	{
   	// Hashcode must be positive. Also, we must not use the sign bit, since
   	// that is used for the collision bit.
   	uint hashcode = (uint)GetHash(key) & 0x7FFFFFFF;
   	seed = (uint)hashcode;
   	// Restriction: incr MUST be between 1 and hashsize - 1, inclusive for
   	// the modular arithmetic to work correctly. This guarantees you'll
   	// visit every bucket in the table exactly once within hashsize
   	// iterations. Violate this and it'll cause obscure bugs forever.
   	// If you change this calculation for h2(key), update putEntry too!
   	incr = (uint)(1 + ((seed * HashHelpers.HashPrime) % ((uint)hashsize - 1)));
   	return hashcode;
   	}

   I'm guessing something happened during the QCall for GetHashCode on the string being used as a key:
   

   runtime/src/coreclr/vm/comutilnative.cpp

   Line 1984 in 57bfe47

   FCIMPL1(INT32, ValueTypeHelper::GetHashCode, Object* objUNSAFE)
10. josalem commented on Jul 14, 2021

    

    josalem

    on Jul 14, 2021

    Contributor

    More actions

    I investigated the CopyBlob() AV stack trace (different from my previous comment), and it appears to be something wonky surrounding following pointers to pinned GC handles.

    EventPipeEventSource reads data into byte[] buffers, then pins them using GC.Alloc(data, GCHandleType.Pinned). It then walks the buffer and creates the EVENT_RECORD structs that the TraceEvent library uses. When I look at the stack, I see a SIGSEGV on an address that is supposed to point to the payload of one of these EVENT_RECORD objects. EventPipeEventSource and TraceEvent in general tend to pin objects and then directly access things unsafely with pointers.

    I'm not convinced the pointer arithmetic/bookkeeping is wrong. It checks bounds and whatnot. When the logic goes to dereference the pointer into the pinned buffer, however, it seg faults. The address is not included in the dump created by createdump, but is in the system created dump. That being said, the system created dump seems to have the values at the address all zeroed out, which may indicate that it is junk data and that is why it isn't in the createdump dump.

    The long and short of it is: this call stack is segfaulting on what should be an address into a pinned GC handle for a byte[]. I'll continue to investigate. I don't have any evidence pointing to TraceEvent being wrong here.
11. josalem commented on Jul 14, 2021

    

    josalem

    on Jul 14, 2021

    Last edited by josalem

    Contributor

    More actions

    I investigated a little further and this looks like this might be caused by the GC collecting data while it is still in use. The code is in the middle of SortAndDispatch which walks the dictionary of events for all the threads and (as the name implies) sorts then dispatches the events. The seg fault is happening when the logic goes to clone some memory that is supposed to be in a pinned GC handle. When I look at the array of these pinned buffers, however, all the entries in the cache are marked as null.

    (lldb) dumparray -length 15 -details  00007f918406bba0
    Name:        Microsoft.Diagnostics.Tracing.EventPipe.EventMarker[]
    MethodTable: 00007f91bd12b3b8
    EEClass:     00007f91bc673588
    Size:        16408(0x4018) bytes
    Array:       Rank 1, Number of elements 2048, Type CLASS
    Element Methodtable: 00007f91bd12a300
    [0] null
    [1] null
    [2] null
    [3] null
    [4] null
    [5] null
    [6] null
    [7] null
    [8] null
    [9] null
    [10] null
    [11] null
    [12] null
    [13] null
    [14] null
    

    One of those entries is supposed to be where the pinned buffer pointed to by the faulting address lived.

    None of the above logic should be pointing to arbitrary data not allocated by itself, nor is it code that has changed recently. I don't believe that this is being caused by TraceEvent itself.

    @Maoni0 or @cshung is this an instance where something marked as pinned got collected, or is it possible that the pinning isn't working because the pinning APIs are misused? I've got this dump open if there is any info you would need to determine yes or no.
12. Maoni0 commented on Jul 14, 2021

    

    Maoni0

    on Jul 14, 2021

    Member

    More actions

    if you have a pinned handle, it's a strong handle so GC will treat it as live till you call Free on it.

    it would be helpful to show the code where you are pinning the object of interest and how it's related to this EventMarker array.
13. josalem commented on Jul 14, 2021

    

    josalem

    on Jul 14, 2021

    Last edited by josalem

    Contributor

    More actions

    Here is the relevant code I found digging through TraceEvent:
    https://github.com/microsoft/perfview/blob/6b4771eecba5ed00555a34d70e19a8742af4ee0a/src/TraceEvent/EventPipe/EventCache.cs#L248-L280

        internal class EventCacheThread
        {
            public Queue<EventMarker> Events = new Queue<EventMarker>();
            public int SequenceNumber;
            public long LastCachedEventTimestamp;
        }
    
        internal class EventMarker
        {
            public EventMarker(PinnedBuffer buffer)
            {
                Buffer = buffer;
            }
            public EventPipeEventHeader Header;
            public PinnedBuffer Buffer;
        }
    
        internal class PinnedBuffer
        {
            public PinnedBuffer(byte[] data)
            {
                Data = data;
                PinningHandle = GCHandle.Alloc(data, GCHandleType.Pinned);
            }
    
            ~PinnedBuffer()
            {
                PinningHandle.Free();
            }
    
            public byte[] Data { get; private set; }
            public GCHandle PinningHandle { get; private set; }
        }

    Those are stored in this dictionary on EventChache:

    Dictionary<long, EventCacheThread> _threads = new Dictionary<long, EventCacheThread>();
14. 9 remaining items

    Load more

15. josalem commented on Aug 9, 2021

    

    josalem

    on Aug 9, 2021

    Contributor

    More actions

    I'll be moving this issue to 7 in order to track completion of microsoft/perfview/issues/1474 and updating dotnet/runtime to the subsequent TraceEvent version.
16. josalem

    added

    tracking-external-issueThe issue is caused by external problem (e.g. OS) - nothing we can do to fix it directlyThe issue is caused by external problem (e.g. OS) - nothing we can do to fix it directly

    on Aug 9, 2021
17. josalem

    modified the milestones: 6.0.0, 7.0.0 on Aug 9, 2021
18. VincentBu commented on Sep 29, 2021

    

    VincentBu

    on Sep 29, 2021

    ContributorAuthor

    More actions

    Failed again in: runtime 20210928.21

    Failed test:

    Mono OSX x64 Release no_tiered_compilation @ OSX.1014.Amd64.Open
    
    - tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh
    
    

    Error message:

    cmdLine:/private/tmp/helix/working/A57108DA/w/AA700948/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh Timed Out (timeout in milliseconds: 600000 from variable __TestTimeout, start: 9/28/2021 9:15:19 AM, end: 9/28/2021 9:25:20 AM)
    
    Return code:      -100
    Raw output file:      /tmp/helix/working/A57108DA/w/AA700948/uploads/Reports/tracing.eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.output.txt
    Raw output:
    BEGIN EXECUTION
    /tmp/helix/working/A57108DA/p/corerun -p System.Reflection.Metadata.MetadataUpdater.IsSupported=false rundownvalidation.dll ''
    0.0s: ==TEST STARTING==
    0.3s: Connecting to EventPipe...
    0.3s: Started sending sentinel events...
    0.4s: Connected to EventPipe with sessionID '0x7fe6ce703e90'
    0.4s: Creating EventPipeEventSource...
    0.5s: EventPipeEventSource created
    0.5s: Dynamic.All callback registered
    0.5s: Running optional trace validator
    0.5s: Finished running optional trace validator
    0.5s: Starting stream processing...
    0.7s: Saw new provider 'Microsoft-DotNETCore-SampleProfiler'
    0.8s: Saw sentinel event
    0.8s: Stopped sending sentinel events
    0.8s: Starting event generating action...
    0.8s: Stopping event generating action
    0.8s: Sending StopTracing command...
    0.9s: Saw new provider 'Microsoft-DotNETCore-EventPipe'
    1.0s: Saw new provider 'Microsoft-Windows-DotNETRuntimeRundown'
    
    cmdLine:/private/tmp/helix/working/A57108DA/w/AA700948/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh Timed Out (timeout in milliseconds: 600000 from variable __TestTimeout, start: 9/28/2021 9:15:19 AM, end: 9/28/2021 9:25:20 AM)
    Test Harness Exitcode is : -100
    To run the test:
    
    set CORE_ROOT=/tmp/helix/working/A57108DA/p
    /private/tmp/helix/working/A57108DA/w/AA700948/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh
    Expected: True
    Actual:   False
    
    
    Stack trace
       at tracing_eventpipe._rundownvalidation_rundownvalidation_rundownvalidation_._rundownvalidation_rundownvalidation_rundownvalidation_sh()
    
19. ViktorHofer commented on Sep 30, 2021

    

    ViktorHofer

    on Sep 30, 2021

    Member

    More actions

    According to runfo this is failing multiple times per week (not the same stack as in the initial post but the same as the post above): https://runfo.azurewebsites.net/search/tests/?q=started%3A%7E7+definition%3Aruntime+name%3Arundownvalidation
20. ViktorHofer

    added

    blocking-clean-ciBlocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'

    on Sep 30, 2021
21. josalem commented on Sep 30, 2021

    

    josalem

    on Sep 30, 2021

    Contributor

    More actions

    Looking at the linked failures in the runfo page, I think there are two different failures and neither is the one tracked in this issue. If I recall, there's a different issue tracking the mono timeout failure that makes up the majority of them, but the two coreclr Windows x86 failures looks new. When I get back to my desk I'll see about rearranging things so the right issue is tracked.
22. josalem commented on Sep 30, 2021

    

    josalem

    on Sep 30, 2021

    Contributor

    More actions

    @ViktorHofer I think the problem that runfo is tracking in this Issue is actually #59296.

    CC @lateralusX since this appears to be affecting Mono
23. krwq commented on Oct 6, 2021

    

    krwq

    on Oct 6, 2021

    Member

    More actions

    Can this be disabled while investigation is pending? similarly to #59994
24. lateralusX commented on Oct 6, 2021

    

    lateralusX

    on Oct 6, 2021

    Member

    More actions

    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 #59296.

    👍React with 👍1Reacted by Krzysztof Wicher
25. lateralusX commented on Oct 6, 2021

    

    lateralusX

    on Oct 6, 2021

    Member

    More actions

    I add it to the exclude list as well.

    👍React with 👍1Reacted by Krzysztof Wicher
26. hoyosjs commented on Mar 9, 2022

    

    hoyosjs

    on Mar 9, 2022

    Member

    More actions

    The underlying issue has been fixed. The hits this month were for a PR.
27. hoyosjs

    closed this as completedon Mar 9, 2022
28. ghost locked as resolved and limited conversation to collaborators on Apr 8, 2022