Details
-
Bug
-
Resolution: Fixed
-
Critical
-
7.1.0
-
Untriaged
-
1
-
Unknown
-
Magma May 2022
Description
When looking at some recent Magma issues (e.g. MB-46661), the amount of log messages output by Magma / MagmaKVStore is large - such that the duration the logs covers is significantly curtailed.
For example (but others probably exist):
- 80 messages about the purger running in a 1 second window (and this repeats many times) - excmple:
2021-06-01T10:51:50.059506-07:00 INFO [(default) magma_35]Started running purger for kvstore:683
2021-06-01T10:51:50.059574-07:00 INFO [(default) magma_34]Started running purger for kvstore:466
2021-06-01T10:51:50.059626-07:00 INFO [(default) magma_34]Completed running purger for kvstore:466
2021-06-01T10:51:50.059775-07:00 INFO [(default) magma_35]Completed running purger for kvstore:683
- very verbose warmup / startup - for example:
2021-06-01T06:16:08.331861-07:00 INFO [(default) magma_19]Created kvstore 955 rev 1 init offset 1:0
2021-06-01T06:16:08.334543-07:00 INFO [(default) magma_19/kvstore-955/rev-000000001]KVStore::Open kvstore-955/rev-000000001 highSeqno:0 replayOffset:1:0
2021-06-01T06:16:08.334576-07:00 INFO [(default) magma_19]KVStore kvstore-955/rev-000000001 created
- others...
The general intent is that INFO should only be used for significant, rare events (initial startup, new DCP connection, new vBucket created, vBucket changes state) - and should be as terse as possible for the more common of those events (i.e. vBucket events typically happen 1024x as often as Bucket events; so it's fine to say print 20 log messages total when a Bucket is created, but not ok to print 20 per vBucket.
I appreciate that during initial bringup it has been useful and desirable to record as much information as possible to debug any issues, but as we prepare for productisation we need to ensure that we have sufficient history in log files coming back from customers - we should be aiming for at least 7 days of logs in a cbcollect when the system is in steady-state.
As a concrete suggestion - for the 3 log messages printed when a vbucket is created, could they be compressed into a single line, or perhaps removed entirely in the successful case?
2021-06-01T06:16:08.331861-07:00 INFO [(default) magma_19]Created kvstore 955 rev 1 init offset 1:0
|
2021-06-01T06:16:08.334543-07:00 INFO [(default) magma_19/kvstore-955/rev-000000001]KVStore::Open kvstore-955/rev-000000001 highSeqno:0 replayOffset:1:0
|
2021-06-01T06:16:08.334576-07:00 INFO [(default) magma_19]KVStore kvstore-955/rev-000000001 created
|
Please let me know if you need any more info / guidance on what's acceptable etc.