feat: log duration of adding new block

[dan-da]

closes #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()

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

2024-04-06T05:54:59.783708912Z DEBUG ThreadId(01) neptune_core::models::state: at src/models/state/mod.rs:1189
-- executed async expression --
store_block_internal_worker(self, new_block, coinbase_utxo_info)
 -- duration: 0.117111901 secs --

---

@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.

[dan-da]

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.

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.

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.

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).

In my opinion you're measuring the right thing.

good, thx.

Is this new functionaly something that can be tested?

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.

Is the 0.1 second reported for an empty wallet btw.?

yes.

[Sword-Smith]

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.

Both options seem good to me.

not something I would think to test really

Makes sense. Don't bother then.

[dan-da]

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.)