Test failure: readytorun/coreroot_determinism/coreroot_determinism/coreroot_determinism.cmd

[amanasifkhalid]

Failed in runtime-jit-experimental on Linux x64.

Error message:

1 / 1 (100%, 1 failed): failed in 18056 msecs, exit code 139, expected 0: corerun /datadisks/disk1/work/AD5609CC/p/crossgen2/crossgen2.dll @/datadisks/disk1/work/AD5609CC/w/BD9609A8/e/readytorun/coreroot_determinism/coreroot_determinism/seed2/CPAOT-ret.out/System.Private.CoreLib.dll.rsp
  [createdump] Gathering state for process 3993 corerun
  [createdump] Crashing thread 0f99 signal 11 (000b)
  [createdump] Writing crash report to file /home/helixbot/dotnetbuild/dumps/coredump.3993.dmp.crashreport.json
  [createdump] Crash report successfully written
  [createdump] Writing minidump with heap to file /home/helixbot/dotnetbuild/dumps/coredump.3993.dmp
  [createdump] Written 202219520 bytes (49370 pages) to core file
  [createdump] Target process is alive
  [createdump] Dump successfully written in 1111ms

Return code:      1
Raw output file:      /datadisks/disk1/work/AD5609CC/w/BD9609A8/uploads/coreroot_determinism/output.txt
Raw output:
BEGIN EXECUTION
/datadisks/disk1/work/AD5609CC/p/corerun -p System.Reflection.Metadata.MetadataUpdater.IsSupported=false -p System.Runtime.Serialization.EnableUnsafeBinaryFormatterSerialization=true coreroot_determinism.dll ''
================================== Compiling with seed 1 ==================================
Locating output folder /datadisks/disk1/work/AD5609CC/w/BD9609A8/e/readytorun/coreroot_determinism/coreroot_determinism/seed1
Deleting 0 output folders
Successfully deleted 0 output folders in 175 msecs
Using dotnet: /datadisks/disk1/work/AD5609CC/p/corerun
1 / 1 (0%, 0 failed): launching: /datadisks/disk1/work/AD5609CC/p/corerun /datadisks/disk1/work/AD5609CC/p/crossgen2/crossgen2.dll @/datadisks/disk1/work/AD5609CC/w/BD9609A8/e/readytorun/coreroot_determinism/coreroot_determinism/seed1/CPAOT-ret.out/System.Private.CoreLib.dll.rsp
1 / 1 (100%, 0 failed): succeeded in 75047 msecs: corerun /datadisks/disk1/work/AD5609CC/p/crossgen2/crossgen2.dll @/datadisks/disk1/work/AD5609CC/w/BD9609A8/e/readytorun/coreroot_determinism/coreroot_determinism/seed1/CPAOT-ret.out/System.Private.CoreLib.dll.rsp
================================== Compiling with seed 2 ==================================
Locating output folder /datadisks/disk1/work/AD5609CC/w/BD9609A8/e/readytorun/coreroot_determinism/coreroot_determinism/seed2
Deleting 0 output folders
Successfully deleted 0 output folders in 78 msecs
Using dotnet: /datadisks/disk1/work/AD5609CC/p/corerun
1 / 1 (0%, 0 failed): launching: /datadisks/disk1/work/AD5609CC/p/corerun /datadisks/disk1/work/AD5609CC/p/crossgen2/crossgen2.dll @/datadisks/disk1/work/AD5609CC/w/BD9609A8/e/readytorun/coreroot_determinism/coreroot_determinism/seed2/CPAOT-ret.out/System.Private.CoreLib.dll.rsp
Compilation failed. /datadisks/disk1/work/AD5609CC/p/corerun /datadisks/disk1/work/AD5609CC/p/R2RTest/R2RTest.dll compile-directory -cr /datadisks/disk1/work/AD5609CC/p -in TestAssemblies --nojit --noexe --large-bubble --release --nocleanup -out seed2 failed with exit code 1
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 Xunit.Assert.Equal[T](T expected, T actual) in /_/src/Microsoft.DotNet.XUnitAssert/src/EqualityAsserts.cs:line 90
   at __GeneratedMainWrapper.Main()
Expected: 100
Actual: 101
END EXECUTION - FAILED

cc @dotnet/jit-contrib.

[dotnet-policy-service]

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

[jakobbotsch]

This only failed once, so I'm going to unmark it as blocking (also doesn't repro easily it looks like).

[jakobbotsch]

From the dump it definitely looks OSR related. The stack trace looks like the following:

(lldb) clrstack -f
OS Thread Id: 0xf99 (1)
        Child SP               IP Call Site
000072F82D64AFA0 000072F82D077613 libc.so.6!___lldb_unnamed_symbol3325 + 115
000072F82D64D100 000072F82D0606CA libc.so.6!fprintf + 154
000072F82D64D1E0 000072F82CEB4787 libcoreclr.so!PROCCreateCrashDump(std::vector<char const*, std::allocator<char const*> >&, char*, int, bool) + 1111 at /__w/1/s/src/coreclr/pal/src/thread/process.cpp:2320
000072F82D64D250 000072F82CEB5A8E libcoreclr.so!PROCCreateCrashDumpIfEnabled + 2942 at /__w/1/s/src/coreclr/pal/src/thread/process.cpp:0
000072F82D64D2E0 000072F82CE533A9 libcoreclr.so!invoke_previous_action(sigaction*, int, siginfo_t*, void*, bool) + 377 at /__w/1/s/src/coreclr/pal/src/exception/signal.cpp:397
000072F82D64D330 000072F82CE525F5 libcoreclr.so!sigsegv_handler(int, siginfo_t*, void*) + 341 at /__w/1/s/src/coreclr/pal/src/exception/signal.cpp:631
000072F82D64D380 000072F82D042520 libc.so.6!___lldb_unnamed_symbol3237 + 1
00007FFF40434DC8 0000000000000000
00007FFF40434DD0 000072F7B0BDA404
00007FFF40434E80 000072F7B0BDAEBF
00007FFF40434EC0 000072F7B0BD46D4
00007FFF404350D0 000072F7B0B8BCD2
00007FFF40435170 000072F7B0B7D6E0

(not sure why managed names are missing. Opened dotnet/diagnostics#4637.)

The previous valid return address is:

(lldb) ip2md 72F7B0BDA404
MethodDesc:   000072f7b0a57a90
Method Name:          ILCompiler.LazyGenericsSupport+GraphBuilder.<.ctor>g__AddProcessType|0_1(Internal.TypeSystem.TypeDesc, <>c__DisplayClass0_0 ByRef)
Class:                000072f7b0a621e8
MethodTable:          000072f7b0a57bc8
mdToken:              0000000006000DB6
Module:               000072f7af160888
IsJitted:             yes
Current CodeAddr:     000072f7b0bda3a0
Version History:
  ILCodeVersion:      0000000000000000
  ReJIT ID:           0
  IL Addr:            000072f7ac0b796c
     CodeAddr:           000072f7b0916f40  (OptimizedTier1OSR)
     NativeCodeVersion:  00005C2444DC3C00
     CodeAddr:           000072f7b0bda3a0  (QuickJitted + Instrumented)
     NativeCodeVersion:  000072B6F8589A80
     CodeAddr:           000072f7b0bdb4c0  (OptimizedTier1OSR)
     NativeCodeVersion:  00005C2444DE84A0
     CodeAddr:           0000000000000000  (OptimizedTier1)
     NativeCodeVersion:  000072B6F86842E0
     CodeAddr:           000072f7b08f0640  (QuickJitted)
     NativeCodeVersion:  0000000000000000
...
(lldb) clru 72F7B0BDA404
Normal JIT generated code
ILCompiler.LazyGenericsSupport+GraphBuilder.<.ctor>g__AddProcessType|0_1(Internal.TypeSystem.TypeDesc, <>c__DisplayClass0_0 ByRef)
ilAddr is 000072F7AC0B796C pImport is 000000000427EC30
Begin 000072F7B0BDA3A0, size 26d
000072f7b0bda3a0 55                   push    rbp
000072f7b0bda3a1 4881eca0000000       sub     rsp, 0xa0
000072f7b0bda3a8 488dac24a0000000     lea     rbp, [rsp + 0xa0]
000072f7b0bda3b0 c4413857c0           vxorps  xmm8, xmm8, xmm8
000072f7b0bda3b5 c57e7f8560ffffff     vmovdqu ymmword ptr [rbp - 0xa0], ymm8
000072f7b0bda3bd c57e7f4580           vmovdqu ymmword ptr [rbp - 0x80], ymm8
000072f7b0bda3c2 c57e7f45a0           vmovdqu ymmword ptr [rbp - 0x60], ymm8
000072f7b0bda3c7 33c0                 xor     eax, eax
000072f7b0bda3c9 488945c0             mov     qword ptr [rbp - 0x40], rax
000072f7b0bda3cd 48897dd0             mov     qword ptr [rbp - 0x30], rdi
000072f7b0bda3d1 488975c8             mov     qword ptr [rbp - 0x38], rsi
000072f7b0bda3d5 c78578ffffff01000000 mov     dword ptr [rbp - 0x88], 0x1
000072f7b0bda3df 8b8578ffffff         mov     eax, dword ptr [rbp - 0x88]
000072f7b0bda3e5 ffc8                 dec     eax
000072f7b0bda3e7 898578ffffff         mov     dword ptr [rbp - 0x88], eax
000072f7b0bda3ed 83bd78ffffff00       cmp     dword ptr [rbp - 0x88], 0x0
000072f7b0bda3f4 7f0e                 jg      0x72f7b0bda404
000072f7b0bda3f6 488dbd78ffffff       lea     rdi, [rbp - 0x88]
000072f7b0bda3fd 33f6                 xor     esi, esi
000072f7b0bda3ff e82ce1ee7b           call    0x72f82cac8530 (JitHelp: CORINFO_HELP_PATCHPOINT)
>>> 000072f7b0bda404 488b7dd0             mov     rdi, qword ptr [rbp - 0x30]
000072f7b0bda408 33f6                 xor     esi, esi

So seems like something went wrong while transitioning from the patchpoint.

@AndyAyersMS do you have any thoughts? I don't suppose there are some diagnostics available to e.g. obtain the particular PerPatchpointInfo relevant here?

[jakobbotsch]

The PerPatchpointInfo is this one:

(lldb) p *(PerPatchpointInfo*)0x000072f7b0cc0638
(PerPatchpointInfo) $17 = {
  m_osrMethodCode = 126408147711168
  m_patchpointCount = 2
  m_flags = 1
  m_patchpointId = 1538
}

That method code corresponds to

     CodeAddr:           000072f7b0bdb4c0  (OptimizedTier1OSR)
     NativeCodeVersion:  00005C2444DE84A0

seen above. Unclear whether the issue here is OSR related or whether something bad just happened after transitioning.

[jakobbotsch]

This is the code for the OSR version:

(lldb) clru 72f7b0bdb4c0
Normal JIT generated code
ILCompiler.LazyGenericsSupport+GraphBuilder.<.ctor>g__AddProcessType|0_1(Internal.TypeSystem.TypeDesc, <>c__DisplayClass0_0 ByRef)
ilAddr is 000072F7AC0B796C pImport is 00007ECC5801F550
Begin 000072F7B0BDB4C0, size 147
>>> 000072f7b0bdb4c0 488b4500             mov     rax, qword ptr [rbp]
000072f7b0bdb4c4 50                   push    rax
000072f7b0bdb4c5 4883ec20             sub     rsp, 0x20
000072f7b0bdb4c9 4c89bc24c8000000     mov     qword ptr [rsp + 0xc8], r15
000072f7b0bdb4d1 4c89b424c0000000     mov     qword ptr [rsp + 0xc0], r14
000072f7b0bdb4d9 48899c24b8000000     mov     qword ptr [rsp + 0xb8], rbx
000072f7b0bdb4e1 488d6c2420           lea     rbp, [rsp + 0x20]
000072f7b0bdb4e6 33c0                 xor     eax, eax
000072f7b0bdb4e8 488945e0             mov     qword ptr [rbp - 0x20], rax
000072f7b0bdb4ec 488b9d80000000       mov     rbx, qword ptr [rbp + 0x80]
000072f7b0bdb4f3 4c8b7d78             mov     r15, qword ptr [rbp + 0x78]
000072f7b0bdb4f7 4885db               test    rbx, rbx
000072f7b0bdb4fa 0f84e7000000         je      0x72f7b0bdb5e7
000072f7b0bdb500 498b3f               mov     rdi, qword ptr [r15]
000072f7b0bdb503 40383f               cmp     byte ptr [rdi], dil
000072f7b0bdb506 488d55e0             lea     rdx, [rbp - 0x20]
000072f7b0bdb50a 488bf3               mov     rsi, rbx
000072f7b0bdb50d ff153d8f61fe         call    qword ptr [rip - 0x19e70c3]
000072f7b0bdb513 85c0                 test    eax, eax
000072f7b0bdb515 742b                 je      0x72f7b0bdb542
000072f7b0bdb517 498b7f08             mov     rdi, qword ptr [r15 + 0x8]
000072f7b0bdb51b ff4714               inc     dword ptr [rdi + 0x14]
000072f7b0bdb51e 488b5708             mov     rdx, qword ptr [rdi + 0x8]
000072f7b0bdb522 8b7710               mov     esi, dword ptr [rdi + 0x10]
000072f7b0bdb525 397208               cmp     dword ptr [rdx + 0x8], esi
000072f7b0bdb528 0f8693000000         jbe     0x72f7b0bdb5c1
000072f7b0bdb52e 8d4601               lea     eax, [rsi + 0x1]
000072f7b0bdb531 894710               mov     dword ptr [rdi + 0x10], eax
000072f7b0bdb534 4863f6               movsxd  rsi, esi
000072f7b0bdb537 488bfa               mov     rdi, rdx
000072f7b0bdb53a 488bd3               mov     rdx, rbx
000072f7b0bdb53d e8fe8c15fe           call    0x72f7aed34240 (System.Runtime.CompilerServices.CastHelpers.StelemRef(System.Object[], IntPtr, System.Object), mdToken: 0000000006006843)
000072f7b0bdb542 4c8bf3               mov     r14, rbx
000072f7b0bdb545 48be10a8fcaff7720000 movabs  rsi, 0x72f7affca810
000072f7b0bdb54f 493936               cmp     qword ptr [r14], rsi
000072f7b0bdb552 7556                 jne     0x72f7b0bdb5aa
000072f7b0bdb554 4533f6               xor     r14d, r14d
000072f7b0bdb557 4d85f6               test    r14, r14
000072f7b0bdb55a 0f8595000000         jne     0x72f7b0bdb5f5
000072f7b0bdb560 48bf10a8fcaff7720000 movabs  rdi, 0x72f7affca810
000072f7b0bdb56a 48393b               cmp     qword ptr [rbx], rdi
000072f7b0bdb56d 7560                 jne     0x72f7b0bdb5cf
000072f7b0bdb56f 48837b7000           cmp     qword ptr [rbx + 0x70], 0x0
000072f7b0bdb574 740b                 je      0x72f7b0bdb581
000072f7b0bdb576 4c8b7370             mov     r14, qword ptr [rbx + 0x70]
000072f7b0bdb57a bbffffffff           mov     ebx, 0xffffffff
000072f7b0bdb57f eb1d                 jmp     0x72f7b0bdb59e
000072f7b0bdb581 488bfb               mov     rdi, rbx
000072f7b0bdb584 ff15864237ff         call    qword ptr [rip - 0xc8bd7a]
000072f7b0bdb58a ebea                 jmp     0x72f7b0bdb576
000072f7b0bdb58c 3bdf                 cmp     ebx, edi
000072f7b0bdb58e 7351                 jae     0x72f7b0bdb5e1
000072f7b0bdb590 498b7cde10           mov     rdi, qword ptr [r14 + 8*rbx + 0x10]
000072f7b0bdb595 498bf7               mov     rsi, r15
000072f7b0bdb598 ff15b2b5e3ff         call    qword ptr [rip - 0x1c4a4e]
000072f7b0bdb59e ffc3                 inc     ebx
000072f7b0bdb5a0 418b7e08             mov     edi, dword ptr [r14 + 0x8]
000072f7b0bdb5a4 3bfb                 cmp     edi, ebx
000072f7b0bdb5a6 7fe4                 jg      0x72f7b0bdb58c
000072f7b0bdb5a8 eb3d                 jmp     0x72f7b0bdb5e7
000072f7b0bdb5aa 488bf3               mov     rsi, rbx
000072f7b0bdb5ad 48bff064cfaff7720000 movabs  rdi, 0x72f7afcf64f0
000072f7b0bdb5b7 e8e47513fe           call    0x72f7aed12ba0 (System.Runtime.CompilerServices.CastHelpers.IsInstanceOfClass(Void*, System.Object), mdToken: 0000000006006838)
000072f7b0bdb5bc 4c8bf0               mov     r14, rax
000072f7b0bdb5bf eb96                 jmp     0x72f7b0bdb557
000072f7b0bdb5c1 488bf3               mov     rsi, rbx
000072f7b0bdb5c4 ff158ead4dfe         call    qword ptr [rip - 0x1b25272]
000072f7b0bdb5ca e973ffffff           jmp     0x72f7b0bdb542
000072f7b0bdb5cf 488bfb               mov     rdi, rbx
000072f7b0bdb5d2 488b03               mov     rax, qword ptr [rbx]
000072f7b0bdb5d5 488b4048             mov     rax, qword ptr [rax + 0x48]
000072f7b0bdb5d9 ff5038               call    qword ptr [rax + 0x38]
000072f7b0bdb5dc 4c8bf0               mov     r14, rax
000072f7b0bdb5df eb99                 jmp     0x72f7b0bdb57a
000072f7b0bdb5e1 e8ca6eee7b           call    0x72f82cac24b0 (JitHelp: CORINFO_HELP_RNGCHKFAIL)
000072f7b0bdb5e6 cc                   int3
000072f7b0bdb5e7 4881c4b8000000       add     rsp, 0xb8
000072f7b0bdb5ee 5b                   pop     rbx
000072f7b0bdb5ef 415e                 pop     r14
000072f7b0bdb5f1 415f                 pop     r15
000072f7b0bdb5f3 5d                   pop     rbp
000072f7b0bdb5f4 c3                   ret
000072f7b0bdb5f5 498b7e28             mov     rdi, qword ptr [r14 + 0x28]
000072f7b0bdb5f9 498bf7               mov     rsi, r15
000072f7b0bdb5fc ff154eb5e3ff         call    qword ptr [rip - 0x1c4ab2]
000072f7b0bdb602 e959ffffff           jmp     0x72f7b0bdb560

I'm not sure what the mov rax, [rbp+0] is doing there. Something related to OSR prolog..?

Both frame 7 and frame 8 have the same frame pointer:

(lldb) fr sel 7
frame #7: 0x0000000000000000
error: core file does not contain 0x0
(lldb) register read
General Purpose Registers:
       rax = 0x000072f82d6376a0
       rbx = 0x000072b799d213b8
       rcx = 0x0000000000000602
       rdx = 0x000072f82d638160
       rdi = 0x00007fff40434170
       rsi = 0x000072f7b0bda404
       rbp = 0x00007fff40434e70
       rsp = 0x00007fff40434dc8
        r8 = 0x00007fff40434138
        r9 = 0x000072f7ac145008
       r10 = 0x00007fff40434170
       r11 = 0x0000000000000000
       r12 = 0x000072b796044770
       r13 = 0x000072b7962a1390
       r14 = 0x000072f7afcf4fe0
       r15 = 0x000072b799659e40
       rip = 0x0000000000000000
...
(lldb) fr sel 8
frame #8: 0x000072f7b0bda404
->  0x72f7b0bda404: mov    rdi, qword ptr [rbp - 0x30]
    0x72f7b0bda408: xor    esi, esi
    0x72f7b0bda40a: call   qword ptr [rip - 0xf03158]
    0x72f7b0bda410: test   eax, eax
(lldb) register read
General Purpose Registers:
       rbx = 0x000072b799d213b8
       rbp = 0x00007fff40434e70
       rsp = 0x00007fff40434dd0
       r12 = 0x000072b796044770
       r13 = 0x000072b7962a1390
       r14 = 0x000072f7afcf4fe0
       r15 = 0x000072b799659e40
       rip = 0x000072f7b0bda404
16 registers were unavailable.

This probably indicates that we're returning. Indeed, it appears we tried to return to 0:

(lldb) p *(void**)$rsp
(void *) $19 = 0x0000000000000000

However, it's quite odd that RBP appears to be the same as frame 8. That means we should be about to return to the tier0 version of a method we transitioned out of. That shouldn't be possible.
The return address of the tier 0 version right after the patchpoint is very close by:

(lldb) p *(void**)($rsp-8)
(void *) $21 = 0x000072f7b0bda404

[jakobbotsch]

Another pointer: rsi still contains the return address passed to JIT_Patchpoint, so it seems likely that we haven't managed to transition successfully, since the OSR version of the code would trash rsi if we did transition successfully.

[jakobbotsch]

It looks like all others threads are suspended for GC:

DBG   ID     OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
   1    1      f99 00005C24445275E0    20062 Cooperative 000072B799D74D80:000072B799D75010 00005C244450CFC0 -00001 Ukn
   6    2      f9f 00005C244452FB20    21220 Preemptive  000072B796802500:000072B796804298 00005C244450CFC0 -00001 Ukn (Finalizer)
   7    3      fa3 00005C244453D240    21220 Preemptive  0000000000000000:0000000000000000 00005C244450CFC0 -00001 Ukn
   8    4      fa4 00005C2444C7BCD0  1021220 Preemptive  000072B799DE01C0:000072B799DE01C0 00005C244450CFC0 -00001 Ukn (GC) (Threadpool Worker)
   9    5      fa5 00005C2444C7F660  1021220 Preemptive  0000000000000000:0000000000000000 00005C244450CFC0 -00001 Ukn (Threadpool Worker)
  10    6      fa6 000072B6F000FDB0  1021220 Preemptive  000072B799DCE608:000072B799DCF0B0 00005C244450CFC0 -00001 Ukn (Threadpool Worker)
  11    7      fe6 000072B6F016EA60  1021220 Preemptive  000072B799D7E990:000072B799D7F0B0 00005C244450CFC0 -00001 Ukn (Threadpool Worker)
  12    8      fe7 000072B6EC122990    21220 Preemptive  0000000000000000:0000000000000000 00005C244450CFC0 -00001 Ukn
  13    9      fea 000072B6EC08C210  1021220 Preemptive  000072B799DDFB60:000072B799DE0178 00005C244450CFC0 -00001 Ukn (Threadpool Worker)
  14   10      fec 000072B6E001D420  1021220 Preemptive  000072B799D95008:000072B799D95010 00005C244450CFC0 -00001 Ukn (Threadpool Worker)

and everyone is waiting for this transitioning thread to suspend. Perhaps some edge case around EE suspension/hijacking during OSR transitions?

[AndyAyersMS]

Yeah I have similar looking crashes where we end up trying to execute at address zero. Haven't gotten very far trying to debug.

As far as I know nothing has changed in the OSR prolog generation and/or the patchpoint helper, so I think the problem lies elsewhere, but am not sure.

[jakobbotsch]

We've definitely called ClrRestoreNonvolatileContext not very long ago. r10 still has the address of the CONTEXT that was passed to restore. In the dump above that address is 0x7fff40434170 and you arrive at the same value from some careful frame pointer arithmetic.

Sadly the CONTEXT on the stack has been overwritten by the functions used for the dump generation code, so it's hard to tell exactly what context was resumed with (and whether the problem happens right at resumption or later). Perhaps the other dump has more information.

[AndyAyersMS]

@janvorli this is similar to the crash dump I was asking you about.

Also seems to be correlated with either unusual patchpoint placement (via DOTNET_JitRandomOnStackReplacement=15) and/or very frequent OSR transitions (via DOTNET_TC_OnStackReplacement_InitialCounter=1 and DOTNET_OSR_HitLimit=2). So I suspect some kind of race or rare interaction. In normal usage we very rarely do OSR transitions.

I have never been able to repro this locally.

I was going to try running with both OSR stress and GC stress to see if perhaps that would lead to a more consistent repro.