Add a Hierarchical timer class #96

michaelbynum · 2020-04-03T21:19:26Z

Summary/Motivation:

This Pr adds a class for hierarchical timing.

Legal Acknowledgement

By contributing to this software project, I agree to the following terms and conditions for my contribution:

I agree my contributions are submitted under the BSD license.
I represent I am authorized to make the contributions and grant the license. If my employer has rights to intellectual property that includes these contributions, I represent that I have received permission to make contributions and grant the required license on behalf of that employer.

coveralls · 2020-04-03T21:22:38Z

Coverage increased (+0.8%) to 61.847% when pulling 2feaa83 on michaelbynum:hierarchical_timer into ad6043c on PyUtilib:master.

jsiirola

I am eager for this functionality, but have concerns that it duplicates much of the functionality in the TicTocTimer but in a different way. Would you consider refactoring this to have the _HierarchicalHelper use TicTocTimers? There are some features in the TicTocTimer that provide more robustness (notably, higher precision timers on Windows).

jsiirola · 2020-04-03T23:03:00Z

pyutilib/misc/timing.py

+            parent.timers[identifier] = _HierarchicalHelper()
+            return parent.timers[identifier]
+
+    def start_increment(self, identifier):


The TicTocTimer uses start() and stop(). Can we make the two APIs consistent?

jsiirola · 2020-04-03T23:04:28Z

pyutilib/misc/timing.py

+            s += name_formatter.format(name=name)
+            s += '{0:>15.2e}'.format(timer.total_time)
+            s += '{0:>15d}'.format(timer.n_calls)
+            s += '{0:>15.2e}\n'.format(timer.total_time/timer.n_calls)


Can n_calls ever be 0?

No, n_calls can never be 0. The timer would just not exist in that case.

jsiirola · 2020-04-03T23:05:12Z

pyutilib/misc/timing.py

+        stack = identifier.split('.')
+        timer = self._get_timer_from_stack(stack)
+        parent = self._get_timer_from_stack(stack[:-1])
+        return timer.total_time / parent.total_time * 100


For timing very short times on machines with low precision, total_time can be 0

I fixed this in the printing methods. However, I think a division by 0 error is appropriate here. Other methods are available for users to easily get the numerator and denominator individually. Although, given what I just said, it might make sense to remove the percent methods. Thoughts?

Personally, I think that either get_relative_percent should return 0 when total_time is 0 so that clients that are doing the equivalent of '%d' % (t.get_relative_percent) will not get exceptions. It is numerically incorrect, but doesn't meaningfully change the interpretation of the results.

Another edge case: if you call get_relative_percent from the top of the stack, you should get 100.

Good catch. That should now be fixed.

I disagree - I think returning 0 from get_relative_percent_time when parent.total_time is 0 does change the interpretation of the results. I would rather the user get an exception. However, I am happy to remove this method completely and let users do what they want manually (with calls to get_total_time).

Actually, we could return math.nan, which is accurate and does not raise an exception. Thoughts?

@michaelbynum Great idea! Just make it float('nan') (for compatibility).

codecov-io · 2020-04-04T00:28:36Z

Codecov Report

Merging #96 into master will increase coverage by 0.79%.
The diff coverage is 93.75%.

@@            Coverage Diff             @@
##           master      #96      +/-   ##
==========================================
+ Coverage   63.13%   63.93%   +0.79%     
==========================================
  Files          87       87              
  Lines        8788     8916     +128     
==========================================
+ Hits         5548     5700     +152     
+ Misses       3240     3216      -24

Impacted Files	Coverage Δ
pyutilib/misc/timing.py	`76.76% <93.75%> (+76.76%)`	⬆️

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 ad6043c...913df89. Read the comment docs.

michaelbynum · 2020-04-04T14:33:44Z

@jsiirola Great suggestions. I never realized the TicTocTimer tracked cumulative time and number of calls. I also did not know about time.perf_counter or time.clock, so thanks. Let me know what you think of the new changes.

jsiirola · 2020-04-04T15:35:05Z

pyutilib/misc/timing.py

+            ab                 4.84e-02             10       4.84e-03           42.0%
+            other              8.00e-04            N/A            N/A            0.7%
+        b                  1.39e-02             10       1.39e-03           10.8%
+        other              3.49e-04            N/A            N/A            0.3%


Would you consider changing this format to more closely match the results from the Python profiler? For reference, the profiler generates:

Function called... ncalls tottime cumtime {posix.waitpid} -> sre_compile.py:228(_compile_charset) -> 122 0.026 0.065 sre_compile.py:256(_optimize_charset) 502 0.000 0.000 {method 'append' of 'list' objects} 20 0.000 0.000 {method 'extend' of 'list' objects}

I am thinking about a format similar to:

Identifier ncalls tottime percall % ------------------------------------------------------------------------ all 1 0.129 0.129 100.0 -------------------------------------------------------------------- a 10 0.115 0.115 89.0 ---------------------------------------------------------------- aa 50 0.066 0.001 57.3 ab 10 0.048 0.005 42.0 other n/a 0.001 n/a 0.7 ================================================================ b 10 0.014 0.014 10.8 other n/a 0.000 n/a 0.3 ==================================================================== ========================================================================

...I am happy to draft the patch if you want.

I like this output way more than what I had. I honestly couldn't come up with anything I really liked, so I just gave up.

I can take a stab at it right now.

michaelbynum · 2020-04-05T14:27:09Z

@jsiirola I think this is ready now. Thanks for all the great suggestions. I am very happy with this timer now.

jsiirola · 2020-04-06T07:06:24Z

@michaelbynum: some questions/comments as I go through this:

Why scientific notation for timing? profile uses '%.3f', and I think that is a good precedent: timings under a millisecond are meaningless, and I (at least) get lost tracking exponents
I would like to propose the table be in '%8d %8.3f %8.3f %5.1f': this makes things more compact, yet ensures in the odd chance that timings run over 10000 seconds that there is still a space between numbers.
(This is a nit): why use .format()? It is verbose, harder to parse, and generally 2x slower that classic formatting (using '%'). We can move to f-strings when we finally drop 2.x and 3.5 (f-strings are faster than '%' and more concise, but not available until 3.6)
Is there a reason you did not have _HierarchicalHelper directly inherit from TicTocTimer? If you did then you would only have to add the timers dict and the printing function.
Similarly, I feel like the HierarchicalTimer should itself be a _HierarchicalHelper object, that just overwrites the start / stop methods to take an optional argument. Maybe everything could be implemented in a single class? That way you could get reports from anywhere in the hierarchy.
Related to the above, I feel like the info methods (like get_total_time and get relative_precent_time could be calculated locally within the Helper. This actually motivated the previous comment, as I was working through the complexity of the printer (the logic is basically duplicated in both the HierarchicalTimer and in the _HierarchicalHelper
You should not directly access the _cumul attribute, as it will return the wrong answer if the timer is currently running. Always access it with toc(msg='')

I have some ideas around addressing the above. Would you like me to draft something as a PR to your branch?

michaelbynum · 2020-04-06T14:03:52Z

@jsiirola

I agreed with most of your formatting comments, so I made some updates. I used 12 and 10 rather than 8 and 5 (8 was to short for the titles).
I disagree about format - I think it is clear, not verbose. It is my personal preference. Also, I would argue that the performance of printing a HierarchicalTimer is not terribly important.
You seem to be favoring inheritance over containment. In this situation, I do not really see the benefit of one over the other, but I am not opposed to inheritance if you want to make some changes an create a PR.
The only problem with putting get_relative_percent_time in the helper object is that the helper object does not currently have a pointer to its parent. Again, I am fine with these changes if you want to make a PR.
I fixed the issue with accessing _cumul.

michaelbynum · 2020-04-06T17:28:11Z

@jsiirola Looks good. Thanks for these changes.

carldlaird · 2020-04-06T17:35:02Z

I agree. Thank you both for this - this looks great - and will definitely get used in a few of our projects.

jsiirola

This is fine to merge. Remaining comments have been archived as #97.

michaelbynum added 3 commits April 3, 2020 11:55

working on hierarchical_timer

2ccc23f

working on hierarchical timer

17bbe0a

tests for hierarchical timer

489dc71

michaelbynum requested review from carldlaird and jsiirola April 3, 2020 21:20

chaning method name from print to pprint

6a555fc

jsiirola reviewed Apr 3, 2020

View reviewed changes

michaelbynum added 3 commits April 3, 2020 18:15

using TicTocTimer in _HierarchicalHelper

a28a4ea

consistent timing api

f6e17aa

updating hierarchical timer tests

b4beefb

working on hierarchical timer

16173fe

bug in get_relative_percent_time

3ee1576

jsiirola reviewed Apr 4, 2020

View reviewed changes

michaelbynum added 3 commits April 4, 2020 09:36

fixing division by 0 errors

fa41371

using float(nan) instead of math.nan

166d6db

improving the output from HierarchicalTimer

913df89

working on hierarchical timer

1d7f76c

jsiirola added 2 commits April 6, 2020 10:38

Compressing result table, PEP8 (long line) formatting

5772baf

Updating test string comparison

2feaa83

jsiirola mentioned this pull request Apr 6, 2020

Simplify HierarchicalTimer implementation #97

Open

jsiirola approved these changes Apr 6, 2020

View reviewed changes

jsiirola changed the title ~~Hierarchical timer~~ Add a Hierarchical timer class Apr 6, 2020

jsiirola merged commit d74cd96 into PyUtilib:master Apr 6, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add a Hierarchical timer class #96

Add a Hierarchical timer class #96

michaelbynum commented Apr 3, 2020

coveralls commented Apr 3, 2020 •

edited

Loading

jsiirola left a comment

jsiirola Apr 3, 2020

jsiirola Apr 3, 2020

michaelbynum Apr 4, 2020

jsiirola Apr 3, 2020

michaelbynum Apr 4, 2020

jsiirola Apr 4, 2020

jsiirola Apr 4, 2020

michaelbynum Apr 4, 2020

michaelbynum Apr 4, 2020

michaelbynum Apr 4, 2020

jsiirola Apr 4, 2020

codecov-io commented Apr 4, 2020 •

edited

Loading

michaelbynum commented Apr 4, 2020

jsiirola Apr 4, 2020 •

edited

Loading

michaelbynum Apr 4, 2020

michaelbynum Apr 4, 2020

michaelbynum commented Apr 5, 2020

jsiirola commented Apr 6, 2020

michaelbynum commented Apr 6, 2020

michaelbynum commented Apr 6, 2020

carldlaird commented Apr 6, 2020

jsiirola left a comment

Add a Hierarchical timer class #96

Add a Hierarchical timer class #96

Conversation

michaelbynum commented Apr 3, 2020

Summary/Motivation:

Legal Acknowledgement

coveralls commented Apr 3, 2020 • edited Loading

jsiirola left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov-io commented Apr 4, 2020 • edited Loading

Codecov Report

michaelbynum commented Apr 4, 2020

jsiirola Apr 4, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

michaelbynum commented Apr 5, 2020

jsiirola commented Apr 6, 2020

michaelbynum commented Apr 6, 2020

michaelbynum commented Apr 6, 2020

carldlaird commented Apr 6, 2020

jsiirola left a comment

Choose a reason for hiding this comment

coveralls commented Apr 3, 2020 •

edited

Loading

codecov-io commented Apr 4, 2020 •

edited

Loading

jsiirola Apr 4, 2020 •

edited

Loading