Failing test suite - all.lua

[Pavel-Durov]

Issue

Failing test suite all.lua.
all.lua file used as a test suite, it sets up the environment and executes multiple tests.

The all.lua execution failure can be tofo with all.lua itself or with the invoked induvisual tests.

Steps to reproduce

$ ../src/lua -e"_U=true" all.lua

        Starting Tests
random seeds: 1692615247, 27885112
current path:
****/usr/local/share/lua/5.4/?.lua;/usr/local/share/lua/5.4/?/init.lua;/usr/local/lib/lua/5.4/?.lua;/usr/local/lib/lua/5.4/?/init.lua;./?.lua;./?/init.lua****

    ---- total memory: 35.8K, max memory: 35.8K ----

time: 3e-05 (+3e-05)

***** FILE 'main.lua'*****
Segmentation fault (core dumped)

Notes

all.lua file overrides the native dofile function https://github.com/ykjit/yklua/blob/main/tests/all.lua#L143
Where each test file:

1. loaded
2. stringified to a binary representation
3. loaded back from binary
4. executed as a function

Based on the attached backtrace, it looks like we have an exception when freeing YK trace locations, probably caused by this dump/load process. Needs further investigation 🕵️

Backtrace

Program received signal SIGSEGV, Segmentation fault.
core::sync::atomic::AtomicUsize::fetch_sub (self=0xfffffffffffffff0) at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/sync/atomic.rs:2540
2540    /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/sync/atomic.rs: No such file or directory.
(gdb) 
(gdb) 
(gdb) bt
#0  core::sync::atomic::AtomicUsize::fetch_sub (self=0xfffffffffffffff0)
    at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/sync/atomic.rs:2540
#1  alloc::sync::{impl#27}::drop<lock_api::mutex::Mutex<parking_lot::raw_mutex::RawMutex, ykrt::location::HotLocation>> (self=0x7fffffffcc20)
    at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/alloc/src/sync.rs:1864
#2  0x00007ffff7b062eb in core::ptr::drop_in_place<alloc::sync::Arc<lock_api::mutex::Mutex<parking_lot::raw_mutex::RawMutex, ykrt::location::HotLocation>>> ()
    at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/ptr/mod.rs:497
#3  0x00007ffff7b2eabe in core::mem::drop<alloc::sync::Arc<lock_api::mutex::Mutex<parking_lot::raw_mutex::RawMutex, ykrt::location::HotLocation>>> (_x=...)
    at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/mem/mod.rs:987
#4  0x00007ffff7b0a4c0 in ykrt::location::{impl#1}::drop (self=0x7fffffffcc78) at ykrt/src/location.rs:196
#5  0x00007ffff7b04d3b in core::ptr::drop_in_place<ykrt::location::Location> ()
    at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/ptr/mod.rs:497
#6  0x00007ffff7b04fdd in core::mem::drop<ykrt::location::Location> (_x=...) at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/mem/mod.rs:987
#7  0x00007ffff7b04cdd in ykcapi::yk_location_drop (loc=...) at ykcapi/src/lib.rs:87
#8  0x000000000088aede in free_loc (f=<optimised out>, i=<optimised out>, idx=<optimised out>) at lyk.c:66
#9  0x000000000088b075 in yk_free_locactions (f=0x926290) at lyk.c:76
#10 0x0000000000807c08 in luaF_freeproto (L=0x916e38, f=0x926290) at lfunc.c:276
#11 0x000000000080a4ae in freeobj (L=0x916e38, o=0x926290) at lgc.c:767
#12 0x0000000000815358 in deletelist (L=0x916e38, p=0x926290, limit=<optimised out>) at lgc.c:1494
#13 0x0000000000815164 in luaC_freeallobjects (L=0x916e38) at lgc.c:1511
#14 0x000000000084fd4d in close_state (L=0x916e38) at lstate.c:276
#15 0x00000000008503ce in lua_close (L=0x916e38) at lstate.c:421
#16 0x00000000007d9aa0 in main (argc=<optimised out>, argv=<optimised out>) at lua.c:663

Versions

YKLua - main/0a80b8adafdba03d111dcc5e032ce3d6e3c913f7
YK - master/a690e6eaf7253a4fa9c04bb54406c07b7efc0085

[Pavel-Durov]

Progress update:
yk_location_drop is called multiple times, sometimes with YK location having Location { inner: 0 } value.

$1 = ykrt::location::Location {inner: core::sync::atomic::AtomicUsize {v: core::cell::UnsafeCell<usize> {value: 117585}}}
....
$2 = ykrt::location::Location {inner: core::sync::atomic::AtomicUsize {v: core::cell::UnsafeCell<usize> {value: 0}}}}}

backtrace:

Program received signal SIGSEGV, Segmentation fault.
core::sync::atomic::AtomicUsize::fetch_sub (self=0xfffffffffffffff0) at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/sync/atomic.rs:2540
2540    /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/sync/atomic.rs: No such file or directory.
#0  core::sync::atomic::AtomicUsize::fetch_sub (self=0xfffffffffffffff0) at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/sync/atomic.rs:2540
#1  alloc::sync::{impl#27}::drop<lock_api::mutex::Mutex<parking_lot::raw_mutex::RawMutex, ykrt::location::HotLocation>> (self=0x7fffffffce60) at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/alloc/src/sync.rs:1864
#2  0x00007ffff7b062eb in core::ptr::drop_in_place<alloc::sync::Arc<lock_api::mutex::Mutex<parking_lot::raw_mutex::RawMutex, ykrt::location::HotLocation>>> () at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/ptr/mod.rs:497
#3  0x00007ffff7b2ebce in core::mem::drop<alloc::sync::Arc<lock_api::mutex::Mutex<parking_lot::raw_mutex::RawMutex, ykrt::location::HotLocation>>> (_x=...) at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/mem/mod.rs:987
#4  0x00007ffff7b0a53b in ykrt::location::{impl#1}::drop (self=0x7fffffffcf18) at ykrt/src/location.rs:197
#5  0x00007ffff7b04d3b in core::ptr::drop_in_place<ykrt::location::Location> () at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/ptr/mod.rs:497
#6  0x00007ffff7b04fdd in core::mem::drop<ykrt::location::Location> (_x=...) at /rustc/8c74a5d27c644a0f7a22bb2fa8dd3ff8257bc220/library/core/src/mem/mod.rs:987
#7  0x00007ffff7b04cdd in ykcapi::yk_location_drop (loc=...) at ykcapi/src/lib.rs:87
#8  0x000000000088d8ed in yk_free_proto (f=<optimised out>) at lyk.c:99
#9  0x0000000000809f28 in luaF_freeproto (L=0x919e38, f=0x8f9410) at lfunc.c:276
#10 0x000000000080c7ce in freeobj (L=0x919e38, o=0x8f9410) at lgc.c:767
#11 0x0000000000817678 in deletelist (L=0x919e38, p=0x8f9410, limit=<optimised out>) at lgc.c:1494
#12 0x0000000000817484 in luaC_freeallobjects (L=0x919e38) at lgc.c:1511
#13 0x000000000085206d in close_state (L=0x919e38) at lstate.c:276
#14 0x00000000008526ee in lua_close (L=0x919e38) at lstate.c:421
#15 0x00000000007dbd40 in main (argc=<optimised out>, argv=<optimised out>) at lua.c:663

Need to see how these locations are set 🕵️‍♀️

[Pavel-Durov]

Lua tests behave differently when executed through all.lua and individually.

Direct execution of math.lua error:

YKD_PRINT_JITSTATE=1 YKD_SERIALISE_COMPILATION=1 /home/pd/yklua-fork/src/lua -e"_U=true" ./math.lua 
instrinsic is missing `yk.intrinsic.inlined` metadata:   %13 = call double @llvm.floor.f64(double %0), !dbg !9453

Execution ofmath.lua via all.lua:

YKD_PRINT_JITSTATE=1 YKD_SERIALISE_COMPILATION=1 /home/pd/yklua-fork/src/lua -e"_U=true" ./all.lua 
...
final OK !!!

We know that math.lua test should fail, but it doesn't 🤔.

One assumption was that all.lua executed sub-tests with the non-yk lua interpreter.
But then I added the lua script to print process information:

local function print_env()
    print(string.format("YKD_SERIALISE_COMPILATION=%s", os.getenv("YKD_SERIALISE_COMPILATION") or "UNDEFINED"))
    print(string.format("YKD_PRINT_JITSTATE=%s", os.getenv("YKD_PRINT_JITSTATE") or "UNDEFINED"))
end

local function exec_cmd(cmd)
    local openPop = assert(io.popen(cmd, 'r'))
    local output = openPop:read('*all')
    openPop:close()
    return output
end

local function print_proc_info()
    print(exec_cmd("ps -Flww -p $(pgrep -x lua)"))
    print(exec_cmd("pstree -p $(pgrep -x lua)"))
end

function proc_print_info(file_name)
    print(string.format("> %s proc info.", file_name))
    print_env()
    print_proc_info()
end

all.lua tests:

YKD_PRINT_JITSTATE=1 YKD_SERIALISE_COMPILATION=1 /home/pd/yklua-fork/src/lua -e"_U=true" ./all.lua
...
> all.lua proc info.
YKD_SERIALISE_COMPILATION=1
YKD_PRINT_JITSTATE=1
F S UID          PID    PPID  C PRI  NI ADDR SZ WCHAN    RSS PSR STIME TTY          TIME CMD
0 S pd       2049911 2049788 25  80   0 - 24603 pipe_r 40016   7 13:15 pts/19   00:00:00 /home/pd/yklua-fork/src/lua -e_U=true ./all.lua

lua(2049911)---sh(2049915)---pstree(2049917)
...
***** FILE 'math.lua'*****
> math.lua proc info.
YKD_SERIALISE_COMPILATION=1
YKD_PRINT_JITSTATE=1
F S UID          PID    PPID  C PRI  NI ADDR SZ WCHAN    RSS PSR STIME TTY          TIME CMD
0 S pd       2049911 2049788 60  80   0 - 24666 pipe_r 40596   7 13:15 pts/19   00:00:00 /home/pd/yklua-fork/src/lua -e_U=true ./all.lua

lua(2049911)---sh(2049921)---pstree(2049923)
...
final OK !!!

math.lua tests:

[13:14:20] $ YKD_PRINT_JITSTATE=1 YKD_SERIALISE_COMPILATION=1 /home/pd/yklua-fork/src/lua -e"_U=true" ./math.lua 
> math.lua proc info.
YKD_SERIALISE_COMPILATION=1
YKD_PRINT_JITSTATE=1
F S UID          PID    PPID  C PRI  NI ADDR SZ WCHAN    RSS PSR STIME TTY          TIME CMD
0 S pd       2049733 2036361 81  80   0 - 24658 pipe_r 40448   0 13:14 pts/26   00:00:00 /home/pd/yklua-fork/src/lua -e_U=true ./math.lua

lua(2049733)---sh(2049737)---pstree(2049739)
...
instrinsic is missing `yk.intrinsic.inlined` metadata:   %13 = call double @llvm.floor.f64(double %0), !dbg !9453 x pd@bencher8 ~/yklua-fork/tests sort-test-serialised/4bdeede7db8b8a3b6eb10e94e0a9d654c54a3212

Based on the output, I can conclude that in both cases yk-enabled lua interpreter is used.

The mystery continues 🕵️

[ltratt]

@ptersilie Perhaps when you're done on the depot speed up, you could have a look at this, to see if we can find any clues to help @Pavel-Durov ?

[Pavel-Durov]

After looking at the issue with @ptersilie
Looks like the problem is with the yk_lookup for dynamically loaded functions (load calls in all.lua).
When functions are loaded dynamically, the locations are set but later on, the lookup fails to get the locations by the PC index.