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.

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

Learn to be lazy with time checks. Don't lock if not threading #197

Merged
merged 5 commits into from Apr 25, 2021

Conversation

IanButterworth
Copy link
Collaborator

@IanButterworth IanButterworth commented Apr 18, 2021

Building on #196 for reducing unnecessary expense for tight loops.

  1. Implements lazy-smart time checking. Previously time() was polled for every next!, which is about ~30ns, so can be a bit of a slow down for tight loops.
    This takes the approach of iteratively predicting the number of iterations for the first print period to be reached, then using that to defer time checking for the next loop for that number of iterations. Then each time the print occurs, the timing is corrected for any overshoot or undershoot. In testing with some debug prints it seems to stabilize quite quickly to check time 1-2 times per dt

  2. Given locks can be expensive (~140ns on 1.7 currently), this changes to only locking if multiple threads are detected by the next/update functions.

ProgressMeter v1.5.0

julia> function perf(n; doprog=true)
           prog = Progress(n)
           x = 0.0
           for i in 1:n
               x += rand()
               doprog && next!(prog)
           end
           return x
       end

julia> @time perf(10^7,  doprog=true)
Progress: 100%|█████████████████████████████████████████| Time: 0:00:02
  2.265462 seconds (1.04 k allocations: 62.078 KiB)
5.002344696500369e6

julia> @time perf(10^7,  doprog=false)
  0.037642 seconds (7 allocations: 400 bytes)
4.999619221211615e6

This PR

julia> @time perf(10^7, 0, doprog=true)
Progress: 100%|█████████████████████████████████████████| Time: 0:00:00
prog.check_iterations = 6459310
  0.150941 seconds (113 allocations: 10.078 KiB)
4.99952291278307e6

julia> @time perf(10^7, 0, doprog=false)
prog.check_iterations = 1
  0.041455 seconds (22 allocations: 976 bytes)
5.000273824098582e6

@codecov
Copy link

codecov bot commented Apr 18, 2021

Codecov Report

Merging #197 (3b62f41) into master (abcfc04) will increase coverage by 0.54%.
The diff coverage is 99.17%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master     #197      +/-   ##
==========================================
+ Coverage   95.76%   96.31%   +0.54%     
==========================================
  Files           1        1              
  Lines         425      488      +63     
==========================================
+ Hits          407      470      +63     
  Misses         18       18              
Impacted Files Coverage Δ
src/ProgressMeter.jl 96.31% <99.17%> (+0.54%) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update c27e0a1...3b62f41. Read the comment docs.

Comment on lines -38 to +50
@test @elapsed(prog_perf(10^7)) < 40*@elapsed(noprog_perf(10^7))
@test @elapsed(prog_perf(10^7)) < 8*@elapsed(noprog_perf(10^7))
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Based on local tests this could go down to 5, but CI seems closer to 6/7. 8 to be conservative

Copy link
Sponsor Contributor

@johnnychen94 johnnychen94 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't know all the internal details but this change looks good to me. A nice observation!

src/ProgressMeter.jl Show resolved Hide resolved
src/ProgressMeter.jl Outdated Show resolved Hide resolved
@IanButterworth IanButterworth merged commit 45e562e into timholy:master Apr 25, 2021
@IanButterworth
Copy link
Collaborator Author

I've tested this in the ways I can think might challenge it, including

  • Loops that start fast and slow down
  • The distributed example that has heterogenous yields

.. and I haven't seen any bad behavior.

Given a few updates on master with new features and no breaking changes to the public API, in a couple of days I'll release 1.6.0 unless anyone disagrees

cc. @timholy @johnnychen94

@IanButterworth IanButterworth deleted the ib/lazier_time_check branch April 25, 2021 14:48
@vancleve
Copy link

vancleve commented May 7, 2021

Hi @IanButterworth.

My sims unfortunately hits on the other end of the spectrum where the step counter counts replicate sim runs each of which has an indeterminate number of time steps and runs a long time.

I was calling next! with step=0 to update the progress meter with time steps from the replicates using showvalues but now nothing is printed initially because I don't update p.counter until a full replicate is done.

Should I try multiple progress meters now? Or maybe there would be a flag to restore the old behavior?

@IanButterworth
Copy link
Collaborator Author

Ok! Yes, let's add a flag to restore the old behavior. Would you happen to have a MWE that I can test and add to the test suite?

@IanButterworth
Copy link
Collaborator Author

IanButterworth commented May 8, 2021

@vancleve is this a valid MWE? It demonstrates the issue I think you have

using ProgressMeter
n = 100
p = Progress(n)
for i in 1:n
    for j in 1:10
        next!(p, step=0, showvalues = [(:j, j)])
        sleep(1)
    end
    next!(p)
end

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants