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

[VincentBu]

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 ---

[mateoatr]

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

[BruceForstall]

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

[VincentBu]

Failed again in runtime-coreclr libraries-jitstress 20210714.1

Failed test:

net6.0-Linux-Release-arm-CoreCLR_checked-tailcallstress-(Ubuntu.1804.Arm32.Open)Ubuntu.1804.Armarch.Open@mcr.microsoft.com/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]

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]

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]

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.