Timing 1.9 WAS (mistaken): Hang on 1.6.6, 1.7.0, julia-1.8.0-beta3 and 1.9

Palli · July 4, 2022, 5:40pm

EDIT: @rssdev1 it’s obvious, in hindsight, that your test code had 1/4 (for 15 sec.) change of failing! Nothing to do with memory/GC or the new option, which is great! And thanks for fixing the test code now in the PR.

What might be happening in stable version of Julia (or with (or without) this new option in 1.9)? In 1.6.6/1.7.0 (likely all versions sometimes), when the program also (sometimes) seems to hang (meant to run for 15 sec):

$ time julia memory_test.jl
^C
^Z
[1]+  Stopped                 julia memory_test.jl

real	1m55,687s

Program from:
https://github.com/JuliaLang/julia/pull/45369

I’ve had this fail or succeed with --heap-size-hint=294m (one lower might always work), but way higher has also worked (and way lower didn’t):

$time ~/julia-1.9-DEV-a60c76ea57/bin/julia --heap-size-hint=360m memory_test.jl
(counter, mem_size) = (163638, 0x01000000)

real	0m15,299s
user	0m13,960s
sys	0m2,883s

$ time ~/julia-1.9-DEV-a60c76ea57/bin/julia --heap-size-hint=380m memory_test.jl
^C
signal (2): Interrupt
in expression starting at /home/pharaldsson_sym/julia_source/julia/memory_test.jl:5
reset_page at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:1189 [inlined]
sweep_page at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:1337 [inlined]
sweep_pool_page at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:1442 [inlined]
sweep_pool_pagetable0 at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:1462 [inlined]
sweep_pool_pagetable1 at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:1482 [inlined]
sweep_pool_pagetable at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:1512 [inlined]
gc_sweep_pool at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:1587
_jl_gc_collect at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:3215
ijl_gc_collect at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:3358
maybe_collect at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:898 [inlined]
jl_gc_pool_alloc_inner at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:1242 [inlined]
jl_gc_pool_alloc_noinline at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:1301
jl_gc_alloc_ at /cache/build/default-amdci5-2/julialang/julia-master/src/julia_internal.h:379 [inlined]
_new_array_ at /cache/build/default-amdci5-2/julialang/julia-master/src/array.c:144 [inlined]
_new_array at /cache/build/default-amdci5-2/julialang/julia-master/src/array.c:198 [inlined]
ijl_alloc_array_1d at /cache/build/default-amdci5-2/julialang/julia-master/src/array.c:436
Array at ./boot.jl:461 [inlined]
Array at ./baseext.jl:23 [inlined]
top-level scope at /home/pharaldsson_sym/julia_source/julia/memory_test.jl:11
jl_toplevel_eval_flex at /cache/build/default-amdci5-2/julialang/julia-master/src/toplevel.c:903
jl_toplevel_eval_flex at /cache/build/default-amdci5-2/julialang/julia-master/src/toplevel.c:856
ijl_toplevel_eval_in at /cache/build/default-amdci5-2/julialang/julia-master/src/toplevel.c:971
eval at ./boot.jl:370 [inlined]
include_string at ./loading.jl:1375
_jl_invoke at /cache/build/default-amdci5-2/julialang/julia-master/src/gf.c:2393 [inlined]
ijl_apply_generic at /cache/build/default-amdci5-2/julialang/julia-master/src/gf.c:2575
_include at ./loading.jl:1435
include at ./Base.jl:418
jfptr_include_33667.clone_1 at /home/pharaldsson_sym/julia-1.9-DEV-a60c76ea57/lib/julia/sys.so (unknown line)
_jl_invoke at /cache/build/default-amdci5-2/julialang/julia-master/src/gf.c:2393 [inlined]
ijl_apply_generic at /cache/build/default-amdci5-2/julialang/julia-master/src/gf.c:2575
exec_options at ./client.jl:299
_start at ./client.jl:516
jfptr__start_29466.clone_1 at /home/pharaldsson_sym/julia-1.9-DEV-a60c76ea57/lib/julia/sys.so (unknown line)
_jl_invoke at /cache/build/default-amdci5-2/julialang/julia-master/src/gf.c:2393 [inlined]
ijl_apply_generic at /cache/build/default-amdci5-2/julialang/julia-master/src/gf.c:2575
jl_apply at /cache/build/default-amdci5-2/julialang/julia-master/src/julia.h:1845 [inlined]
true_main at /cache/build/default-amdci5-2/julialang/julia-master/src/jlapi.c:567
jl_repl_entrypoint at /cache/build/default-amdci5-2/julialang/julia-master/src/jlapi.c:711
main at /cache/build/default-amdci5-2/julialang/julia-master/cli/loader_exe.c:59
unknown function (ip: 0x7f383bf4ed8f)
__libc_start_main at /lib/x86_64-linux-gnu/libc.so.6 (unknown line)
unknown function (ip: 0x401098)
unknown function (ip: (nil))
Allocations: 1022925 (Pool: 1022713; Big: 212); GC: 392948

real	0m36,161s
user	0m31,910s
sys	0m5,753s

I don’t see any OOM on Linux in /var/log/syslog can someone test on e.g. Windows (or Linux).

I doubt there’s any safe version where this does work (1.7.0 is my only 1.7.x), or any safe value in 1.9:

$ time ~/julia-1.9-DEV-a60c76ea57/bin/julia --heap-size-hint=10m memory_test.jl
^C
signal (2): Interrupt
in expression starting at /home/pharaldsson_sym/julia_source/julia/memory_test.jl:5
gc_setmark_tag at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:752 [inlined]
gc_try_setmark at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:1762 [inlined]
gc_mark_scan_obj8 at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:2001 [inlined]
gc_mark_loop at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:2297
_jl_gc_collect at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:3096
ijl_gc_collect at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:3358
maybe_collect at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:898 [inlined]
jl_gc_pool_alloc_inner at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:1242 [inlined]
jl_gc_pool_alloc_noinline at /cache/build/default-amdci5-2/julialang/julia-master/src/gc.c:1301
jl_gc_alloc_ at /cache/build/default-amdci5-2/julialang/julia-master/src/julia_internal.h:379 [inlined]
_new_array_ at /cache/build/default-amdci5-2/julialang/julia-master/src/array.c:144 [inlined]
_new_array at /cache/build/default-amdci5-2/julialang/julia-master/src/array.c:198 [inlined]
ijl_alloc_array_1d at /cache/build/default-amdci5-2/julialang/julia-master/src/array.c:436
Array at ./boot.jl:461 [inlined]
Array at ./baseext.jl:23 [inlined]
top-level scope at /home/pharaldsson_sym/julia_source/julia/memory_test.jl:11
jl_toplevel_eval_flex at /cache/build/default-amdci5-2/julialang/julia-master/src/toplevel.c:903
jl_toplevel_eval_flex at /cache/build/default-amdci5-2/julialang/julia-master/src/toplevel.c:856
ijl_toplevel_eval_in at /cache/build/default-amdci5-2/julialang/julia-master/src/toplevel.c:971
eval at ./boot.jl:370 [inlined]
include_string at ./loading.jl:1375
_jl_invoke at /cache/build/default-amdci5-2/julialang/julia-master/src/gf.c:2393 [inlined]
ijl_apply_generic at /cache/build/default-amdci5-2/julialang/julia-master/src/gf.c:2575
_include at ./loading.jl:1435
include at ./Base.jl:418
jfptr_include_33667.clone_1 at /home/pharaldsson_sym/julia-1.9-DEV-a60c76ea57/lib/julia/sys.so (unknown line)
_jl_invoke at /cache/build/default-amdci5-2/julialang/julia-master/src/gf.c:2393 [inlined]
ijl_apply_generic at /cache/build/default-amdci5-2/julialang/julia-master/src/gf.c:2575
exec_options at ./client.jl:299
_start at ./client.jl:516
jfptr__start_29466.clone_1 at /home/pharaldsson_sym/julia-1.9-DEV-a60c76ea57/lib/julia/sys.so (unknown line)
_jl_invoke at /cache/build/default-amdci5-2/julialang/julia-master/src/gf.c:2393 [inlined]
ijl_apply_generic at /cache/build/default-amdci5-2/julialang/julia-master/src/gf.c:2575
jl_apply at /cache/build/default-amdci5-2/julialang/julia-master/src/julia.h:1845 [inlined]
true_main at /cache/build/default-amdci5-2/julialang/julia-master/src/jlapi.c:567
jl_repl_entrypoint at /cache/build/default-amdci5-2/julialang/julia-master/src/jlapi.c:711
main at /cache/build/default-amdci5-2/julialang/julia-master/cli/loader_exe.c:59
unknown function (ip: 0x7fcab997dd8f)
__libc_start_main at /lib/x86_64-linux-gnu/libc.so.6 (unknown line)
unknown function (ip: 0x401098)
unknown function (ip: (nil))
Allocations: 237675 (Pool: 237464; Big: 211); GC: 324

real	0m31,044s
user	0m31,381s
sys	0m1,388s

Palli · July 4, 2022, 5:56pm

Reported:
https://github.com/JuliaLang/julia/issues/45928

Palli · July 4, 2022, 6:31pm

EDIT: Even disabling the allocation line, then it sometimes fails, so about Dates, in the while line?!

I tried to simplify the program for faster testing, also sometimes hangs with 5 sec, and smaller mem_size (EDIT: that also failed: ~~but if I change to Vector{Int64} it strangely may always work (or I just got lucky so far)~~:

$ time ~/julia-1.6.6/bin/julia memory_test_new.jl

const mem_size = 0x100_000

using Dates

counter = let
    counter = 0
    start_t = now()

    while Dates.second(now()) - Dates.second(start_t) < 5
        counter += 1
        arr = Vector{Int32}(undef, mem_size)
#        arr[rand(1:mem_size)] = rand(Int32, 1)[begin]
        # sleep(1)
    end
    counter
end

@show counter, mem_size

Palli · July 4, 2022, 6:40pm

MWE (in 1.6.6):

julia> using Dates
julia> start_t = now()
2022-07-04T18:38:39.717

julia> while Dates.second(now()) - Dates.second(start_t) < 5
       end

julia> while Dates.second(now()) - Dates.second(start_t) < 5
       end

julia> start_t = now()
2022-07-04T18:38:57.901

julia> while Dates.second(now()) - Dates.second(start_t) < 5
       end
^C

jebej · July 4, 2022, 6:41pm

Did you see the reply in the issue you created? The problem is that subtracting only the Dates.second part of two timestamps can lead to negative numbers.

jebej · July 4, 2022, 6:45pm

replacing the above with now() - start_t < Dates.Second(5) should fix it.

Palli · July 4, 2022, 11:00pm

@rssdev10 I was hoping this new option could help with the Debian BenchmarkGame. I tried on almost all the benchmarks, and it doesn’t seem to do much, except hurt, if you go too low, can e.g. more than double your runtime (when multi-threaded).

$ hyperfine '~/julia-1.9-DEV-a60c76ea57/bin/julia -O3 -t4 --heap-size-hint=80m --cpu-target=ivybridge --math-mode=ieee binarytree.jl 21'
Benchmark 1: ~/julia-1.9-DEV-a60c76ea57/bin/julia -O3 -t4 --heap-size-hint=80m --cpu-target=ivybridge --math-mode=ieee binarytree.jl 21
 ⠼ Current estimate: 18.633 s     ███████████░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ ETA 00:02:48

 hyperfine '~/julia-1.9-DEV-a60c76ea57/bin/julia -O3 -t4 --heap-size-hint=8000m --cpu-target=ivybridge --math-mode=ieee binarytree.jl 21'
Benchmark 1: ~/julia-1.9-DEV-a60c76ea57/bin/julia -O3 -t4 --heap-size-hint=8000m --cpu-target=ivybridge --math-mode=ieee binarytree.jl 21
  Time (mean ± σ):      8.609 s ±  0.184 s    [User: 18.213 s, System: 5.822 s]
  Range (min … max):    8.356 s …  8.899 s    10 runs

I tried, from 1, 80m, 800m etc. up to 800000m (or none), and same the options didn’t hurt as much when single-threaded:

$ hyperfine '~/julia-1.9-DEV-a60c76ea57/bin/julia -O3 --heap-size-hint=80m --cpu-target=ivybridge --math-mode=ieee binarytree.jl 21'
Benchmark 1: ~/julia-1.9-DEV-a60c76ea57/bin/julia -O3 --heap-size-hint=80m --cpu-target=ivybridge --math-mode=ieee binarytree.jl 21
 ⠋ Current estimate: 17.569 s     ███████████░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ ETA 00:02:38
^C
$ hyperfine '~/julia-1.9-DEV-a60c76ea57/bin/julia -O3 --heap-size-hint=800m --cpu-target=ivybridge --math-mode=ieee binarytree.jl 21'
Benchmark 1: ~/julia-1.9-DEV-a60c76ea57/bin/julia -O3 --heap-size-hint=800m --cpu-target=ivybridge --math-mode=ieee binarytree.jl 21
 ⠧ Current estimate: 12.515 s     ███████████░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ ETA 00:01:53
^C

rssdev10 · July 5, 2022, 12:07am

heap-size-hint is just a hint to GC to start collecting memory more aggressive. As a result you can see time increase with --heap-size-hint=80m. But there is no guarantee that heap consumption will be the same as the hint. And, there is a minimal memory consumption by Julia itself, and that is more than 80M. So, in that case, you are configuring GC to be always aggressive.

Actually, my role in that patch was adding of the command line interface for that option only. About the algorithms and details of GC ask chflood