Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Performance regression in locking #38947

Closed
timholy opened this issue Dec 19, 2020 · 5 comments
Closed

Performance regression in locking #38947

timholy opened this issue Dec 19, 2020 · 5 comments
Assignees
@JeffBezanson
Labels
multithreading Base.Threads and related functionality performance Must go faster regression Regression in behavior compared to a previous version

Comments

@timholy
Copy link
Member

timholy commented Dec 19, 2020 •
edited
Loading

@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
@timholy timholy added the performance Must go faster label Dec 19, 2020
@JeffBezanson
Copy link
Member

Looks like enable_finalizers (#38487).

@JeffBezanson JeffBezanson added multithreading Base.Threads and related functionality regression Regression in behavior compared to a previous version labels Dec 21, 2020
@vtjnash
Copy link
Member

vtjnash commented Dec 22, 2020

makes sense—that adds a lot of overhead right now, since we don't inline the inc/dec as we probably need to do

@JeffBezanson JeffBezanson added this to the 1.6 blockers milestone Jan 5, 2021
@JeffBezanson JeffBezanson self-assigned this Jan 7, 2021
JeffBezanson added a commit that referenced this issue Jan 8, 2021
@JeffBezanson
improve performance of disabling finalizers in locks
4977d52 
helps #38947
@JeffBezanson JeffBezanson mentioned this issue Jan 8, 2021
Merged
JeffBezanson added a commit that referenced this issue Jan 15, 2021
@JeffBezanson
improve performance of disabling finalizers in locks
58d5b00 
helps #38947
JeffBezanson added a commit that referenced this issue Jan 19, 2021
@JeffBezanson
improve performance of disabling finalizers in locks (#39153)
e8f23d7 
helps #38947
@JeffBezanson JeffBezanson removed this from the 1.6 blockers milestone Jan 19, 2021
KristofferC pushed a commit that referenced this issue Jan 19, 2021
@JeffBezanson @KristofferC
improve performance of disabling finalizers in locks (#39153)
a7a9fe5 
helps #38947

(cherry picked from commit e8f23d7)
vchuravy pushed a commit that referenced this issue Jan 22, 2021
@JeffBezanson @vchuravy
improve performance of disabling finalizers in locks
63b937e 
helps #38947

(cherry picked from commit 58d5b00)
vchuravy pushed a commit that referenced this issue Jan 25, 2021
@JeffBezanson @vchuravy
improve performance of disabling finalizers in locks
1c3326f 
helps #38947

(cherry picked from commit 58d5b00)
KristofferC pushed a commit that referenced this issue Feb 1, 2021
@JeffBezanson @KristofferC
improve performance of disabling finalizers in locks (#39153)
cbfe333 
helps #38947

(cherry picked from commit e8f23d7)
@vtjnash
Copy link
Member

vtjnash commented Mar 31, 2021

We'll continue working on the performance substantially, but let's call this closed by #39153 for now

@vtjnash vtjnash closed this as completed Mar 31, 2021
@IanButterworth
Copy link
Member

IanButterworth commented Apr 18, 2021 •
edited
Loading

Just sharing some benchmarks:

1.5.3

julia> using BenchmarkTools

julia> l = Base.ReentrantLock()
ReentrantLock(nothing, Base.GenericCondition{Base.Threads.SpinLock}(Base.InvasiveLinkedList{Task}(nothing, nothing), Base.Threads.SpinLock(0)), 0)

julia> @btime lock(l) do
       end
  56.702 ns (0 allocations: 0 bytes)

1.6.0

  72.725 ns (0 allocations: 0 bytes)

Master 3a6b2a1

  137.011 ns (0 allocations: 0 bytes)

@oscardssmith
Copy link
Member

oscardssmith commented Apr 18, 2021 •
edited
Loading

That's not good. Any ideas what has caused the regression?

@IanButterworth IanButterworth mentioned this issue Apr 18, 2021
Merged
ElOceanografo pushed a commit to ElOceanografo/julia that referenced this issue May 4, 2021
@JeffBezanson @ElOceanografo
improve performance of disabling finalizers in locks (JuliaLang#39153)
c2468c4 
helps JuliaLang#38947
antoine-levitt pushed a commit to antoine-levitt/julia that referenced this issue May 9, 2021
@JeffBezanson @antoine-levitt
improve performance of disabling finalizers in locks (JuliaLang#39153)
05f267a 
helps JuliaLang#38947
staticfloat pushed a commit that referenced this issue Dec 23, 2022
@JeffBezanson @staticfloat
improve performance of disabling finalizers in locks (#39153)
0455031 
helps #38947

(cherry picked from commit e8f23d7)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@JeffBezanson JeffBezanson

Labels
multithreading Base.Threads and related functionality performance Must go faster regression Regression in behavior compared to a previous version
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@vtjnash @JeffBezanson @timholy @IanButterworth @oscardssmith