[SERVER-71080] Revise WiredTiger verbose messaging config Created: 04/Nov/22  Updated: 03/Nov/23  Resolved: 03/Nov/23

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: 7.2.0-rc0

Type: Task Priority: Minor - P4
Reporter: Will Korteland Assignee: Damian Wasilewicz
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File Screenshot 2023-09-14 at 10.40.50 AM.png     PNG File Screenshot 2023-09-15 at 11.24.28 AM.png    
Issue Links:
Depends
depends on WT-11673 Increase the verbosity level of Journ... Closed
Assigned Teams:
Storage Execution NAMER
Backwards Compatibility: Fully Compatible
Sprint: Execution Team 2023-11-13
Participants:

 Description   

A recent project (PM-2898) has added support for DEBUG_1 through DEBUG_5 verbosity levels to WiredTiger, and moved a large number of messages to DEBUG_2 and DEBUG_3. The code that maps Server log levels to WiredTiger log levels currently skips DEBUG_1 since it would previously result in too much output, but that may no longer be true.

We should experiment with re-allowing DEBUG_1, and if there's still too much output, look at which WiredTiger messages can be moved up a level or two.



 Comments   
Comment by Githook User [ 03/Nov/23 ]

Author:

{'name': 'Damian Wasilewicz', 'email': 'damian.wasilewicz@mongodb.com', 'username': 'DamianWasilewicz'}

Message: SERVER-71080 Revise WiredTiger verbose messaging config
Branch: master
https://github.com/mongodb/mongo/commit/65e7b63cc6dbc6d73fb3a4634e882277495a925f

Comment by Damian Wasilewicz [ 02/Nov/23 ]

With the change in logging, based on running a few tests (the replica_sets_jscore_passthrough suite and keeping a mongod instance running idly locally) logging seems to be reasonable now

Comment by Will Korteland [ 22/Sep/23 ]

damian.wasilewicz@mongodb.com no worries. Just a heads up, the WT ticket blocking this is merged, but it'll take a few days to get vendored into MongoDB so you can play with it in master.

(If you're really keen, you could include that WT change in your local checkout and test it like that.)

Comment by Damian Wasilewicz [ 18/Sep/23 ]

Hey will.korteland@mongodb.com, thanks for the detailed response! I'm admittedly not super familiar with WiredTiger logging yet but I feel like I'm learning a lot just from digging into this ticket/from your responses - I think keeping the logging for when we do something on a tree, and not when we skip it, sounds like a good idea.

Comment by Will Korteland [ 17/Sep/23 ]

Thanks for the info damian.wasilewicz@mongodb.com. It seems reasonable to me to have some per-database output on startup with DEBUG_1, even if (as you point out) there could be a lot of collections. These messages come from rollback to stable, so they could also happen at runtime as well after an election. It's also possible for this to run on a clean shutdown, but I think the most likely scenario there is for RTS to find all content is stable and not do any work.

What do you think about logging only when we choose to do something on a tree (collection), rather than when we skip? (Just FYI - the three messages above are all possible even when RTS does no work for a tree.)

Comment by Damian Wasilewicz [ 15/Sep/23 ]

Yeah of course! After a bit more digging around it looks like the WTRECOV messages below might also be problematic - it looks like they get printed for every collection in the existing db, or at least increase as the number of existing collections increases. They are only printed on initial start up, but with databases with large amounts of collections this could result in a lot of messages being printed.

 

Comment by Will Korteland [ 14/Sep/23 ]

Thanks for the feedback damian.wasilewicz@mongodb.com. Was this the only problematic message? If I'm going to open a WT ticket and fix this, it'd be nice to knock them all over at once.

Comment by Damian Wasilewicz [ 14/Sep/23 ]

After some investigation it appears that including DEBUG_1 still produces too much output. From starting up a basic mongod instance with verbose mode on, it appeared that in particular this Journal Flushing message:

continues to be printed about 10 times per second while the instance is running. It could be worth moving this particular message up in terms of its verbosity level if we do want to stop skipping DEBUG_1.

Generated at Thu Feb 08 06:17:59 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.