[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: |
|
||||||||
| Issue Links: |
|
||||||||
| 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: |
| 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 |
| 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. |