Block report logs incorrect times

[heifner]

debug 2024-09-27T03:35:46.775 nodeos    producer_plugin.cpp:2165      start_block          ] Starting block #396367492 2024-09-27T03:35:47.500 producer atticlabeosb, deadline 2024-09-27T03:35:47.275
...
debug 2024-09-27T03:35:47.112 nodeos    producer_plugin.cpp:310       report               ] Block #396367492 atticlabeosb trx idle: 192987us out of 427393us, success: 74, 143230us, fail: 0, 0us, transient: 0, 0us, other: 91176us

Looks like the total time of 427393 and the other time of 91176 includes the processing of the incoming block:

debug 2024-09-27T03:35:46.685 nodeos    producer_plugin.cpp:310       report               ] Block #396367491 atticlabeosb trx idle: 292841us out of 504843us, success: 43, 152771us, fail: 9, 276us, transient: 0, 0us, other: 58955us

Not sure if this is always incorrect or only when restarting a speculative block:

debug 2024-09-27T03:35:46.684 nodeos    producer_plugin.cpp:987       restart_speculative_ ] Restarting exhausted speculative block #396367491

[greg7mdp]

@heifner do you know of a way to reliably reproduce this issue?

I'm wondering if this issue could be caused by this, where we first call abort_block();, which calls _time_tracker.clear();, and then maybe_switch_forks(), which time may be counted in other?

[heifner]

I don't know of a way to reproduce it. Maybe spam a node with set_code or other heavy transactions (jumborow or eosmechanics cpu maybe) to cause a speculative block to be exhausted.

I think likely did find the issue as the timer should be reset after the maybe_switch_forks.