[Win 7, Linux/x64] Tests fail with COMPlus_JitELTHookEnabled

[kvochko]

The following tests fail in Windows and Linux (with PR dotnet/coreclr#7719) builds of CoreCLR when COMPlus_JitELTHookEnabled environment variable is set to 1:

JIT/Methodical/Arrays/misc/_dbgarrres/_dbgarrres
JIT/Methodical/Arrays/misc/_relarrres/_relarrres
GC/API/GC/KeepAlive
GC/Scenarios/Samples/gc/gc
GC/Scenarios/LeakGen/leakgen/leakgen
GC/Scenarios/WeakReference/weakreffinal/weakreffinal

If we look at the KeepAlive test, after line 59 (https://github.com/dotnet/coreclr/blob/033b11d631f346a55c4d7c453bca1f49f77a44d5/tests/src/GC/API/GC/KeepAlive.cs#L59) object obj2 can be collected by GC. Without the COMPlus_JitELTHookEnabled, gcroot shows the following and, as expected, the object gets collected after line 61:

(lldb) gcroot 00007fff6006c3a0
Finalizer Queue:
    00007FFF6006C3A0
    -> 00007FFF6006C3A0 Test+Dummy2

With COMPlus_JitELTHookEnabled=1, gcroot shows:

(lldb) gcroot 00007fff6006c3a0
Thread 7338:
    00007FFFFFFFC880 00007FFF7D717F3E Test.RunTest() [/home/akvochko/projects/KeepAlive/KeepAlive.cs @ 60]
        rbp-30: 00007fffffffc880
            ->  00007FFF6006C3A0 Test+Dummy2

and the object does not get collected.
What could be the possible reason for this behavior? Is it correct to run this test with profiling enabled?
The remaining 5 tests show a similar behavior.

@janvorli @sivarv @BruceForstall
CC: @Dmitri-Botcharnikov @sergign60
category:correctness
theme:gc-info
skill-level:intermediate
cost:medium

[janvorli]

Could you please generate jitdump of the method using COMPlus_JitDump for both cases? the dump includes local variable liveness details that might give us a clue.

[kvochko]

@janvorli here are the jitdumps for both cases
COMPlus_JitELTHookDisabled.txt
COMPlus_JitELTHookEnabled.txt

[janvorli]

@kvochko, thank you. I can see several differences in the local variable lifetimes.
They start to occur after IN000d. Right after this line, the version without the hook has this:

New GC ref live vars=000000000000000C {V00 V01}
[0271C550] gcr var died at [rbp-18H]

While the other has nothing there.
The same case happens a bit later again after IN0015:

New GC ref live vars=000000000000000C {V00 V01}
[0271C6D8] gcr var died at [rbp-20H]

Then the version with the hook has this after IN001d while the version without the hook has nothing in there:

New GC ref live vars=000000000000000C {V00 V01}
[019428D0] gcr var died at [rbp-28H]
[01942A40] gcr var died at [rbp-30H]

Since the rbp offsets in the version with the hook are by 0x10 larger than the offsets in the version without the hook, it means that the version with the hook marked the two variables alive for longer time. Without the hook, they died before the System.GC.Collect call, with the hook, they died after the call to System.GC.KeepAlive.

[sergign60]

@janvorli
CC: @kvochko @Dmitri-Botcharnikov

Thank you very much for your explanation. Another question was: Is it correct to run this test with profiling enabled? Is such behaviour of the test correct or it should be fixed? If it should be fixed could you describe possible ways of fixing.

[janvorli]

@BruceForstall do you have any idea why would the fact that the COMPlus_JitELTHookEnabled is set cause the extension of the lifetime of the variable at [rbp-0x30], which causes the KeepAlive test to fail on both Windows and Unix AMD64? The added profiler hook calling code doesn't use or access those locals.
Links to jitdump with and without the hook are above.

[sergign60]

@janvorli @BruceForstall
CC: @kvochko @Dmitri-Botcharnikov

I removed profiling hook calls generating and r14&r15 saving that are used for argument passing into profiling hooks now, and got the following dumps:
JitELTHookDisabled.txt
JitELTHookEnabled.txt

JitELTHookDisabled.txt

IN0011: 000067 E8BCF8FFFF           call     Dummy2:.ctor():this
gcrReg +[rax]
IN0012: 00006C 488B45E0             mov      rax, gword ptr [rbp-20H]
IN0013: 000070 488945F0             mov      gword ptr [rbp-10H], rax
IN0014: 000074 33C0                 xor      rax, rax
IN0015: 000076 488945F0             mov      gword ptr [rbp-10H], rax
New GC ref live vars=000000000000000C {V00 V01}
[00FDEBA8] gcr var died at [rbp-20H]
New gcrReg live regs=00000000 {}
gcrReg -[rax]

JitELTHookEnabled.txt

IN0011: 000067 E8ACF8FFFF           call     Dummy2:.ctor():this
gcrReg +[rax]
IN0012: 00006C 488B45E0             mov      rax, gword ptr [rbp-20H]
IN0013: 000070 488945F0             mov      gword ptr [rbp-10H], rax
IN0014: 000074 33C0                 xor      rax, rax
IN0015: 000076 488945F0             mov      gword ptr [rbp-10H], rax
New gcrReg live regs=00000000 {}
gcrReg -[rax]

[janvorli]

@sergign60 I am not sure I understand the purpose of this change. Could you please explain it? I am also not sure why the registers were changed from R12, 13 to R14, 15.

[sergign60]

@janvorli There are some codes in the generator where R12&R13 (src/jit/codegencommon.cpp) are used for other purposes.

[janvorli]

@sergign60 so if I read the dumps it correctly, just setting the COMPlus_JitELTHookEnabled without actually generating any profiling hooks, the lifetime of those locals is still extended, right?

[sergign60]

@janvorli
Yes, the result is the same: with COMPlus_JitELTHookEnabled=1 the test fails because of the longer lifetime of obj2, with COMPlus_JitELTHookEnabled=0 - passes.

[janvorli]

Then JIT folks will need to explain if that's intended or unintended behavior. I can imagine that there could be some reason why during profiling, the lifetime would get extended - e.g. to allow the profiler to see the locals on the call stack.

[sergign60]

Actually, we have the different computations of GCvars: below are their dumps on call instructions

COMPlus_JitELTHookEnabled=0:

emitter::emitIns_Call CORINFO_HELP_DBG_IS_JUST_MY_CODE: GCvars=000000000000000F {V00 V01 V02 V03}
emitter::emitIns_Call CORINFO_HELP_NEWFAST: GCvars=000000000000000C {V00 V01}
emitter::emitIns_Call Dummy:.ctor():this: GCvars=000000000000000D {V00 V01 V02}
emitter::emitIns_Call CORINFO_HELP_NEWFAST: GCvars=000000000000000C {V00 V01}
emitter::emitIns_Call Dummy2:.ctor():this: GCvars=000000000000000E {V00 V01 V03}
emitter::emitIns_Call System.GC:Collect(): GCvars=000000000000000C {V00 V01}
emitter::emitIns_Call System.GC:WaitForPendingFinalizers(): GCvars=000000000000000C {V00 V01}
emitter::emitIns_Call System.GC:KeepAlive(ref): GCvars=000000000000000C {V00 V01}

COMPlus_JitELTHookEnabled=1:

emitter::emitIns_Call CORINFO_HELP_DBG_IS_JUST_MY_CODE: GCvars=000000000000000F {V00 V01 V02 V03}
emitter::emitIns_Call CORINFO_HELP_NEWFAST: GCvars=000000000000000C {V00 V01}
emitter::emitIns_Call Dummy:.ctor():this: GCvars=000000000000000D {V00 V01 V02}
emitter::emitIns_Call CORINFO_HELP_NEWFAST: GCvars=000000000000000D {V00 V01 V02}
emitter::emitIns_Call Dummy2:.ctor():this: GCvars=000000000000000F {V00 V01 V02 V03}
emitter::emitIns_Call System.GC:Collect(): GCvars=000000000000000F {V00 V01 V02 V03}
emitter::emitIns_Call System.GC:WaitForPendingFinalizers(): GCvars=000000000000000F {V00 V01 V02 V03}
emitter::emitIns_Call System.GC:KeepAlive(ref): GCvars=000000000000000F	 {V00 V01 V02 V03}

[sergign60]

dotnet/coreclr#9166

[gkhanna79]

CC @RussKeldorph

[RussKeldorph]

@BruceForstall @sivarv @briansull Does this sound unintended, or should we simply consider these tests invalid when profiling?
@dotnet/jit-contrib