Add TimingContext to measure execution time#1421
Conversation
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #1421 +/- ##
==========================================
+ Coverage 86.80% 86.82% +0.01%
==========================================
Files 59 60 +1
Lines 8384 8395 +11
Branches 8384 8395 +11
==========================================
+ Hits 7278 7289 +11
Misses 790 790
Partials 316 316 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
tsmbland
left a comment
tsmbland
left a comment
There was a problem hiding this comment.
Looks nice. Very minimal and non-invasive so I'm ok with this. Some people may have reservations about adding another dependency? It looks very minimal so possibly something we could write a tailored version of ourselves.
For now I think the two functions you've chosen are the most important to monitor. Long run we may also want look at investments running time each individual commodity.
Maybe should be debug level, since the log messages are referring to function names that normal users shouldn't have to concern themselves with? (Or make the messages more user facing)
I think this is fine for eyeballing, but would be quite fiddly to do any kind of analytics on this. Is there any way to get extra context into the timer messages (e.g. year)? I guess you can look at previous messages to figure out what it's referring to, but that's a bit fiddly.
Interested in @alexdewar's opinion so I'm going to hold off approving until he can have a look
dc2917
left a comment
dc2917
left a comment
There was a problem hiding this comment.
This is neat, and all looks good as far as I'm concerned.
As Tom says, I think it might be useful to have more descriptive messages about what exactly ran in a given amount of time, rather than the function names.
Also not sure whether microsecond precision is necessary, but is harmless anyway.
|
There are a couple of different options here, depending on how much customisation we want in the logged information, how many different functions are timed and how intrusive we are willing to be. Option 1If we want to be not intrusive - as it is now -, we do not have many functions, and we want full customisation of the information logged, we could just create a custom context per function to time. Eg. Option 2If we want to keep things generic, there's an option I was exploring - with my buddy Claude 😆 - that uses a small macro to customise the message and that is used at the calling point. Something like: #[context_manager::wrap(TimingContext)]
fn query_database(id: u32) -> String {
// Do something here
}
// and then at the calling point...
let record = timed!("Querying database", query_database(42));Resulting in Option 3Any other option I feel would require coding our own |
3 participants
Description
Uses a context manager, in a pythonic style, to decorate functions whose execution time we want to measure. The result is provided as an
infolevel log entry. For now, onlyrun_dispatch_for_yearandperform_agent_investmentare decorated, but other functions could be included in the future.Having said that, if the decorated functions are nested, the output might be confusing, so if that were a use case, we might need to re-think what we output in the logs for it to be useful.
The output of the
simplemodel now looks like (note the[Timer]entries):Fixes #527
Type of change
Key checklist
$ cargo test$ cargo docpresent in the previous release
Further checks