There is currently a small bug which describes prints the log as seconds when it should milliseconds.
here at L157 in rts_api.c,
__wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session), "finished rollback to stable on uri %s and has ran for %" PRIu64 " seconds", uri, time_diff);
L218 in rts_api.c,
__wt_verbose_multi(session, WT_VERB_RECOVERY_RTS(session), "finished rollback to stable on uri %s and has ran for %" PRIu64 " seconds", uri, time_diff);
L89 in rts.c,
__wt_verbose(session, WT_VERB_RECOVERY_PROGRESS, "Rollback to stable has been performing on %s for %" PRIu64 " seconds. For more detailed logging, enable WT_VERB_RTS ",
and L94 in rts.c
__wt_verbose(session, WT_VERB_RECOVERY_PROGRESS, "Rollback to stable has been performing on %s for %" PRIu64 " seconds. For more detailed logging, enable WT_VERB_RTS ",
The bug is more than just logging. Since timer_diff is actually milliseconds instead of seconds, any calculation with timer_diff is off by 1000 times due to incorrect units.
L87 in rts.c,
if ((time_diff / WT_PROGRESS_MSG_PERIOD) > *rollback_msg_count) {
and L99 in rts.c,
*rollback_msg_count = time_diff / WT_PROGRESS_MSG_PERIOD;
To make the code clearer, time_diff is renamed to time_diff_ms, and a units comment is added to the definition of WT_PROGRESS_MSG_PERIOD.
Once the bug is fixed we only need to backport into mongodb-7.1
- is caused by
-
WT-11491 Log the WiredTiger time spent during startup and shutdown
- Closed