Rare deadlock and segmentation fault in a parallel quicksort implementation (with an MWE)

[tkf]

I have a trouble with finding a cause of a rare deadlock in my parallel quicksort. I tried my best, with a big help from @chriselrod, to find out the problem but I still have no idea how to fix it.

I am reporting this here since I think there is some chance that there is a bug in julia (scheduler? compiler?). (In other words I'm hopelessly lost now and all I can do is "blame" the upstream.)

MWE: Install the latest ThreadsX (v0.1.1) and BenchmarkTools. Then run the following code eventually causes a deadlock when JULIA_NUM_THREADS is appropriate (for me it's 13 for @chriselrod it's 8 but not 7):

using BenchmarkTools, ThreadsX, Random
seed = Ref(0)
while true
    @btime ThreadsX.sort($(rand(MersenneTwister(@show(seed[] += 1)), 0:0.01:1, 1_000_000)))
end

I've tried git bisect with this script and found that #32599 changes the way the problem(s) manifest:

• After threads: further optimize scheduler based on #32551 #32599 (dc46ddd): running the MWE eventually hangs (it hung within 18 minuets once but it continued to run more than 30 minutes once).
• Before threads: further optimize scheduler based on #32551 #32599 (f5dbc47): running the MWE does not cause the hang.
• In both cases, the MWE can cause a segmentation fault but it is very rare; i.e., the MWE can run for more than one hour without a problem.

With f5dbc47, I observed this segmentation fault:

seed[] += 1 = 247
[ Info: %CPU = 1167.0
[ Info: 45.550472802933335 minutes without a hang....

signal (11): Segmentation fault
in expression starting at none:3
setindex! at ./Base.jl:0 [inlined]
setindex! at ./subarray.jl:301 [inlined]
partition_sizes! at /root/.julia/packages/ThreadsX/OsJPr/src/quicksort.jl:167
#97 at /root/.julia/packages/ThreadsX/OsJPr/src/quicksort.jl:158 [inlined]
#3 at ./threadingconstructs.jl:126
unknown function (ip: 0x7f54cc050ee6)
_jl_invoke at /julia/src/gf.c:2144 [inlined]
jl_apply_generic at /julia/src/gf.c:2328
jl_apply at /julia/src/julia.h:1695 [inlined]
start_task at /julia/src/task.c:687
unknown function (ip: (nil))
Allocations: 6273831512 (Pool: 6273798676; Big: 32836); GC: 17817

However, I don't understand how this function partition_sizes! can cause a segfault.

@chriselrod also observed another segfault with 65b8e7e:

signal (11): Segmentation fault
in expression starting at REPL[3]:1
- at ./int.jl:52 [inlined]
unsafe_length at ./range.jl:517 [inlined]
unsafe_indices at ./abstractarray.jl:99 [inlined]
_indices_sub at ./subarray.jl:409 [inlined]
axes at ./subarray.jl:404 [inlined]
axes1 at ./abstractarray.jl:95 [inlined]
eachindex at ./abstractarray.jl:267 [inlined]
eachindex at ./abstractarray.jl:270 [inlined]
eachindex at ./abstractarray.jl:260 [inlined]
partition_sizes! at /home/chriselrod/.julia/packages/ThreadsX/OsJPr/src/quicksort.jl:163
unknown function (ip: 0x7f67b598804f)
unknown function (ip: (nil))
Allocations: 10113947179 (Pool: 10113915735; Big: 31444); GC: 29811

It is puzzling for me that how the code involved in the above stacktrace can cause a segfault:

- at ./int.jl:52
unsafe_length at ./range.jl:517
unsafe_indices at ./abstractarray.jl:99
_indices_sub at ./subarray.jl:409
axes at ./subarray.jl:404
axes1 at ./abstractarray.jl:95
eachindex at ./abstractarray.jl:267
eachindex at ./abstractarray.jl:270
eachindex at ./abstractarray.jl:260
partition_sizes! at ThreadsX.jl/src/quicksort.jl:163

We (me and @chriselrod) tried to get a better error report by running the MWE with --check-bounds=yes. But we couldn't get a hang or segfault even after running the MWE for hours.

I highly appreciate any help/advice from core devs or anyone who knows how threading works in Julia. I'm currently trying to build ASAN-enabled julia with help from @vchuravy #35338, hoping that it gives us some information. But I'm not sure how much I can discover by doing this as I don't know anything about LLVM or C++.

[Keno]

If you can reproduce it under rr, that'll be easiest to debug.

[tkf]

Thanks! But https://github.com/mozilla/rr/wiki/Usage says

rr forces your application's threads to execute on a single core, so your application can see an additional slowdown if it takes advantage of multicore parallelism.

So I guess it cannot be used to debug multi-threading bug? We never observed the bug with single thread.

I tried it anyway but it failed to start

root@459e9488a96a:/julia# rr --version
rr version 5.3.0
root@459e9488a96a:/julia# rr record ./julia -e 'using BenchmarkTools, ThreadsX, Random; seed = Ref(0); while true; @btime ThreadsX.sort($(rand(MersenneTwister(@show(seed[] += 1)), 0:0.01:1, 1_000_000))); end'
[FATAL /home/roc/rr/rr/src/PerfCounters.cc:317:start_counter() errno: EPERM] Failed to initialize counter
=== Start rr backtrace:
rr(_ZN2rr13dump_rr_stackEv+0x3b)[0x5f229b]
rr(_ZN2rr15notifying_abortEv+0x47)[0x5f2327]
rr[0x52cba5]
rr[0x52dede]
rr(_ZN2rr12PerfCounters23default_ticks_semanticsEv+0x1a)[0x52e9ca]
rr(_ZN2rr7SessionC1Ev+0x139)[0x5bc369]
rr(_ZN2rr13RecordSessionC1ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERKSt6vectorIS6_SaIS6_EESD_RKNS_20DisableCPUIDFeaturesENS0_16SyscallBufferingEiNS_7BindCPUES8_PKNS_9TraceUuidE+0x4d)[0x54069d] 
rr(_ZN2rr13RecordSession6createERKSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EESB_RKNS_20DisableCPUIDFeaturesENS0_16SyscallBufferingEhNS_7BindCPUERKS7_PKNS_9TraceUuidE+0xba9)[0x541769] 
rr(_ZN2rr13RecordCommand3runERSt6vectorINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEESaIS7_EE+0xe14)[0x535c24]
rr(main+0x353)[0x4ac743]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7)[0x7f935c454b97]
rr(_start+0x29)[0x4acb59]
=== End rr backtrace
Aborted (core dumped)

(Edit: it looks like this is because I'm using docker? https://github.com/mozilla/rr/wiki/Docker)

[tkf]

Ah sorry I missed that https://docs.julialang.org/en/v1/devdocs/debuggingtips/#Reproducing-concurrency-bugs-with-rr-1 mentions rr record --chaos

[Keno]

[FATAL /home/roc/rr/rr/src/PerfCounters.cc:317:start_counter() errno: EPERM] Failed to initialize counter

This might be due to docker, you can try using a priviledged container to get access to the perf counters.

[tkf]

Thanks! I followed https://github.com/mozilla/rr/wiki/Docker and then just started the MWE with

JULIA_NUM_THREADS=13 rr record --num-cores=13 --chaos ./julia -e 'using BenchmarkTools, ThreadsX, Random; seed = Ref(0); while true; @btime ThreadsX.sort($(rand(MersenneTwister(@show(seed[] += 1)), 0:0.01:1, 1_000_000))); end'

It runs like usual (though of course slowly). Let's hope it hangs.

[tkf]

So I ran this for more than three hours (up to seed = 1000) and rr generated 17 GB of trace but it didn't cause a hang or segfault.

[Keno]

If before it hung only after 45 minutes, you'll probably need to run in at least 10 hours with that many threads.you may also want to kick off multiple runs in parallel to maximize your chances of catching it.

[tkf]

The hang can happen within a few minutes if I'm lucky. It's the segfault that is super rare. I was worrying that rr generates a big amount of data that eats up all the disk space so I limited the loop when I started it yesterday. I know how much space it'll eat now so I'll run more of them.

[tkf]

With ASAN #35338, running the MWE with

JULIA_NUM_THREADS=13 ASAN_OPTIONS=detect_leaks=0:allow_user_segv_handler=1 ./julia -e 'using BenchmarkTools, ThreadsX, Random; for seed in 1:5000; @btime ThreadsX.sort($(rand(MersenneTwister(@show(seed)), 0:0.01:1, 1_000_000))); end'

now somehow gives me the segfault that @chriselrod observed (see the OP) reliably with some short amount of time (a few minutes):

...
seed = 13

signal (11): Segmentation fault
in expression starting at none:1
- at ./int.jl:85 [inlined]
unsafe_length at ./range.jl:540 [inlined]
unsafe_indices at ./abstractarray.jl:99 [inlined]
_indices_sub at ./subarray.jl:409 [inlined]
axes at ./subarray.jl:404 [inlined]
size at ./subarray.jl:71 [inlined]
length at ./abstractarray.jl:206 [inlined]
#89 at ./none:0 [inlined]
iterate at ./generator.jl:47 [inlined]
collect at ./array.jl:664
_quicksort! at /root/.julia/packages/ThreadsX/OsJPr/src/quicksort.jl:77
macro expansion at /root/.julia/packages/ThreadsX/OsJPr/src/quicksort.jl:136 [inlined]
#92 at ./threadingconstructs.jl:126
jl_apply at /julia/src/./julia.h:1687 [inlined]
start_task at /julia/src/task.c:687
unknown function (ip: (nil))
Allocations: 99406804 (Pool: 0; Big: 99406804); GC: 1180
Segmentation fault

Though nothing specific seems to be printed via ASAN runtime itself.

I get different kind of setfault too:

...
  12.312 ms (21628 allocations: 19.69 MiB)
seed = 17

signal (11): Segmentation fault

signal (11): Segmentation fault
in expression starting at none:1
in expression starting at none:1

signal (11): Segmentation fault
in expression starting at none:1
in expres11): Segmentation fault
in expression starting at none:1
in expression starting at none:1

signal (11): Segmentation fault
in expression starting at none:1

signal (11): Segmentation fault

signal (11): Segmentation fault
in expression starting at none:1
in expression starting at none:1
in expression starting at none:1

signal (11): Segmentation fault
in expression starting at none:1

signal (11): Segmentation fault
in expression starting at none:1

signal (11): Segmentation fault
in expression starting at none:1
unknown function (ip: 0x7fa637bee020)
unknown function (ip: 0x7fa637bee020)
Segmentation fault

[tkf]

Running without multi-threading (without JULIA_NUM_THREADS=13) now gives me:

seed = 6
  42.666 ms (19937 allocations: 19.42 MiB)
seed = 7
=================================================================
==21519==ERROR: AddressSanitizer: heap-use-after-free on address 0x610017ba6578 at pc 0x7f4ce9302a5b bp 0x7f4caa960570 sp 0x
7f4caa960568
READ of size 8 at 0x610017ba6578 thread T0
    #0 0x7f4ce9302a5a  (/julia/usr/bin/../lib/libjulia.so.1+0x2b3a5a)
    #1 0x7f4ce930672c  (/julia/usr/bin/../lib/libjulia.so.1+0x2b772c)
    #2 0x7f4ce9304ab0  (/julia/usr/bin/../lib/libjulia.so.1+0x2b5ab0)
    #3 0x7f4ce92f9def  (/julia/usr/bin/../lib/libjulia.so.1+0x2aadef)
    #4 0x7f4cbfb230dc  (/memfd:julia-codegen (deleted)+0x260dc)
    #5 0x7f4cbfb2c1d4  (/memfd:julia-codegen (deleted)+0x2f1d4)
    #6 0x7f4cbfb3009d  (/memfd:julia-codegen (deleted)+0x3309d)
    #7 0x7f4cbfb32d8b  (/memfd:julia-codegen (deleted)+0x35d8b)
    #8 0x7f4ce92942b4  (/julia/usr/bin/../lib/libjulia.so.1+0x2452b4)

0x610017ba6578 is located 56 bytes inside of 128-byte region [0x610017ba6540,0x610017ba65c0)
freed by thread T0 here:
    #0 0x4a89d0  (/julia/usr/bin/julia+0x4a89d0)
    #1 0x7f4ce9310f77  (/julia/usr/bin/../lib/libjulia.so.1+0x2c1f77)
    #2 0x7f4ce930e57f  (/julia/usr/bin/../lib/libjulia.so.1+0x2bf57f)
    #3 0x7f4ce9307cb0  (/julia/usr/bin/../lib/libjulia.so.1+0x2b8cb0)
    #4 0x7f4ce9304ab0  (/julia/usr/bin/../lib/libjulia.so.1+0x2b5ab0)
    #5 0x7f4ce92f9def  (/julia/usr/bin/../lib/libjulia.so.1+0x2aadef)
    #6 0x7f4cbfb2bf90  (/memfd:julia-codegen (deleted)+0x2ef90)
    #7 0x7f4cbfb3009d  (/memfd:julia-codegen (deleted)+0x3309d)
    #8 0x7f4cbfb32d8b  (/memfd:julia-codegen (deleted)+0x35d8b)

previously allocated by thread T0 here:
    #0 0x4a993d  (/julia/usr/bin/julia+0x4a993d)
    #1 0x7f4ce92f9e4d  (/julia/usr/bin/../lib/libjulia.so.1+0x2aae4d)
    #2 0x7f4cbfb230dc  (/memfd:julia-codegen (deleted)+0x260dc)

SUMMARY: AddressSanitizer: heap-use-after-free (/julia/usr/bin/../lib/libjulia.so.1+0x2b3a5a) 
Shadow bytes around the buggy address:
  0x0c2082f6cc50: fd fd fd fd fd fd fd fd fa fa fa fa fa fa fa fa
  0x0c2082f6cc60: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
  0x0c2082f6cc70: fd fd fd fd fd fd fd fd fa fa fa fa fa fa fa fa
  0x0c2082f6cc80: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
  0x0c2082f6cc90: fd fd fd fd fd fd fd fd fa fa fa fa fa fa fa fa
=>0x0c2082f6cca0: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd[fd]
  0x0c2082f6ccb0: fd fd fd fd fd fd fd fd fa fa fa fa fa fa fa fa
  0x0c2082f6ccc0: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
  0x0c2082f6ccd0: fd fd fd fd fd fd fd fd fa fa fa fa fa fa fa fa
  0x0c2082f6cce0: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
  0x0c2082f6ccf0: fd fd fd fd fd fd fd fd fa fa fa fa fa fa fa fa
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
  Shadow gap:              cc
==21519==ABORTING

[tkf]

What's the best next step? I'm trying this with rr record ATM.

[maleadt]

If you use a debug build and set ASAN_SYMBOLIZER_PATH to the llvm-symbolizer you've built in the process, you'll get debug info in the ASAN trace. Also see https://github.com/google/sanitizers/wiki/AddressSanitizerAndDebugger, ASAN_OPTIONS=abort_on_error=1 makes it easier to use ASAN with rr.