feat: log duration of adding new block #130
Conversation
closes Neptune-Crypto#128 Adds a macro `log_duration` that logs execution time of a standard function and also `log_duration_async` for async functions. The latter macro is then used to log the duration of `GlobalState::store_block_internal()`
There was a problem hiding this comment.
Looks good. Can we make the log on the info level instead of the debug level? Getting a new block only happens about every 10 minutes, so I think it won't make the info log output too big.
Excited to see what the results are and how they scale on our next testnet. I'd probably just have used a simpler machinery of adding a few log output and perhaps manually handled a timer, but this works too.
In my opinion you're measuring the right thing. It's worth noting that the relevant measure, which is also what this PR measures, is how long it takes to apply one new block (and not a batch of block). Batch downloading happens rarely.
Is this new functionaly something that can be tested?
Is the 0.1 second reported for an empty wallet btw.?
Sure info level seems fine for this case, but probably not every case we want to track as we start to care more about perf/optimization. So I will either add a log-level param to the macro or maybe just make different macro versions. I've also considered adding a description param. Anyway, I'll try and come up with something that's flexible while remaining simple to use.
I already had a fn for doing the timing, so this just adds macros that make it simpler to time + log. I'm envisioning we will end up doing this in a bunch of places, so I'd like to keep it simple at the usage sites. Also using a macro enables printing the file:line info and the exact expression, which a regular fn call wouldn't do (or at least I don't know how).
good, thx.
not something I would think to test really. There are basically two bits of functionality: timing a fn call and logging the results. How would I test timing a call, since I don't know the answer until I get the result, and it will vary from execution to execution and machine to machine? I guess one could test it is inside a certain sanity window, but... worth the effort? Likewise logging seems a bit hard/pointless to test. diminishing returns, etc.
yes. |
Both options seem good to me.
Makes sense. Don't bother then. |
Changes: * Moves the duration macros into new module crate::macros * adds macros duration_info!, duration_debug!, duration_async_info!, and duration_async_debug! * duration! and duration_async! now use log-level TRACE by default. * adds an optional message string to each macro. * adds tests to ensure that each usage variant will compile. In total, the caller can now: * log duration to trace, debug, info log-levels * include an optional descriptive message.
|
Ok, it is logging at Info level now. I also added a couple tests just to ensure that the macros compile cleanly when used, including each param variant, because it is very easy to have a macro that compiles if unused, but breaks once it is used. Details: I added more macros to logging durations more flexible. So now we have duration!(), duration_info!(), and duration_debug!(), each of which accept an optional message. There is also an async variant of each. To keep things organized, I moved these into a new crate::macros module. (I don't intend to get carried away with writing macros, but they were useful for this purpose, and fit well with other logging macros.) |
closes #128
Adds a macro
log_durationthat logs execution time of a standard function and alsolog_duration_asyncfor async functions.The latter macro is then used to log the duration of
GlobalState::store_block_internal()The macros will make it easy to add timings for anything we care about, just by wrapping any existing fn with the appropriate macro.
The log-level is Debug, which is presently hard-coded into the macros. Rationale: I don't think users need to see this info in normal operation and also I wanted the macros to be dead-simple to use for wrapping existing functions (so I didn't make a log-level param).
Example log output
@Sword-Smith is this what you had in mind? I chose to log execution time of the entire GlobalState::store_block_internal() method rather than the two archival_state specific calls. Pls let me know if you want a different behavior.