Julia can hang when using threading, on 1.7 beta2 and 1.8

[PallHaraldsson]

A.

$ time ~/julia-1.8-DEV-7553ca13cc/bin/julia --startup-file=no -t4 -O2 fasta.jl 25000000 > /dev/null

real	0m3,032s
user	0m8,379s
sys	0m0,883s

then immediately after:

$ time sh -c ~/julia-1.8-DEV-7553ca13cc/bin/julia --startup-file=no -t4 -O2 fasta.jl 25000000 > /dev/null

^C
^C
^C
Terminated

real	4m25,588s
user	0m0,004s
sys	0m0,000s

Note, CTRL-C didn't work to kill, I had to use the kill command (did in another terminal tab). I previously ran into hangs with hyperfine, which I do not believe implicated, it does the latter, but wqith it I could kill with CTRL-C, meaning hyperfine got killed but julia was still running in the background.

I would mark this as a regression. I've done plenty of benchmarking before, often with hyperfine for 1.6, or time (or just @btime), and this never happened with hyperfine. I'm however new to using only "sh -c" (which is implied by hyperfine). See at #39598 (comment)

This affect 1.7.0-beta2 too (tested later):

$ time sh -c ~/julia-1.7-DEV-da96fef327/bin/julia --startup-file=no -t4 -O2 fasta.jl 25000000 > /dev/null
Terminated

real	1m31,985s
user	0m0,001s
sys	0m0,003s

and strangely doing "nothing":

Note, I believe I pressed ENTER despite of ERROR on the same line. At least it was quick:

$ ~/julia-1.7-DEV-da96fef327/bin/juliaERROR: TaskFailedException
Stacktrace:
  [1] try_yieldto(undo::typeof(Base.ensure_rescheduled))
    @ Base ./task.jl:705
  [2] wait
    @ ./task.jl:764 [inlined]
  [3] wait(c::Base.GenericCondition{ReentrantLock})
    @ Base ./condition.jl:113
  [4] take_buffered(c::Channel{Any})
    @ Base ./channels.jl:389
  [5] take!
    @ ./channels.jl:383 [inlined]
  [6] repl_backend_loop(backend::REPL.REPLBackend)
    @ REPL /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/REPL.jl:195
  [7] start_repl_backend(backend::REPL.REPLBackend, consumer::Any)
    @ REPL /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/REPL.jl:185
  [8] run_repl(repl::REPL.AbstractREPL, consumer::Any; backend_on_current_task::Bool)
    @ REPL /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/REPL.jl:317
  [9] run_repl(repl::REPL.AbstractREPL, consumer::Any)
    @ REPL /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/REPL.jl:305
 [10] (::Base.var"#914#916"{Bool, Bool, Bool})(REPL::Module)
    @ Base ./client.jl:394
 [11] #invokelatest#2
    @ ./essentials.jl:721 [inlined]
 [12] invokelatest
    @ ./essentials.jl:719 [inlined]
 [13] run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_file::Bool, color_set::Bool)
    @ Base ./client.jl:379
 [14] exec_options(opts::Base.JLOptions)
    @ Base ./client.jl:309
 [15] _start()
    @ Base ./client.jl:492

    nested task error: IOError: stream is closed or unusable
    Stacktrace:
     [1] check_open(x::Base.TTY)
       @ Base ./stream.jl:386
     [2] raw!(t::REPL.Terminals.TTYTerminal, raw::Bool)
       @ REPL.Terminals /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/Terminals.jl:138
     [3] prompt!(term::REPL.Terminals.TextTerminal, prompt::REPL.LineEdit.ModalInterface, s::REPL.LineEdit.MIState)
       @ REPL.LineEdit /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/LineEdit.jl:2602
     [4] run_interface(terminal::REPL.Terminals.TextTerminal, m::REPL.LineEdit.ModalInterface, s::REPL.LineEdit.MIState)
       @ REPL.LineEdit /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/LineEdit.jl:2481
     [5] run_frontend(repl::REPL.LineEditREPL, backend::REPL.REPLBackendRef)
       @ REPL /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/REPL.jl:1126
     [6] (::REPL.var"#44#49"{REPL.LineEditREPL, REPL.REPLBackendRef})()
       @ REPL ./task.jl:406
    
    caused by: IOError: read: i/o error (EIO)
    Stacktrace:
     [1] wait_readnb(x::Base.TTY, nb::Int64)
       @ Base ./stream.jl:408
     [2] eof(s::Base.TTY)
       @ Base ./stream.jl:106
     [3] eof(io::REPL.Terminals.TTYTerminal)
       @ Base ./io.jl:416
     [4] match_input(k::Dict{Char, V} where V, s::Union{Nothing, REPL.LineEdit.MIState}, term::Union{REPL.Terminals.AbstractTerminal, IOBuffer}, cs::Vector{Char}, keymap::Dict{Char, V} where V) (repeats 4 times)
       @ REPL.LineEdit /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/LineEdit.jl:1475
     [5] prompt!(term::REPL.Terminals.TextTerminal, prompt::REPL.LineEdit.ModalInterface, s::REPL.LineEdit.MIState)
       @ REPL.LineEdit /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/LineEdit.jl:2571
     [6] run_interface(terminal::REPL.Terminals.TextTerminal, m::REPL.LineEdit.ModalInterface, s::REPL.LineEdit.MIState)
       @ REPL.LineEdit /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/LineEdit.jl:2481
     [7] run_frontend(repl::REPL.LineEditREPL, backend::REPL.REPLBackendRef)
       @ REPL /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.7/REPL/src/REPL.jl:1126
     [8] (::REPL.var"#44#49"{REPL.LineEditREPL, REPL.REPLBackendRef})()

then nothing for a while until I pressed ENTER (again?!) and got:

   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.7.0-DEV.714 (2021-03-16)
 _/ |\__'_|_|_|\__'_|  |  Commit da96fef327 (105 days old master)

This is getting strange, running that julia version straight after no problem. It's either only random and/or my machine getting strange. Any idea what could cause it? Everything else seems to work fine. I do not recall if I was using that exact git commit of 1.7 before.

I was probably using all my three 1.7 downloads frequently before, not sure which most, and running all of them once went ok now:

$ ~/julia-1.7-
julia-1.7-a7848a28e5/     julia-1.7-DEV-da96fef327/ julia-1.7-DEV-f2ea26d1a1/ 

B.
Since I got "ERROR: TaskFailedException" on the same line, it it plausible it was from previous invocation, i.e. when running with sh? If not then not even sh needs be implicated. I guess that's the mostly likely reason, since I tried later to run that 1.7 version 20 times in a row without any problems.

[PallHaraldsson]

sh is probably not needed to trigger this. It seems just random:

$ time sh -c ~/julia-1.8-DEV-7553ca13cc/bin/julia --startup-file=no -t4 -O2 fasta.jl 25000000 > /dev/null

signal (15): Terminated
in expression starting at none:0
epoll_wait at /lib/x86_64-linux-gnu/libc.so.6 (unknown line)
uv__io_poll at /workspace/srcdir/libuv/src/unix/linux-core.c:309
uv_run at /workspace/srcdir/libuv/src/unix/core.c:379
jl_task_get_next at /buildworker/worker/package_linux64/build/src/partr.c:476
poptask at ./task.jl:800
wait at ./task.jl:808 [inlined]
wait at ./condition.jl:112
wait_readnb at ./stream.jl:413
eof at ./stream.jl:106
jfptr_eof_42984.clone_1 at /home/pharaldsson_sym/julia-1.8-DEV-7553ca13cc/lib/julia/sys.so (unknown line)
_jl_invoke at /buildworker/worker/package_linux64/build/src/gf.c:2245 [inlined]
jl_apply_generic at /buildworker/worker/package_linux64/build/src/gf.c:2427
eof at ./io.jl:416
jfptr_eof_42989.clone_1 at /home/pharaldsson_sym/julia-1.8-DEV-7553ca13cc/lib/julia/sys.so (unknown line)
_jl_invoke at /buildworker/worker/package_linux64/build/src/gf.c:2245 [inlined]
jl_apply_generic at /buildworker/worker/package_linux64/build/src/gf.c:2427
match_input at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.8/REPL/src/LineEdit.jl:1482
match_input at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.8/REPL/src/LineEdit.jl:1482 [inlined]
match_input at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.8/REPL/src/LineEdit.jl:1482 [inlined]
match_input at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.8/REPL/src/LineEdit.jl:1482 [inlined]
prompt! at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.8/REPL/src/LineEdit.jl:2578
run_interface at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.8/REPL/src/LineEdit.jl:2488
jfptr_run_interface_47021.clone_1 at /home/pharaldsson_sym/julia-1.8-DEV-7553ca13cc/lib/julia/sys.so (unknown line)
_jl_invoke at /buildworker/worker/package_linux64/build/src/gf.c:2245 [inlined]
jl_apply_generic at /buildworker/worker/package_linux64/build/src/gf.c:2427
run_frontend at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.8/REPL/src/REPL.jl:1227
#49 at ./task.jl:411
jfptr_YY.49_47547.clone_1 at /home/pharaldsson_sym/julia-1.8-DEV-7553ca13cc/lib/julia/sys.so (unknown line)
_jl_invoke at /buildworker/worker/package_linux64/build/src/gf.c:2245 [inlined]
jl_apply_generic at /buildworker/worker/package_linux64/build/src/gf.c:2427
jl_apply at /buildworker/worker/package_linux64/build/src/julia.h:1787 [inlined]
start_task at /buildworker/worker/package_linux64/build/src/task.c:884
unknown function (ip: (nil))
Allocations: 2723 (Pool: 2712; Big: 11); GC: 0

real	1m44,213s
user	0m1,186s
sys	0m0,482s

then ran 5 times successfully without sh, until a problem:

$ time ~/julia-1.8-DEV-7553ca13cc/bin/julia --startup-file=no -t4 -O2 fasta.jl 25000000 > /dev/null

real	0m2,441s
user	0m6,672s
sys	0m0,855s

$ time ~/julia-1.8-DEV-7553ca13cc/bin/julia --startup-file=no -t4 -O2 fasta.jl 25000000 > /dev/null


^C
signal (2): Interrupt
in expression starting at /home/pharaldsson_sym/discretionary_dash/fasta.jl:131
jl_mutex_unlock_nogc at /buildworker/worker/package_linux64/build/src/locks.h:120 [inlined]
multiq_deletemin at /buildworker/worker/package_linux64/build/src/partr.c:184 [inlined]
get_next_task at /buildworker/worker/package_linux64/build/src/partr.c:401
jl_task_get_next at /buildworker/worker/package_linux64/build/src/partr.c:420
poptask at ./task.jl:800
wait at ./task.jl:808 [inlined]
task_done_hook at ./task.jl:531
_jl_invoke at /buildworker/worker/package_linux64/build/src/gf.c:2245 [inlined]
jl_apply_generic at /buildworker/worker/package_linux64/build/src/gf.c:2427
jl_apply at /buildworker/worker/package_linux64/build/src/julia.h:1787 [inlined]
jl_finish_task at /buildworker/worker/package_linux64/build/src/task.c:217
start_task at /buildworker/worker/package_linux64/build/src/task.c:895
unknown function (ip: (nil))
jl_safepoint_wait_gc at /buildworker/worker/package_linux64/build/src/safepoint.c:163
_IO_funlockfile at /lib/x86_64-linux-gnu/libpthread.so.0 (unknown line)
sigatomic_end at ./c.jl:437 [inlined]
task_done_hook at ./task.jl:529
unknown function (ip: (nil))
jl_gc_wait_for_the_world at /buildworker/worker/package_linux64/build/src/gc.c:205 [inlined]
jl_gc_collect at /buildworker/worker/package_linux64/build/src/gc.c:3230
maybe_collect at /buildworker/worker/package_linux64/build/src/gc.c:881 [inlined]
jl_gc_pool_alloc at /buildworker/worker/package_linux64/build/src/gc.c:1205
jl_gc_alloc_ at /buildworker/worker/package_linux64/build/src/julia_internal.h:353 [inlined]
_new_array_ at /buildworker/worker/package_linux64/build/src/array.c:134 [inlined]
_new_array at /buildworker/worker/package_linux64/build/src/array.c:190 [inlined]
jl_alloc_array_1d at /buildworker/worker/package_linux64/build/src/array.c:461
Array at ./boot.jl:457 [inlined]
generate_chunks at /home/pharaldsson_sym/discretionary_dash/fasta.jl:88
#9 at ./threadingconstructs.jl:178
unknown function (ip: 0x7fb599115dbf)
_jl_invoke at /buildworker/worker/package_linux64/build/src/gf.c:2245 [inlined]
jl_apply_generic at /buildworker/worker/package_linux64/build/src/gf.c:2427
jl_apply at /buildworker/worker/package_linux64/build/src/julia.h:1787 [inlined]
start_task at /buildworker/worker/package_linux64/build/src/task.c:884
unknown function (ip: (nil))
jl_safepoint_wait_gc at /buildworker/worker/package_linux64/build/src/safepoint.c:163
_IO_funlockfile at /lib/x86_64-linux-gnu/libpthread.so.0 (unknown line)
jl_gc_safepoint at /buildworker/worker/package_linux64/build/src/jlapi.c:465
unknown function (ip: (nil))
Allocations: 807427 (Pool: 807252; Big: 175); GC: 6

^[[A^[[B

^C
real	13m30,783s
user	54m0,265s
sys	0m0,796s

That last time I could interrupt with CTRL-C (while I do not get back the first one-two times the the shell), but not other times with sh. Then I used kill command. Likely just a coincidence.

[PallHaraldsson]

Confirmed the problem on beta2 (do not have access to beta3), while latest nightly, I just downloaded, worked so far 20 times in a row, so might be fixed (or not...).

[PallHaraldsson]

The code is from the Debian game:

import .Threads: @spawn

const LINESIZE = 60
const CHUNKSIZE = 512LINESIZE

const IM = 139968 % Int32
const IA = 3877 % Int32
const IC = 29573 % Int32
const SEED = Ref(42 % Int32)

gen_random() = (SEED[] = ((SEED[] * IA) + IC) % IM)

# Vector{UInt8} faster indexing than Base.CodeUnits{UInt8,String} (julia 1.2)
const alu = Vector{UInt8}(string(
   "GGCCGGGCGCGGTGGCTCACGCCTGTAATCCCAGCACTTTGG",
   "GAGGCCGAGGCGGGCGGATCACCTGAGGTCAGGAGTTCGAGA",
   "CCAGCCTGGCCAACATGGTGAAACCCCGTCTCTACTAAAAAT",
   "ACAAAAATTAGCCGGGCGTGGTGGCGCGCGCCTGTAATCCCA",
   "GCTACTCGGGAGGCTGAGGCAGGAGAATCGCTTGAACCCGGG",
   "AGGCGGAGGTTGCAGTGAGCCGAGATCGCGCCACTGCACTCC",
   "AGCCTGGGCGACAGAGCGAGACTCCGTCTCAAAAA"))

const iub1 = Vector{UInt8}("acgtBDHKMNRSVWY")
# Instead of the probability, iub2 is the integer upper-bounding the random
# integer to the equivalent index in iub1. cumsum is not used here as
# it adds almost 10% of total time to inference time.
const iub2 = [floor(Int32, IM * x) for x in
              (0.27, 0.39, 0.51, 0.78, 0.8, 0.82, 0.84, 0.86, 0.88, 0.9, 0.92,
               0.94, 0.96, 0.98, 1.0)]
const homosapiens1 = Vector{UInt8}("acgt")
const homosapiens2 = [floor(Int32, IM * x) for x in
                      (0.3029549426680, 0.5009432431601, 0.6984905497992, 1.0)]

# Defining a function with successive comparisons is faster than getindex lookup
for (op, symb, pr) in ((:iub, iub1, iub2),
                       (:homosapiens, homosapiens1, homosapiens2))
    # successively compares x with all values in pr and returns value from symb
    @eval @inline function $op(x)
        $([:(x <= $(pr[i]) && return $(symb[i])) for i=1:length(symb)]...)
        'a' % UInt8
    end
end

function repeat_fasta(io, src, n)
    len = length(src)
    pos = 1
    GC.@preserve src for i=1:LINESIZE:n
        # l is the number of characters we need to write this iteration.
        # m is less than l if not enough characters are left to write from src.
        l = min(LINESIZE, n - i + 1)
        m = min(l, len - pos + 1)

        unsafe_write(io, pointer(src, pos), m)
        if l != m # reached end of src
            # Loop back around to the start of src and write remaining chars
            pos = 1
            m = l - m
            unsafe_write(io, pointer(src, pos), m)
        end
        pos += m

        write(io, '\n')
    end
end

# Writes chunks of random characters from c to io with newlines added
# every LINESIZE. c is filled with Task which must be ordered. The
# chunks yielded from each Task must be a multiple in length of
# LINESIZE unless they are the last chunk in the channel.
function print_chunks(io, c)
    for vt in c
        v = fetch(vt)::Vector{UInt8}
        n = length(v)
        for i=1:LINESIZE:n
            GC.@preserve v unsafe_write(io, pointer(v, i),
                                        min(LINESIZE, n - i + 1))
            write(io, '\n')
        end
    end
end

# Put tasks that yield chunks of random characters into c. The total
# number of characters before c is closed will be n.
function generate_chunks(flookup, c, n)
    for p=1:CHUNKSIZE:n
        # Create a chunk of random Int32 of length l
        l = min(CHUNKSIZE, n - p + 1)
        v = Vector{Int32}(undef, l)
        # Fill chunk with random numbers
        for i=1:l
            @inbounds v[i] = gen_random()
        end

        # Spawn task to convert random Int32 to characters. We must
        # put this task in the channel synchronously to make sure we
        # preserve the order of writing.
        t = @spawn @inbounds map!(flookup, Vector{UInt8}(undef, l), v)
        put!(c, t)
    end
    close(c)
end

function random_fasta(io, flookup, n, firstline, iotask, rtask=nothing)
    c = Channel{Task}(24)

    # We cannot proceed with generating random numbers until rtask is
    # complete otherwise the random numbers will be interleaved.
    rtask === nothing || wait(rtask)
    rtask = @spawn generate_chunks(flookup, c, n)
    # Similarily, we can't start writing to io until the previous
    # iotask has completed.
    iotask2 = @spawn begin
        wait(iotask)
        write(io, firstline)
        print_chunks(io, c)
    end

    iotask2, rtask
end

function fasta(n=25000000, io=stdout)
    write(io, ">ONE Homo sapiens alu\n")
    io1 = @spawn repeat_fasta(io, alu, 2n)

    io2, r1 = random_fasta(io, iub, 3n, ">TWO IUB ambiguity codes\n", io1)
    io3, _ = random_fasta(io, homosapiens, 5n, ">THREE Homo sapiens frequency\n",
                          io2, r1)
    wait(io3)
end

isinteractive() || fasta(parse(Int,ARGS[1]))

[PallHaraldsson]

Too bad, it also hung on nightly (just seems less rare, thus more dangerous):

$ time ~/julia-1.8-DEV-d1145d4569/bin/julia --startup-file=no -t4 fasta.jl 25000000 > /dev/null
^C
signal (2): Interrupt
in expression starting at /home/pharaldsson_sym/discretionary_dash/fasta.jl:131
multiq_deletemin at /buildworker/worker/package_linux64/build/src/partr.c:171 [inlined]
get_next_task at /buildworker/worker/package_linux64/build/src/partr.c:401
jl_task_get_next at /buildworker/worker/package_linux64/build/src/partr.c:420
poptask at ./task.jl:800
wait at ./task.jl:808 [inlined]
task_done_hook at ./task.jl:531
_jl_invoke at /buildworker/worker/package_linux64/build/src/gf.c:2245 [inlined]
jl_apply_generic at /buildworker/worker/package_linux64/build/src/gf.c:2427
jl_apply at /buildworker/worker/package_linux64/build/src/julia.h:1787 [inlined]
jl_finish_task at /buildworker/worker/package_linux64/build/src/task.c:217
start_task at /buildworker/worker/package_linux64/build/src/task.c:895
unknown function (ip: (nil))
jl_gc_wait_for_the_world at /buildworker/worker/package_linux64/build/src/gc.c:205 [inlined]
jl_gc_collect at /buildworker/worker/package_linux64/build/src/gc.c:3230
maybe_collect at /buildworker/worker/package_linux64/build/src/gc.c:881 [inlined]
jl_gc_pool_alloc at /buildworker/worker/package_linux64/build/src/gc.c:1205
jl_gc_alloc_ at /buildworker/worker/package_linux64/build/src/julia_internal.h:353 [inlined]
_new_array_ at /buildworker/worker/package_linux64/build/src/array.c:134 [inlined]
_new_array at /buildworker/worker/package_linux64/build/src/array.c:190 [inlined]
jl_alloc_array_1d at /buildworker/worker/package_linux64/build/src/array.c:461
Array at ./boot.jl:457 [inlined]
generate_chunks at /home/pharaldsson_sym/discretionary_dash/fasta.jl:88
#9 at ./threadingconstructs.jl:178
unknown function (ip: 0x7fa89cbdbdbf)
_jl_invoke at /buildworker/worker/package_linux64/build/src/gf.c:2245 [inlined]
jl_apply_generic at /buildworker/worker/package_linux64/build/src/gf.c:2427
jl_apply at /buildworker/worker/package_linux64/build/src/julia.h:1787 [inlined]
start_task at /buildworker/worker/package_linux64/build/src/task.c:884
unknown function (ip: (nil))
_mm_pause at /usr/local/lib/gcc/x86_64-pc-linux-gnu/7.3.0/include/xmmintrin.h:1267 [inlined]
jl_safepoint_wait_gc at /buildworker/worker/package_linux64/build/src/safepoint.c:164
jl_set_gc_and_wait at /buildworker/worker/package_linux64/build/src/julia_internal.h:792 [inlined]
segv_handler at /buildworker/worker/package_linux64/build/src/signals-unix.c:322
_IO_funlockfile at /lib/x86_64-linux-gnu/libpthread.so.0 (unknown line)
sigatomic_end at ./c.jl:437 [inlined]
task_done_hook at ./task.jl:529
unknown function (ip: (nil))
jl_safepoint_wait_gc at /buildworker/worker/package_linux64/build/src/safepoint.c:163
jl_set_gc_and_wait at /buildworker/worker/package_linux64/build/src/julia_internal.h:792 [inlined]
segv_handler at /buildworker/worker/package_linux64/build/src/signals-unix.c:322
_IO_funlockfile at /lib/x86_64-linux-gnu/libpthread.so.0 (unknown line)
jl_gc_safepoint at /buildworker/worker/package_linux64/build/src/jlapi.c:465
unknown function (ip: (nil))
Allocations: 829005 (Pool: 828830; Big: 175); GC: 13

^C
real	0m31,464s
user	2m3,095s
sys	0m0,772s

For the older nightly, this Heisenbug seems to be less frequent, or totally absent on -01. May also be true for the latest nightly.