Test Failure:Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.TestBaseline_TestWithTwoParams_Success #55253

VincentBu · 2021-07-07T07:24:51Z

Run runtime-coreclr libraries-jitstress 20210706.1

Failed tests:

net6.0-windows-Release-arm64-CoreCLR_checked-tailcallstress-Windows.10.Arm64v8.Open

- Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.TestBaseline_TestWithTwoParams_Success(argumentList: \"0, LogLevel.Error, \\\"M0 {a1} {a2}\\\", SkipEnabledCh\"...)
- Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.TestBaseline_TestWithTwoParams_Success(argumentList: \"0, LogLevel.Error, \\\"M0 {a1} {a2}\\\"\")
- Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.TestBaseline_TestWithTwoParams_Success(argumentList: \"eventId: 0, level: LogLevel.Error, message: \\\"M0 {\"...)
- Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.TestBaseline_TestWithNestedClass_Success
- Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.TestBaseline_TestWithSkipEnabledCheck_Success

One of error messages

Line 9 does not match.
Expected Line:
global::Microsoft.Extensions.Logging.LoggerMessage.Define(global::Microsoft.Extensions.Logging.LogLevel.Information, new global::Microsoft.Extensions.Logging.EventId(0, nameof(M0)), "Message: When using SkipEnabledCheck, the generated code skips logger.IsEnabled(logLevel) check before calling log. To be used when consumer has already guarded logger method in an IsEnabled check.", true);
Actual Line:
global::Microsoft.Extensions.Logging.LoggerMessage.Define(global::Microsoft.Extensions.Logging.LogLevel.Information, new global::Microsoft.Extensions.Logging.EventId(-256, nameof(M0)), "Message: When using SkipEnabledCheck, the generated code skips logger.IsEnabled(logLevel) check before calling log. To be used when consumer has already guarded logger method in an IsEnabled check.", true);
Expected: True
Actual:   False


Stack trace
   at Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.VerifyAgainstBaselineUsingFile(String filename, String testSourceCode) in /_/src/libraries/Microsoft.Extensions.Logging.Abstractions/tests/Microsoft.Extensions.Logging.Generators.Tests/LoggerMessageGeneratorEmitterTests.cs:line 164
   at Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.TestBaseline_TestWithSkipEnabledCheck_Success() in /_/src/libraries/Microsoft.Extensions.Logging.Abstractions/tests/Microsoft.Extensions.Logging.Generators.Tests/LoggerMessageGeneratorEmitterTests.cs:line 49
--- End of stack trace from previous location ---

The text was updated successfully, but these errors were encountered:

mateoatr · 2021-07-07T15:15:11Z

The failure is also present in win10 amd64 (net6.0-windows-Release-x64-CoreCLR_checked-tailcallstress-Windows.10.Amd64.Open).

BruceForstall · 2021-07-07T17:15:03Z

@jakobbotsch this is apparently a new failure only in tailcallstress mode

VincentBu · 2021-07-15T01:42:37Z

Failed again in runtime-coreclr libraries-jitstress 20210714.1

Failed test:

net6.0-Linux-Release-arm-CoreCLR_checked-tailcallstress-(Ubuntu.1804.Arm32.Open)[email protected]/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm32v7-bfcd90a-20200121150440

Error message:

Line 9 does not match.
Expected Line:
global::Microsoft.Extensions.Logging.LoggerMessage.Define<global::System.Int32, global::System.Collections.Generic.IEnumerableglobal::System.Int32>(global::Microsoft.Extensions.Logging.LogLevel.Error, new global::Microsoft.Extensions.Logging.EventId(0, nameof(M0)), "M0 {a1} {a2}", new global::Microsoft.Extensions.Logging.LogDefineOptions() { SkipEnabledCheck = true });
Actual Line:
global::Microsoft.Extensions.Logging.LoggerMessage.Define<global::System.Int32, global::System.Collections.Generic.IEnumerableglobal::System.Int32>(global::Microsoft.Extensions.Logging.LogLevel.Error, new global::Microsoft.Extensions.Logging.EventId(-256, nameof(M0)), "M0 {a1} {a2}", new global::Microsoft.Extensions.Logging.LogDefineOptions() { SkipEnabledCheck = true });
Expected: True
Actual:   False


Stack trace
   at Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.VerifyAgainstBaselineUsingFile(String filename, String testSourceCode) in /_/src/libraries/Microsoft.Extensions.Logging.Abstractions/tests/Microsoft.Extensions.Logging.Generators.Tests/LoggerMessageGeneratorEmitterTests.cs:line 164
   at Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.TestBaseline_TestWithTwoParams_Success(String argumentList) in /_/src/libraries/Microsoft.Extensions.Logging.Abstractions/tests/Microsoft.Extensions.Logging.Generators.Tests/LoggerMessageGeneratorEmitterTests.cs:line 83
--- End of stack trace from previous location ---

jakobbotsch · 2021-07-15T12:31:59Z

This seems to be caused by #54864 in combination with portable tailcall helpers. There are two functions in Roslyn, Microsoft.CodeAnalysis.ConstantValue:get_Int16Value() and Microsoft.CodeAnalysis.ConstantValue:get_Int32Value that normally generate the following code:

  ; Assembly listing for method Microsoft.CodeAnalysis.ConstantValue:get_Int16Value():short:this
  ; Emitting BLENDED_CODE for X64 CPU with AVX - Windows
  ; Tier-0 compilation
  ; MinOpts code
  ; rbp based frame
  ; partially interruptible
  ; Final local variable assignments
  ;
  ;  V00 this         [V00    ] (  1,  1   )     ref  ->  [rbp+10H]   do-not-enreg[] this class-hnd
  ;  V01 OutArgs      [V01    ] (  1,  1   )  lclBlk (32) [rsp+00H]   do-not-enreg[] "OutgoingArgSpace"
  ;
  ; Lcl frame size = 32

  G_M47293_IG01:              ;; offset=0000H
         55                   push     rbp
         4883EC20             sub      rsp, 32
         488D6C2420           lea      rbp, [rsp+20H]
         48894D10             mov      gword ptr [rbp+10H], rcx
                                                ;; bbWeight=1    PerfScore 2.75
  G_M47293_IG02:              ;; offset=000EH
         488B4D10             mov      rcx, gword ptr [rbp+10H]
         488B4510             mov      rax, gword ptr [rbp+10H]
         488B00               mov      rax, qword ptr [rax]
         488B4050             mov      rax, qword ptr [rax+80]
         FF5008               call     qword ptr [rax+8]Microsoft.CodeAnalysis.ConstantValue:get_SByteValue():byte:this
         90                   nop
                                                ;; bbWeight=1    PerfScore 9.25
  G_M47293_IG03:              ;; offset=0021H
         4883C420             add      rsp, 32
         5D                   pop      rbp
         C3                   ret
                                                ;; bbWeight=1    PerfScore 1.75

  ; Total bytes of code 39, prolog size 10, PerfScore 17.65, instruction count 13, allocated bytes for code 39 (MethodHash=19b84742) for method Microsoft.CodeAnalysis.ConstantValue:get_Int16Value():short:this

  ; Assembly listing for method Microsoft.CodeAnalysis.ConstantValue:get_Int32Value():int:this
  ; Emitting BLENDED_CODE for X64 CPU with AVX - Windows
  ; Tier-0 compilation
  ; MinOpts code
  ; rbp based frame
  ; partially interruptible
  ; Final local variable assignments
  ;
  ;  V00 this         [V00    ] (  1,  1   )     ref  ->  [rbp+10H]   do-not-enreg[] this class-hnd
  ;  V01 OutArgs      [V01    ] (  1,  1   )  lclBlk (32) [rsp+00H]   do-not-enreg[] "OutgoingArgSpace"
  ;
  ; Lcl frame size = 32

  G_M24922_IG01:              ;; offset=0000H
         55                   push     rbp
         4883EC20             sub      rsp, 32
         488D6C2420           lea      rbp, [rsp+20H]
         48894D10             mov      gword ptr [rbp+10H], rcx
                                                ;; bbWeight=1    PerfScore 2.75
  G_M24922_IG02:              ;; offset=000EH
         488B4D10             mov      rcx, gword ptr [rbp+10H]
         488B4510             mov      rax, gword ptr [rbp+10H]
         488B00               mov      rax, qword ptr [rax]
         488B4050             mov      rax, qword ptr [rax+80]
         FF5018               call     qword ptr [rax+24]Microsoft.CodeAnalysis.ConstantValue:get_Int16Value():short:this
         90                   nop
                                                ;; bbWeight=1    PerfScore 9.25
  G_M24922_IG03:              ;; offset=0021H
         4883C420             add      rsp, 32
         5D                   pop      rbp
         C3                   ret
                                                ;; bbWeight=1    PerfScore 1.75

  ; Total bytes of code 39, prolog size 10, PerfScore 17.65, instruction count 13, allocated bytes for code 39 (MethodHash=b24d9ea5) for method Microsoft.CodeAnalysis.ConstantValue:get_Int32Value():int:this

After #54864 they are considered return type compatible and in tailcall stress end up using tailcall-via-helper. The code generated is:

; Assembly listing for method Microsoft.CodeAnalysis.ConstantValue:get_Int16Value():short:this
  ; Emitting BLENDED_CODE for X64 CPU with AVX - Windows
  ; Tier-0 compilation
  ; MinOpts code
  ; rbp based frame
  ; partially interruptible
  ; Final local variable assignments
  ;
  ;  V00 this         [V00    ] (  1,  1   )     ref  ->  [rbp+10H]   do-not-enreg[] this class-hnd
  ;  V01 OutArgs      [V01    ] (  1,  1   )  lclBlk (32) [rsp+00H]   do-not-enreg[] "OutgoingArgSpace"
  ;  V02 tmp1         [V02    ] (  1,  1   )    byte  ->  [rbp-04H]   do-not-enreg[XB] addr-exposed "Return value for tail call dispatcher"
  ;  V03 ReturnAddress[V03    ] (  1,  1   )    long  ->  [rbp+08H]   do-not-enreg[XB] addr-exposed "Return address"
  ;
  ; Lcl frame size = 48

  G_M47293_IG01:              ;; offset=0000H
         55                   push     rbp
         4883EC30             sub      rsp, 48
         488D6C2430           lea      rbp, [rsp+30H]
         48894D10             mov      gword ptr [rbp+10H], rcx
                                                ;; bbWeight=1    PerfScore 2.75
  G_M47293_IG02:              ;; offset=000EH
         488B4D10             mov      rcx, gword ptr [rbp+10H]
         E801F1FFFF           call     ILStubClass:IL_STUB_StoreTailCallArgs(System.Object)
         488D4D08             lea      rcx, bword ptr [rbp+08H]
         4C8D45FC             lea      r8, bword ptr [rbp-04H]
         48BA4878710FFF7F0000 mov      rdx, 0x7FFF0F717848
         E812C06CF8           call     System.Runtime.CompilerServices.RuntimeHelpers:DispatchTailCalls(long,long,long)
         8B45FC               mov      eax, dword ptr [rbp-04H]
         480FBEC0             movsx    rax, al
                                                ;; bbWeight=1    PerfScore 5.50
  G_M47293_IG03:              ;; offset=0035H
         4883C430             add      rsp, 48
         5D                   pop      rbp
         C3                   ret
                                                ;; bbWeight=1    PerfScore 1.75

  ; Total bytes of code 59, prolog size 10, PerfScore 15.90, instruction count 15, allocated bytes for code 59 (MethodHash=19b84742) for method Microsoft.CodeAnalysis.ConstantValue:get_Int16Value():short:this

; Assembly listing for method Microsoft.CodeAnalysis.ConstantValue:get_Int32Value():int:this
  ; Emitting BLENDED_CODE for X64 CPU with AVX - Windows
  ; Tier-0 compilation
  ; MinOpts code
  ; rbp based frame
  ; partially interruptible
  ; Final local variable assignments
  ;
  ;  V00 this         [V00    ] (  1,  1   )     ref  ->  [rbp+10H]   do-not-enreg[] this class-hnd
  ;  V01 OutArgs      [V01    ] (  1,  1   )  lclBlk (32) [rsp+00H]   do-not-enreg[] "OutgoingArgSpace"
  ;  V02 tmp1         [V02    ] (  1,  1   )   short  ->  [rbp-04H]   do-not-enreg[XB] addr-exposed "Return value for tail call dispatcher"
  ;  V03 ReturnAddress[V03    ] (  1,  1   )    long  ->  [rbp+08H]   do-not-enreg[XB] addr-exposed "Return address"
  ;
  ; Lcl frame size = 48

  G_M24922_IG01:              ;; offset=0000H
         55                   push     rbp
         4883EC30             sub      rsp, 48
         488D6C2430           lea      rbp, [rsp+30H]
         48894D10             mov      gword ptr [rbp+10H], rcx
                                                ;; bbWeight=1    PerfScore 2.75
  G_M24922_IG02:              ;; offset=000EH
         488B4D10             mov      rcx, gword ptr [rbp+10H]
         E8D1F1FFFF           call     ILStubClass:IL_STUB_StoreTailCallArgs(System.Object)
         488D4D08             lea      rcx, bword ptr [rbp+08H]
         4C8D45FC             lea      r8, bword ptr [rbp-04H]
         48BA2878710FFF7F0000 mov      rdx, 0x7FFF0F717828
         E802C16CF8           call     System.Runtime.CompilerServices.RuntimeHelpers:DispatchTailCalls(long,long,long)
         8B45FC               mov      eax, dword ptr [rbp-04H]
         480FBFC0             movsx    rax, ax
                                                ;; bbWeight=1    PerfScore 5.50
  G_M24922_IG03:              ;; offset=0035H
         4883C430             add      rsp, 48
         5D                   pop      rbp
         C3                   ret
                                                ;; bbWeight=1    PerfScore 1.75

  ; Total bytes of code 59, prolog size 10, PerfScore 15.90, instruction count 15, allocated bytes for code 59 (MethodHash=b24d9ea5) for method Microsoft.CodeAnalysis.ConstantValue:get_Int32Value():int:this

Still tracing down why this is problematic, seems like the sign extensions being done should be ok.

jakobbotsch · 2021-07-15T12:45:53Z

Small repro:

using System;

class Runtime_55253
{
    static int Main()
    {
        Console.WriteLine(AsInt32());
        return 0;
    }

    public static int AsInt32() => AsInt16();
    public static short AsInt16() => AsInt8();
    public static sbyte AsInt8() => -1;
}

Prints 255 with $env:COMPlus_TailcallStress=1 and -1 without.

jakobbotsch · 2021-07-15T12:52:42Z

The problem is that CallTailCallTarget stubs are not writing normalized (widened) values to the arg buffer. It means that on the second tailcall, i.e. when AsInt8() is done, the stub only stores (sbyte)-1 to the arg buffer. Then the return value is loaded in the first dispatcher as a 16-bit value and things go wrong.
The call-tail-call-target stub needs to do the same normalization as the JIT would do when return values are stored.

In the managed calling convention the callee is responsible for widening the return value up to 4 bytes. We need to mimic this in portable tailcall helpers as the JIT cannot know which call eventually produced the value that was stored in the return value buffer passed to the dispatcher. Fix dotnet#55253

It is a runtime detail that the managed calling convention widens return values, so only allow this behavior for opportunistic tailcalls. Fix dotnet#55253

It is a runtime detail that the managed calling convention widens return values, so only allow this behavior for opportunistic tailcalls. Fix #55253

VincentBu added arch-arm64 os-windows JitStress CLR JIT issues involving JIT internal stress modes labels Jul 7, 2021

jeffschwMSFT added the area-CodeGen-coreclr CLR JIT compiler in src/coreclr/src/jit and related components such as SuperPMI label Jul 7, 2021

JulieLeeMSFT assigned jakobbotsch Jul 8, 2021

JulieLeeMSFT added this to the 6.0.0 milestone Jul 8, 2021

jakobbotsch mentioned this issue Jul 15, 2021

Widen return values in CallTailCallTarget stubs #55740

Closed

ghost added the in-pr There is an active PR which will close this issue when it is merged label Jul 15, 2021

jakobbotsch added a commit to jakobbotsch/runtime that referenced this issue Jul 20, 2021

Disallow widening for explicit tailcalls

c5fa991

It is a runtime detail that the managed calling convention widens return values, so only allow this behavior for opportunistic tailcalls. Fix dotnet#55253

jakobbotsch mentioned this issue Jul 20, 2021

Disallow widening for explicit tailcalls #55989

Merged

jakobbotsch closed this as completed in #55989 Jul 21, 2021

jakobbotsch added a commit that referenced this issue Jul 21, 2021

Disallow widening for explicit tailcalls (#55989)

94a8430

It is a runtime detail that the managed calling convention widens return values, so only allow this behavior for opportunistic tailcalls. Fix #55253

ghost removed the in-pr There is an active PR which will close this issue when it is merged label Jul 21, 2021

ghost locked as resolved and limited conversation to collaborators Aug 20, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Test Failure:Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.TestBaseline_TestWithTwoParams_Success #55253

Test Failure:Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.TestBaseline_TestWithTwoParams_Success #55253

VincentBu commented Jul 7, 2021

mateoatr commented Jul 7, 2021

Uh oh!

BruceForstall commented Jul 7, 2021

Uh oh!

VincentBu commented Jul 15, 2021

Uh oh!

jakobbotsch commented Jul 15, 2021

Uh oh!

jakobbotsch commented Jul 15, 2021 •

edited

Loading

Uh oh!

jakobbotsch commented Jul 15, 2021

Uh oh!

Test Failure:Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.TestBaseline_TestWithTwoParams_Success #55253

Test Failure:Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorEmitterTests.TestBaseline_TestWithTwoParams_Success #55253

Comments

VincentBu commented Jul 7, 2021

mateoatr commented Jul 7, 2021

Uh oh!

BruceForstall commented Jul 7, 2021

Uh oh!

VincentBu commented Jul 15, 2021

Uh oh!

jakobbotsch commented Jul 15, 2021

Uh oh!

jakobbotsch commented Jul 15, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jakobbotsch commented Jul 15, 2021

Uh oh!

jakobbotsch commented Jul 15, 2021 •

edited

Loading