Monitoring thread to prevent tqdm taking too much time for display #251

lrq3000 · 2016-08-28T10:41:50Z

Added a monitoring thread that will check all tqdm instances regularly and reduce miniters if necessary. This should fix issues like #249 and #54 for good.

About performance impact:

This solution adds a bit of additional overhead at the first tqdm instanciation because it creates a thread, but the bright side is that then the thread sleeps most of the time, and wakes up only to check every instances' miniters value and last printing time. By default, it wakes up every 10 seconds. So the monitoring thread
But the bad side is that this solution needs to access and modify self.miniters. No problem here, the problem is with tqdm.__iter__() since it doesn't do any access to self variables inside loops. So I had to modify the loop to access self.miniters. My reasoning is that accessing self.miniters will use less CPU than calling time.time(), but I didn't try it out. If someone wants to profile to see the impact of self.miniters, that would be great!

/EDIT: profiled, here are the results:

Normal tqdm (pre-PR):

for i in tqdm.trange(int(1e8)):
    pass
100%|#######################| 100000000/100000000 [00:20<00:00, 5000000.00it/s]
(20.002348575184286, 'seconds')

Normal tqdm no miniters:

for i in tqdm.trange(int(1e8), miniters=1, mininterval=0.1):
    pass
100%|#######################| 100000000/100000000 [00:40<00:00, 2499937.51it/s]
(40.00375434790657, 'seconds')

Monitoring thread PR:

for i in tqdm.trange(int(1e8)):
    pass
100%|#######################| 100000000/100000000 [00:22<00:00, 4423995.78it/s]
(22.605596624972463, 'seconds')

Note that for all other tests in examples/simple_examples.py, they all show similar performances between standard tqdm and monitoring thread PR (of course the no miniters is slower).

So there is a small performance hit, which is still way better than removing miniters completely: removing miniters doubles the computation time, whereas the monitoring thread has an overhead of 10% (2s here). The perf hit doesn't even come from the monitoring thread itself, but rather from using self.miniters instead of miniters in tqdm.__iter__(). This seems to slow down by a linear constant, so it's indeed noticeable but it can be ok (or if we can find a way around it would be better but I can't think how). Makes tqdm go from 20s to 22s for the task above.

Note that there is no performance impact on manual tqdm. The perf hit is only on iterable tqdm.

TODO:

Profile if self.miniters in tqdm.__iter__() isn't too much of a burden.
Fix thread hanging up terminal if KeyboardInterrupt.
Force display refresh on miniters update from monitoring thread (else user will have to wait until next iteration to see the update).
Fix slowdown at closing (because of TMonitor.join()).
Add unit test for monitoring thread and the special case in tqdm hangs up with highly irregular iterations speed #249 (would need to modify TMonitor to support virtual discrete timer, just store in self._time and self._sleep like we do in tqdm).
Add a note to Readme.
Fix unit test to synchronize with thread and wait for it to wake up instead of sleeping (which makes Travis fail sometimes).
Fix thread hanging up and making Travis test fail randomly.

codecov-io · 2016-08-28T10:50:05Z

Current coverage is 91.77% (diff: 100%)

Merging #251 into master will increase coverage by 1.26%

@@             master       #251   diff @@
==========================================
  Files             7          7          
  Lines           485        523    +38   
  Methods           0          0          
  Messages          0          0          
  Branches         89         92     +3   
==========================================
+ Hits            439        480    +41   
+ Misses           44         43     -1   
+ Partials          2          0     -2

Powered by Codecov. Last update 38af576...7470638

coveralls · 2016-08-28T11:00:08Z

Coverage increased (+0.1%) to 90.909% when pulling b5de8ef on monitoring-thread into 4b3d916 on master.

coveralls · 2016-08-28T14:12:57Z

Coverage decreased (-0.4%) to 90.401% when pulling db88191 on monitoring-thread into 4b3d916 on master.

coveralls · 2016-08-28T14:53:21Z

Coverage increased (+0.009%) to 90.784% when pulling db88191 on monitoring-thread into 4b3d916 on master.

coveralls · 2016-08-28T17:21:25Z

Coverage decreased (-0.6%) to 90.177% when pulling 3febc50 on monitoring-thread into 4b3d916 on master.

coveralls · 2016-08-28T18:20:06Z

Coverage decreased (-0.4%) to 90.373% when pulling a49143c on monitoring-thread into 4b3d916 on master.

coveralls · 2016-08-28T20:16:02Z

Coverage increased (+0.9%) to 91.715% when pulling 51b09be on monitoring-thread into 4b3d916 on master.

lrq3000 · 2016-08-28T21:19:27Z

All done, good to go for me. Please review me :)

coveralls · 2016-08-28T21:25:20Z

Coverage increased (+1.0%) to 91.747% when pulling 0eed820 on monitoring-thread into 4b3d916 on master.

CrazyPython · 2016-08-28T21:27:53Z

tqdm/_tqdm.py

@@ -15,7 +15,9 @@
 from ._utils import _supports_unicode, _environ_cols_wrapper, _range, _unich, \
    _term_move_up, _unicode, WeakSet
 import sys
-from time import time
+from threading import Thread
+from threading import Event


@lrq3000 merge into from threading import Thread, event?

CrazyPython · 2016-08-28T21:35:40Z

@lrq3000 ding! reviewing done.

coveralls · 2016-08-28T22:11:06Z

Coverage increased (+1.0%) to 91.747% when pulling 0b77677 on monitoring-thread into 4b3d916 on master.

lrq3000 · 2016-08-28T22:24:01Z

Thank's @CrazyPython, I fixed what you reviewed :)

However I would like a more code oriented review about whether we should include this or not. I think it's a good idea obviously because I'm biased (else I wouldn't have spend the time to implement it), but if you guys can think of some edge case to try this feature out (and see whether it can fail or have shortcomings) it would help a lot!

Or we can merge and see later :) At least it's 100% unit tested, so it doesn't break anything and it's working like expected on the cases it's supposed to fix.

coveralls · 2016-08-28T22:29:35Z

Coverage increased (+1.0%) to 91.731% when pulling b3a2f0d on monitoring-thread into 4b3d916 on master.

CrazyPython · 2016-08-28T23:17:38Z

@lrq3000 I'll see what I can do... also Travis CI...

lrq3000 · 2016-08-29T08:47:50Z

@CrazyPython What about TravisCI?
/EDIT: ah it failed, I don't know why, I restarted the failing tests and it works now without any change. I'm going to try to enhance the unit test, it's because there's a real sleep somewhere to wait for the thread to wake up. I wonder if there's a way around.

CrazyPython · 2016-08-29T19:58:50Z

tqdm/_tqdm.py

@@ -716,12 +797,13 @@ def __iter__(self):
                # Note: does not call self.update(1) for speed optimisation.
                n += 1
                # check the counter first (avoid calls to time())
-                if n - last_print_n >= miniters:
+                if n - last_print_n >= self.miniters:
+                    miniters = self.miniters  # watch monitoring thread changes


Can we directly modify self.miniters or am I missing something? I'm probably missing something.

This is an optimization, we store instance variables as local function variables, this speeds up the calculations a great deal because there's no dot reference lookup. But here we need to access self.miniters since it can be modified by the monitoring thread.

lrq3000 · 2016-09-04T11:44:48Z

@CrazyPython Thank's for editing your comment: lemurheavy/coveralls-public#838 (comment) 👍

casperdcl · 2016-09-04T19:37:48Z

Nice. Surprised you got a response. I filtered all github emails a few days ago since almost all of them were essentially spam. Pity.

CrazyPython · 2016-09-04T20:00:38Z

@casperdcl ignore those and just use the gh notif system

lrq3000 · 2016-09-04T20:14:11Z

@casperdcl Actually we could drop coveralls as we are using codecov's branch coverage (whereas coveralls is only statement coverage as far as I know).

casperdcl

👍

lrq3000 · 2016-10-29T22:36:33Z

Merged in commit f78ecc6.

lrq3000 · 2016-10-29T22:43:20Z

Self-reminder: next time use (close #id) instead of just (#id) in the commit message, this will automatically define the PR as closed:

http://stackoverflow.com/questions/23015168/how-to-close-a-github-pull-request-with-a-commit-comment

Also gitreflow and git-when-merged might become handy in the future.

casperdcl · 2016-10-30T16:55:36Z

@lrq3000 did you mean to close this? I intended you to merge #250 into #251, not the other way around. Currently, comparing https://github.com/tqdm/tqdm/pull/250/commits to https://github.com/tqdm/tqdm/pull/251/commits it looks like you're missing things.

lrq3000 · 2016-10-30T21:04:44Z

Sorry but too many messages, I processed them one by one yesterday so I didn't see the order before after I was finished with merging this one.

Anyway they are two different PRs, why should they be merged?

lrq3000 · 2016-10-30T21:08:48Z

It's normal that the commits history is different, I rebased #250 over #251.

I mean, the PR names exactly mean what it's written: #251 was a new feature (the monitoring thread), while #250 was two bugfixes. This is why I didn't merge them, I figured it's easier to review and accept bugfixes rather than new features, so I separated every PRs into two types: bugfixes or new features. And it's better to merge them separately in case there are bugs in the future (they will probably be imputable to the new feature #251 rather than the bugfix #250).

casperdcl · 2016-10-31T00:25:31Z

arg ok did you squash merge this branch into master?

lrq3000 · 2016-10-31T01:29:56Z

Yes, I thought the review was a signal that I could merge. Also, I did add a few corrections when I merged into master. I will check what is missing since I have a local copy.

lrq3000 · 2016-10-31T01:30:57Z

But that's weird, why didn't you want to squash merge? It made more sense to me to squash because it was easier to track down then...

lrq3000 · 2016-10-31T01:35:45Z

Ok nevermind, there's just the interations typo left in the readme, you merged all the changes, so we'll fix that later :) thank's @casperdcl . But can you tell me what you think about squash merge? We need to be consistent about our merge procedure. I thought that 1 new feature PR = 1 commit. For bugfix PR we might merge or squash merge depending on the case.

casperdcl · 2016-10-31T01:58:19Z

I haven't tagged and formally released master yet so we can squash any minor corrections still. I think minor PR = 1 commit rebase/squash merge. major PR (eg this) = rebase and squash debug commits, then master merge --no-ff.

lrq3000 · 2016-10-31T03:22:06Z

Ok I'll do that in the future, thank's for explaining.

2016-10-31 2:58 GMT+01:00 Casper da Costa-Luis notifications@github.com:

I haven't tagged and formally released master yet so we can squash any
minor corrections still. I think minor PR = 1 commit rebase/squash merge.
major PR (eg this) = rebase and squash debug commits, then master merge
--no-ff.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#251 (comment), or mute
the thread
https://github.com/notifications/unsubscribe-auth/ABES3l8hCH7JiQQpIV0pUGK9EwRf6x3Vks5q5Us8gaJpZM4Ju5Tm
.

lrq3000 mentioned this pull request Aug 28, 2016

tqdm hangs up with highly irregular iterations speed #249

Closed

lrq3000 added the to-review 🔍 Awaiting final confirmation label Aug 28, 2016

CrazyPython reviewed Aug 28, 2016
View reviewed changes

CrazyPython reviewed Aug 29, 2016
View reviewed changes

lrq3000 added the p3-enhancement 🔥 Much new such feature label Sep 2, 2016

This was referenced Sep 5, 2016

Barebones tqdm in submodule #255

Closed

Pythonic submodules architecture #198

Closed

casperdcl approved these changes Oct 29, 2016

View reviewed changes

casperdcl mentioned this pull request Oct 29, 2016

Fix maxinterval to adjust miniters to mininterval + fix dynamic_miniters when smoothing #250

Merged

4 tasks

lrq3000 added a commit that referenced this pull request Oct 29, 2016

Monitoring thread to prevent tqdm taking too much time for display #251

f78ecc6

lrq3000 closed this Oct 29, 2016

lrq3000 deleted the monitoring-thread branch October 29, 2016 22:44

casperdcl restored the monitoring-thread branch October 30, 2016 16:54

casperdcl reopened this Oct 30, 2016

casperdcl force-pushed the monitoring-thread branch 2 times, most recently from c052097 to 1cd7cce Compare October 31, 2016 00:49

casperdcl merged commit 1cd7cce into master Oct 31, 2016

casperdcl force-pushed the master branch from f78ecc6 to aeea13a Compare October 31, 2016 00:54

casperdcl deleted the monitoring-thread branch October 31, 2016 14:52

Uh oh!

Monitoring thread to prevent tqdm taking too much time for display #251

Monitoring thread to prevent tqdm taking too much time for display #251

Uh oh!

Conversation

lrq3000 commented Aug 28, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

codecov-io commented Aug 28, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Current coverage is 91.77% (diff: 100%)

Uh oh!

coveralls commented Aug 28, 2016

Uh oh!

coveralls commented Aug 28, 2016

Uh oh!

coveralls commented Aug 28, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

coveralls commented Aug 28, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

coveralls commented Aug 28, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

coveralls commented Aug 28, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

lrq3000 commented Aug 28, 2016

Uh oh!

coveralls commented Aug 28, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

CrazyPython Aug 28, 2016

Choose a reason for hiding this comment

Uh oh!

CrazyPython commented Aug 28, 2016

Uh oh!

coveralls commented Aug 28, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

lrq3000 commented Aug 28, 2016

Uh oh!

coveralls commented Aug 28, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

CrazyPython commented Aug 28, 2016

Uh oh!

lrq3000 commented Aug 29, 2016

Uh oh!

CrazyPython Aug 29, 2016

Choose a reason for hiding this comment

Uh oh!

lrq3000 Sep 2, 2016

Choose a reason for hiding this comment

Uh oh!

lrq3000 commented Sep 4, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

casperdcl commented Sep 4, 2016

Uh oh!

CrazyPython commented Sep 4, 2016

Uh oh!

lrq3000 commented Sep 4, 2016

Uh oh!

casperdcl left a comment

Choose a reason for hiding this comment

Uh oh!

lrq3000 commented Oct 29, 2016

Uh oh!

lrq3000 commented Oct 29, 2016

Uh oh!

casperdcl commented Oct 30, 2016

Uh oh!

lrq3000 commented Oct 30, 2016

Uh oh!

lrq3000 commented Oct 30, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

casperdcl commented Oct 31, 2016

lrq3000 commented Aug 28, 2016 •

edited

Loading

codecov-io commented Aug 28, 2016 •

edited

Loading

coveralls commented Aug 28, 2016 •

edited

Loading

coveralls commented Aug 28, 2016 •

edited

Loading

coveralls commented Aug 28, 2016 •

edited

Loading

coveralls commented Aug 28, 2016 •

edited

Loading

coveralls commented Aug 28, 2016 •

edited

Loading

coveralls commented Aug 28, 2016 •

edited

Loading

coveralls commented Aug 28, 2016 •

edited

Loading

lrq3000 commented Sep 4, 2016 •

edited

Loading

lrq3000 commented Oct 30, 2016 •

edited

Loading