search

dotnet / runtime

.NET is a cross-platform runtime for cloud, mobile, desktop, and IoT apps.
https://docs.microsoft.com/dotnet/core/
MIT License
14.56k stars 4.54k forks source link

[Question] JIT/Directed/debugging/debuginfo/tester fail with DOTNET_TieredCompilation=0 on Linux #104451

Open gbalykov opened 3 days ago

gbalykov commented 3 days ago

Test JIT/Directed/debugging/debuginfo/tester passes with tiered jit and other env vars specified for it:

export DOTNET_JitNoForwardSub=1
export DOTNET_JitEnableHeadTailMerge=0
export DOTNET_JitEnableCrossBlockLocalAssertionProp=0
export DOTNET_JitEnableOptRepeat=0

Output:

  0.0s: ==TEST STARTING==
  0.3s: Started sending sentinel events...
  0.3s: Connecting to EventPipe...
  0.5s: Creating EventPipeEventSource...
  0.5s: EventPipeEventSource created
  0.5s: Dynamic.All callback registered
  0.5s: Running optional trace validator
  0.6s: Finished running optional trace validator
  0.6s: Starting stream processing...
  0.6s: Saw new provider 'Microsoft-Windows-DotNETRuntime'
  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'
  0.9s: Saw new provider 'Microsoft-Windows-DotNETRuntimeRundown'
  1.0s: Stopping stream processing
  1.0s: Dropped 0 events
  1.0s: Finished StopTracing command
  1.0s: Reader task finished
  1.0s: Validating optional callback...
[tests_d]DebugInfoMethods.TestUninlined: Validate mappings for debuggable codegen (tier: MinOptJitted)
[tests_d]DebugInfoMethods.TestLateFailingInlineCandidate: Validate mappings for debuggable codegen (tier: MinOptJitted)
[tests_d]DebugInfoMethods.TestSucceedingInlineCandidate: Validate mappings for debuggable codegen (tier: MinOptJitted)
[tests_d]DebugInfoMethods.TestControlFlow: Validate mappings for debuggable codegen (tier: MinOptJitted)
[tests_r]DebugInfoMethods.TestUninlined: Validate mappings for optimized codegen (tier: QuickJitted)
[tests_r]DebugInfoMethods.TestLateFailingInlineCandidate: Validate mappings for optimized codegen (tier: QuickJitted)
[tests_r]DebugInfoMethods.TestSucceedingInlineCandidate: Validate mappings for optimized codegen (tier: QuickJitted)
[tests_r]DebugInfoMethods.TestControlFlow: Validate mappings for optimized codegen (tier: QuickJitted)
  1.0s: ==TEST FINISHED: PASSED!==

However, setting DOTNET_TieredCompilation=0 leads to fail:

  0.0s: ==TEST STARTING==
  0.5s: Started sending sentinel events...
  0.5s: Connecting to EventPipe...
  0.8s: Creating EventPipeEventSource...
  0.8s: EventPipeEventSource created
  0.8s: Dynamic.All callback registered
  0.8s: Running optional trace validator
  0.9s: Finished running optional trace validator
  0.9s: Starting stream processing...
  1.0s: Saw new provider 'Microsoft-Windows-DotNETRuntime'
  1.2s: Saw sentinel event
  1.2s: Stopped sending sentinel events
  1.2s: Starting event generating action...
  1.2s: Stopping event generating action
  1.2s: Sending StopTracing command...
  1.3s: Saw new provider 'Microsoft-DotNETCore-EventPipe'
  1.3s: Saw new provider 'Microsoft-Windows-DotNETRuntimeRundown'
  1.3s: Stopping stream processing
  1.3s: Dropped 0 events
  1.3s: Finished StopTracing command
  1.3s: Reader task finished
  1.3s: Validating optional callback...
[tests_d]DebugInfoMethods.TestUninlined: Validate mappings for debuggable codegen (tier: MinOptJitted)
[tests_d]DebugInfoMethods.TestLateFailingInlineCandidate: Validate mappings for debuggable codegen (tier: MinOptJitted)
[tests_d]DebugInfoMethods.TestSucceedingInlineCandidate: Validate mappings for debuggable codegen (tier: MinOptJitted)
[tests_d]DebugInfoMethods.TestControlFlow: Validate mappings for debuggable codegen (tier: MinOptJitted)
[tests_r]DebugInfoMethods.TestUninlined: Validate mappings for optimized codegen (tier: Optimized)
[tests_r]DebugInfoMethods.TestLateFailingInlineCandidate: Validate mappings for optimized codegen (tier: Optimized)
[tests_r]DebugInfoMethods.TestSucceedingInlineCandidate: Validate mappings for optimized codegen (tier: Optimized)
[tests_r]DebugInfoMethods.TestControlFlow: Validate mappings for optimized codegen (tier: Optimized)
  Validation failed: expected mappings at IL offsets 000, 006, 00e, 012, 01c, 02c
  Actual (IL <-> native):
    Prolog <-> 000
    000 <-> 008
    012 <-> 00c
    02c <-> 020
    034 <-> 032
    Epilog <-> 032
  1.3s: ==TEST FINISHED: FAILED!==
Xunit.Sdk.EqualException: Assert.Equal() Failure: Values differ
Expected: 100
Actual:   -1
   at Xunit.Assert.Equal[T](T expected, T actual, IEqualityComparer`1 comparer) in /_/src/Microsoft.DotNet.XUnitAssert/src/EqualityAsserts.cs:line 168
   at __GeneratedMainWrapper.Main() in /home/runtime/artifacts/tests/coreclr/obj/linux.x64.Release/Managed/JIT/Directed/debugging/debuginfo/tester/XUnitWrapperGenerator/XUnitWrapperGenerator.XUnitWrapperGenerator/SimpleRunner.g.cs:line 10

This happens independently from architecture. According to original PR that added it (https://github.com/dotnet/runtime/pull/61962), README and other files, it seems that it should support such mode. Looks like now debug info generated for Optimized differs from QuickJitted and MinOptJitted and test seems to need update for such case. Is this correct?

Build of e78b72b1fdf43d9678877400bcfe801b38c14681:

./build.sh --arch x64 --runtimeConfiguration Release --librariesConfiguration Release --subset clr+libs
BuildAllTestsAsStandalone=true ./src/tests/build.sh -Release -x64 -priority1

cc @jakobbotsch @dotnet/samsung

dotnet-policy-service[bot] commented 3 days ago

Tagging subscribers to this area: @JulieLeeMSFT, @jakobbotsch See info in area-owners.md if you want to be subscribed.

jakobbotsch commented 2 days ago

Looks like now debug info generated for Optimized differs from QuickJitted and MinOptJitted and test seems to need update for such case. Is this correct?

The test already has different debug info expected for unoptimized and optimized versions of the test cases. It's odd that we do not see this failing in our CI if it really does fail with TieredCompilation=0. CI should be running this test with TC=0 regularly.

gbalykov commented 2 days ago

CI should be running this test with TC=0 regularly.

Is this done for each PR or some weekly testing? For example, I've tried to find such test in https://github.com/dotnet/runtime/pull/104432 and it seems it wasn't run there (please correct me if I'm wrong). Note that this issue happens only with release build of runtime and tests, and not sure if this test is part of pri0 or not.

jakobbotsch commented 2 days ago

Is this done for each PR or some weekly testing? For example, I've tried to find such test in #104432 and it seems it wasn't run there (please correct me if I'm wrong).

The test is part of Directed_3. Here is the run of Directed_3 with DOTNET_TieredCompilation=0 in that PR: https://helixre107v0xdcypoyl9e7f.blob.core.windows.net/dotnet-runtime-refs-pull-104432-merge-c83008598e104e0fb6/Directed_3/1/console.ef8e5326.log?helixlogtype=result

14:29:18.611 Running test: JIT/Directed/debugging/debuginfo/tester/tester.cmd

Return code:      0
Raw output file:      C:\h\w\A26508E8\w\AFDE09A2\uploads\debugging\debuginfo\tester\output.txt
Raw output:
BEGIN EXECUTION
 "C:\h\w\A26508E8\p\corerun.exe" -p "System.Reflection.Metadata.MetadataUpdater.IsSupported=false" -p "System.Runtime.Serialization.EnableUnsafeBinaryFormatterSerialization=true"  tester.dll 
  0.0s: ==TEST STARTING==
  0.6s: Started sending sentinel events...
  0.7s: Connecting to EventPipe...
  1.2s: Creating EventPipeEventSource...
  1.3s: EventPipeEventSource created
  1.3s: Dynamic.All callback registered
  1.3s: Running optional trace validator
  1.8s: Finished running optional trace validator
  1.8s: Starting stream processing...
  2.1s: Saw new provider 'Microsoft-Windows-DotNETRuntime'
  2.9s: Saw sentinel event
  2.9s: Stopped sending sentinel events
  2.9s: Starting event generating action...
  3.0s: Stopping event generating action
  3.0s: Sending StopTracing command...
  3.1s: Saw new provider 'Microsoft-DotNETCore-EventPipe'
  3.3s: Saw new provider 'Microsoft-Windows-DotNETRuntimeRundown'
  3.3s: Stopping stream processing
  3.3s: Dropped 0 events
  3.3s: Finished StopTracing command
  3.3s: Reader task finished
  3.3s: Validating optional callback...
[tests_d]DebugInfoMethods.TestUninlined: Validate mappings for debuggable codegen (tier: MinOptJitted)
[tests_d]DebugInfoMethods.TestLateFailingInlineCandidate: Validate mappings for debuggable codegen (tier: MinOptJitted)
[tests_d]DebugInfoMethods.TestSucceedingInlineCandidate: Validate mappings for debuggable codegen (tier: MinOptJitted)
[tests_d]DebugInfoMethods.TestControlFlow: Validate mappings for debuggable codegen (tier: MinOptJitted)
[tests_r]DebugInfoMethods.TestUninlined: Validate mappings for optimized codegen (tier: Optimized)
[tests_r]DebugInfoMethods.TestLateFailingInlineCandidate: Validate mappings for optimized codegen (tier: Optimized)
[tests_r]DebugInfoMethods.TestSucceedingInlineCandidate: Validate mappings for optimized codegen (tier: Optimized)
[tests_r]DebugInfoMethods.TestControlFlow: Validate mappings for optimized codegen (tier: Optimized)
  3.4s: ==TEST FINISHED: PASSED!==
Expected: 100
Actual: 100
END EXECUTION - PASSED
PASSED

On PRs we run all tests with DOTNET_TieredCompilation=0, while on rolling builds (twice a day I believe) we run with both DOTNET_TieredCompilation=0 and DOTNET_TieredCompilation=1.

Note that this issue happens only with release build of runtime and tests, and not sure if this test is part of pri0 or not.

Does the failure reproduce with release builds but not with checked builds? That would definitely be something to investigate.

gbalykov commented 2 days ago

Does the failure reproduce with release builds but not with checked builds?

I did some more testing with DOTNET_TieredCompilation=0:

jakobbotsch commented 2 days ago

Ok, that needs to be investigated. Definitely seems like it has been failing for a while (https://dev.azure.com/dnceng-public/public/_build?definitionId=135&_a=summary has the failures).