[SERVER-54906] log WiredTiger record store oplog processing times persistent between versions Created: 03/Mar/21  Updated: 27/Oct/23  Resolved: 16/Mar/21

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: None
Fix Version/s: None

Type: Improvement Priority: Minor - P4
Reporter: Dmitry Agranat Assignee: Backlog - Storage Execution Team
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
Assigned Teams:
Storage Execution
Participants:

 Description   

In MongoDB versions prior to 4.4, we were printing:

WiredTiger record store oplog processing took

In MongoDB versions post 4.4, we print:

WiredTiger record store oplog processing finished

It would be helpful to keep such startup messages consistent and identical between versions, otherwise searching for the exact string does not provide the output for all MongoDB versions.

I also think "finished" is a less acceptable word in terms of time tracking unless we also print "started"



 Comments   
Comment by Louis Williams [ 03/Mar/21 ]

This is a consequence of the log format changes in 4.4. You can see the current log line accepts two strings: one with parameter substitution and one without.

        LOGV2(22382,
              "WiredTiger record store oplog processing took {duration}ms",
              "WiredTiger record store oplog processing finished",
              "duration"_attr = Milliseconds(static_cast<int64_t>(waitTime / 1000)));

The logger defaults to using messages without substitution because they are easier to read. That is why you don't see the version with substitutions in the logs.

For log lines without substitution, it does not make sense to end a sentence with a verb, "took", because the variables are logged as a JSON object. This is a pattern with all new log messages.

This should not happen in the future. In 4.4 and above you should be able to string search for 22382, the unique log message ID, even if the text changes.

Generated at Thu Feb 08 05:34:50 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.