Performance regression in locking #38947
Description
@garrison pointed out (timholy/ProgressMeter.jl#175 (comment)) that ProgressMeter slows things down more than it used to:
using ProgressMeter
function prog_perf(n)
prog = Progress(n)
x = 0.0
for i in 1:n
x += rand()
next!(prog)
end
return x
end
@time(prog_perf(10^7))
Julia 1.5: 0.860743 seconds (358 allocations: 45.047 KiB)
master: 1.340942 seconds (560 allocations: 61.328 KiB)Profiling suggests that the difference is primarily in the locking (set Profile.init(delay=0.01) before trying this):
Julia 1.5 profile:
julia> Profile.print()
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
╎93 @Base/client.jl:506; _start()
╎ 93 @Base/client.jl:313; exec_options(::Base.JLOptions)
╎ 93 @Base/client.jl:383; run_main_repl(::Bool, ::Bool, ::Bool, ::Bool, ::Bool)
╎ 93 @Base/essentials.jl:709; invokelatest
╎ 93 @Base/essentials.jl:710; #invokelatest#1
╎ 93 @Base/client.jl:399; (::Base.var"#807#809"{Bool,Bool,Bool,Bool})(::Module)
╎ ╎ 93 @REPL/src/REPL.jl:288; run_repl(::REPL.AbstractREPL, ::Any)
╎ ╎ 93 @REPL/src/REPL.jl:292; run_repl(::REPL.AbstractREPL, ::Any; backend_on_current_task::Bool)
╎ ╎ 93 @REPL/src/REPL.jl:180; start_repl_backend(::REPL.REPLBackend, ::Any)
╎ ╎ 93 @REPL/src/REPL.jl:195; repl_backend_loop(::REPL.REPLBackend)
╎ ╎ 93 @REPL/src/REPL.jl:134; eval_user_input(::Any, ::REPL.REPLBackend)
╎ ╎ ╎ 93 @Base/boot.jl:331; eval(::Module, ::Any)
╎ ╎ ╎ 5 REPL[2]:5; prog_perf(::Int64)
2╎ ╎ ╎ 2 @Base/float.jl:401; +
╎ ╎ ╎ 3 @Random/src/Random.jl:256; rand
╎ ╎ ╎ 1 @Random/src/RNGs.jl:298; default_rng
╎ ╎ ╎ 1 @Random/src/RNGs.jl:300; default_rng(::Int64)
1╎ ╎ ╎ ╎ 1 @Base/array.jl:219; length
╎ ╎ ╎ 2 @Random/src/Random.jl:256; rand
╎ ╎ ╎ 2 @Random/src/generation.jl:35; rand
2╎ ╎ ╎ ╎ 2 @Base/float.jl:403; -
╎ ╎ ╎ 87 REPL[2]:6; prog_perf(::Int64)
╎ ╎ ╎ 87 @ProgressMeter/src/ProgressMeter.jl:342; next!
╎ ╎ ╎ 87 @ProgressMeter/src/ProgressMeter.jl:342; #next!#13
2╎ ╎ ╎ 2 @Base/lock.jl:158; lock(::ProgressMeter.var"#14#15"{Int64,Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),...
2╎ ╎ ╎ 16 @Base/lock.jl:159; lock(::ProgressMeter.var"#14#15"{Int64,Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),...
1╎ ╎ ╎ ╎ 1 @Base/lock.jl:67; lock(::ReentrantLock)
╎ ╎ ╎ ╎ 12 @Base/lock.jl:69; lock(::ReentrantLock)
1╎ ╎ ╎ ╎ 12 @Base/condition.jl:73; lock
2╎ ╎ ╎ ╎ 2 @Base/locks-mt.jl:61; lock(::Base.Threads.SpinLock)
╎ ╎ ╎ ╎ 8 @Base/locks-mt.jl:65; lock(::Base.Threads.SpinLock)
8╎ ╎ ╎ ╎ 8 @Base/promotion.jl:398; ==
1╎ ╎ ╎ ╎ 1 @Base/locks-mt.jl:66; lock(::Base.Threads.SpinLock)
1╎ ╎ ╎ ╎ 1 @Base/lock.jl:87; lock(::ReentrantLock)
5╎ ╎ ╎ 5 @Base/lock.jl:160; lock(::ProgressMeter.var"#14#15"{Int64,Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),...
8╎ ╎ ╎ 44 @Base/lock.jl:161; lock(::ProgressMeter.var"#14#15"{Int64,Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),...
╎ ╎ ╎ ╎ 36 @ProgressMeter/src/ProgressMeter.jl:344; #14
3╎ ╎ ╎ ╎ 36 @ProgressMeter/src/ProgressMeter.jl:203; updateProgress!
╎ ╎ ╎ ╎ 32 @ProgressMeter/src/ProgressMeter.jl:210; updateProgress!(::Progress; showvalues::Tuple{}, truncate_lines::Bool, valuecolor::Symbol, offse...
31╎ ╎ ╎ ╎ 32 @Base/libc.jl:247; time
1╎ ╎ ╎ ╎ 1 @ProgressMeter/src/ProgressMeter.jl:229; updateProgress!(::Progress; showvalues::Tuple{}, truncate_lines::Bool, valuecolor::Symbol, offse...
2╎ ╎ ╎ 20 @Base/lock.jl:163; lock(::ProgressMeter.var"#14#15"{Int64,Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),...
╎ ╎ ╎ ╎ 17 @Base/lock.jl:102; unlock(::ReentrantLock)
3╎ ╎ ╎ ╎ 17 @Base/condition.jl:73; lock
1╎ ╎ ╎ ╎ 1 @Base/locks-mt.jl:61; lock(::Base.Threads.SpinLock)
╎ ╎ ╎ ╎ 2 @Base/locks-mt.jl:64; lock(::Base.Threads.SpinLock)
2╎ ╎ ╎ ╎ 2 @Base/locks-mt.jl:36; _xchg!
╎ ╎ ╎ ╎ 10 @Base/locks-mt.jl:65; lock(::Base.Threads.SpinLock)
10╎ ╎ ╎ ╎ 10 @Base/promotion.jl:398; ==
1╎ ╎ ╎ ╎ 1 @Base/locks-mt.jl:66; lock(::Base.Threads.SpinLock)
1╎ ╎ ╎ ╎ 1 @Base/locks-mt.jl:61; lock(::Base.Threads.SpinLock)
1╎ ╎ ╎ 1 @Random/src/RNGs.jl:307; default_rng(::Int64)
Total snapshots: 95
Julia master profile:
julia> Profile.print()
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
╎133 @Base/client.jl:485; _start()
╎ 133 @Base/client.jl:302; exec_options(opts::Base.JLOptions)
╎ 133 @Base/client.jl:372; run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_file::Bool, color_set::Bool)
╎ 133 @Base/essentials.jl:706; invokelatest
╎ 133 @Base/essentials.jl:707; #invokelatest#2
╎ 133 @Base/client.jl:387; (::Base.var"#873#875"{Bool, Bool, Bool})(REPL::Module)
╎ ╎ 133 @REPL/src/REPL.jl:305; run_repl(repl::REPL.AbstractREPL, consumer::Any)
╎ ╎ 133 @REPL/src/REPL.jl:317; run_repl(repl::REPL.AbstractREPL, consumer::Any; backend_on_current_task::Bool)
╎ ╎ 133 @REPL/src/REPL.jl:185; start_repl_backend(backend::REPL.REPLBackend, consumer::Any)
╎ ╎ 133 @REPL/src/REPL.jl:200; repl_backend_loop(backend::REPL.REPLBackend)
╎ ╎ 133 @REPL/src/REPL.jl:139; eval_user_input(ast::Any, backend::REPL.REPLBackend)
╎ ╎ ╎ 133 @Base/boot.jl:360; eval(m::Module, e::Any)
2╎ ╎ ╎ 2 REPL[2]:0; prog_perf(n::Int64)
╎ ╎ ╎ 2 REPL[2]:5; prog_perf(n::Int64)
╎ ╎ ╎ 2 @Random/src/Random.jl:256; rand
╎ ╎ ╎ 2 @Random/src/Random.jl:256; rand
╎ ╎ ╎ 2 @Random/src/generation.jl:35; rand
╎ ╎ ╎ ╎ 2 @Random/src/Random.jl:253; rand
╎ ╎ ╎ ╎ 2 @Random/src/RNGs.jl:459; rand
╎ ╎ ╎ ╎ 2 @Random/src/RNGs.jl:233; reserve_1
╎ ╎ ╎ ╎ 2 @Random/src/RNGs.jl:229; gen_rand(r::Random.MersenneTwister)
╎ ╎ ╎ ╎ 2 @Random/src/RNGs.jl:542; fill_array!
╎ ╎ ╎ ╎ ╎ 2 @Random/src/RNGs.jl:548; fill_array!
2╎ ╎ ╎ ╎ ╎ 2 @Random/src/DSFMT.jl:85; dsfmt_fill_array_close1_open2!(s::Random.DSFMT.DSFMT_state, A::Ptr{Float64}, n::Int64)
10╎ ╎ ╎ 127 REPL[2]:6; prog_perf(n::Int64)
╎ ╎ ╎ 2 @Base/range.jl:671; iterate
2╎ ╎ ╎ 2 @Base/promotion.jl:410; ==
2╎ ╎ ╎ 2 @ProgressMeter/src/ProgressMeter.jl:341; next!(p::Progress)
╎ ╎ ╎ 113 @ProgressMeter/src/ProgressMeter.jl:342; next!(p::Progress)
2╎ ╎ ╎ 113 @ProgressMeter/src/ProgressMeter.jl:342; #next!#13
3╎ ╎ ╎ 3 @Base/lock.jl:184; lock(f::ProgressMeter.var"#14#15"{Int64, Base.Iterators.Pairs{Union{}, Union{}, Tuple{}, NamedTup...
╎ ╎ ╎ 23 @Base/lock.jl:185; lock(f::ProgressMeter.var"#14#15"{Int64, Base.Iterators.Pairs{Union{}, Union{}, Tuple{}, NamedTup...
2╎ ╎ ╎ ╎ 2 @Base/lock.jl:86; lock(rl::ReentrantLock)
╎ ╎ ╎ ╎ 12 @Base/lock.jl:91; lock(rl::ReentrantLock)
╎ ╎ ╎ ╎ 12 @Base/condition.jl:73; lock
3╎ ╎ ╎ ╎ 3 @Base/locks-mt.jl:61; lock(l::Base.Threads.SpinLock)
╎ ╎ ╎ ╎ 3 @Base/locks-mt.jl:64; lock(l::Base.Threads.SpinLock)
3╎ ╎ ╎ ╎ 3 @Base/gcutils.jl:117; enable_finalizers
╎ ╎ ╎ ╎ 1 @Base/locks-mt.jl:65; lock(l::Base.Threads.SpinLock)
1╎ ╎ ╎ ╎ 1 @Base/locks-mt.jl:36; _xchg!
╎ ╎ ╎ ╎ 5 @Base/locks-mt.jl:66; lock(l::Base.Threads.SpinLock)
5╎ ╎ ╎ ╎ 5 @Base/promotion.jl:410; ==
╎ ╎ ╎ ╎ 3 @Base/lock.jl:96; lock(rl::ReentrantLock)
3╎ ╎ ╎ ╎ 3 @Base/gcutils.jl:117; enable_finalizers
╎ ╎ ╎ ╎ 2 @Base/lock.jl:106; lock(rl::ReentrantLock)
1╎ ╎ ╎ ╎ 1 @Base/Base.jl:33; getproperty
╎ ╎ ╎ ╎ 1 @Base/condition.jl:74; unlock
╎ ╎ ╎ ╎ 1 @Base/locks-mt.jl:92; unlock(l::Base.Threads.SpinLock)
1╎ ╎ ╎ ╎ 1 @Base/gcutils.jl:117; enable_finalizers
1╎ ╎ ╎ ╎ 1 @Base/lock.jl:108; lock(rl::ReentrantLock)
1╎ ╎ ╎ ╎ 1 @Base/locks-mt.jl:67; lock(l::Base.Threads.SpinLock)
╎ ╎ ╎ ╎ 2 @Base/locks-mt.jl:92; unlock(l::Base.Threads.SpinLock)
2╎ ╎ ╎ ╎ 2 @Base/gcutils.jl:117; enable_finalizers
6╎ ╎ ╎ 6 @Base/lock.jl:186; lock(f::ProgressMeter.var"#14#15"{Int64, Base.Iterators.Pairs{Union{}, Union{}, Tuple{}, NamedTup...
7╎ ╎ ╎ 45 @Base/lock.jl:187; lock(f::ProgressMeter.var"#14#15"{Int64, Base.Iterators.Pairs{Union{}, Union{}, Tuple{}, NamedTup...
1╎ ╎ ╎ ╎ 1 @ProgressMeter/src/ProgressMeter.jl:343; #14
╎ ╎ ╎ ╎ 36 @ProgressMeter/src/ProgressMeter.jl:344; #14
3╎ ╎ ╎ ╎ 36 @ProgressMeter/src/ProgressMeter.jl:203; updateProgress!
1╎ ╎ ╎ ╎ 1 @Base/promotion.jl:410; ==
1╎ ╎ ╎ ╎ 1 @ProgressMeter/src/ProgressMeter.jl:0; updateProgress!(p::Progress; showvalues::Tuple{}, truncate_lines::Bool, valuecolor::Symbol, offs...
2╎ ╎ ╎ ╎ 2 @ProgressMeter/src/ProgressMeter.jl:202; updateProgress!(p::Progress; showvalues::Tuple{}, truncate_lines::Bool, valuecolor::Symbol, offs...
╎ ╎ ╎ ╎ 28 @ProgressMeter/src/ProgressMeter.jl:210; updateProgress!(p::Progress; showvalues::Tuple{}, truncate_lines::Bool, valuecolor::Symbol, offs...
28╎ ╎ ╎ ╎ 28 @Base/libc.jl:249; time
1╎ ╎ ╎ ╎ 1 @ProgressMeter/src/ProgressMeter.jl:229; updateProgress!(p::Progress; showvalues::Tuple{}, truncate_lines::Bool, valuecolor::Symbol, offs...
7╎ ╎ ╎ 34 @Base/lock.jl:189; lock(f::ProgressMeter.var"#14#15"{Int64, Base.Iterators.Pairs{Union{}, Union{}, Tuple{}, NamedTup...
2╎ ╎ ╎ ╎ 2 @Base/lock.jl:119; unlock(rl::ReentrantLock)
╎ ╎ ╎ ╎ 1 @Base/lock.jl:122; unlock(rl::ReentrantLock)
1╎ ╎ ╎ ╎ 1 @Base/promotion.jl:410; ==
╎ ╎ ╎ ╎ 16 @Base/lock.jl:127; unlock(rl::ReentrantLock)
2╎ ╎ ╎ ╎ 2 @Base/Base.jl:33; getproperty
╎ ╎ ╎ ╎ 14 @Base/condition.jl:73; lock
2╎ ╎ ╎ ╎ 2 @Base/locks-mt.jl:61; lock(l::Base.Threads.SpinLock)
╎ ╎ ╎ ╎ 6 @Base/locks-mt.jl:64; lock(l::Base.Threads.SpinLock)
6╎ ╎ ╎ ╎ 6 @Base/gcutils.jl:117; enable_finalizers
╎ ╎ ╎ ╎ 5 @Base/locks-mt.jl:66; lock(l::Base.Threads.SpinLock)
5╎ ╎ ╎ ╎ 5 @Base/promotion.jl:410; ==
1╎ ╎ ╎ ╎ 1 @Base/locks-mt.jl:67; lock(l::Base.Threads.SpinLock)
╎ ╎ ╎ ╎ 4 @Base/lock.jl:139; unlock(rl::ReentrantLock)
╎ ╎ ╎ ╎ 4 @Base/condition.jl:74; unlock
╎ ╎ ╎ ╎ 4 @Base/locks-mt.jl:92; unlock(l::Base.Threads.SpinLock)
4╎ ╎ ╎ ╎ 4 @Base/gcutils.jl:117; enable_finalizers
2╎ ╎ ╎ ╎ 2 @Base/lock.jl:141; unlock(rl::ReentrantLock)
2╎ ╎ ╎ ╎ 2 @Base/locks-mt.jl:89; unlock(l::Base.Threads.SpinLock)
2╎ ╎ ╎ 2 @Random/src/RNGs.jl:379; default_rng(tid::Int64)
╎1 @Base/locks-mt.jl:64; lock(l::Base.Threads.SpinLock)
1╎ 1 @Base/gcutils.jl:117; enable_finalizers
╎2 @Base/locks-mt.jl:92; unlock(l::Base.Threads.SpinLock)
2╎ 2 @Base/gcutils.jl:117; enable_finalizers
Total snapshots: 139