[SERVER-30841] Lower the amount of metadata refresh logging Created: 25/Aug/17  Updated: 08/Jan/24  Resolved: 25/Jul/18

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: 3.4.0, 3.5.1, 3.6.3
Fix Version/s: 3.6.8, 4.0.3, 4.1.1

Type: Improvement Priority: Major - P3
Reporter: Dianna Hohensee (Inactive) Assignee: Cheahuychou Mao
Resolution: Fixed Votes: 6
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Depends
Duplicate
is duplicated by SERVER-36180 Sharding: Config server log spamming ... Closed
is duplicated by SERVER-36972 SHARDING CatalogCacheLoader + Balance... Closed
Related
is related to SERVER-43021 MongoS server crashes when attempt to... Closed
is related to SERVER-8245 logging cleanup: review severity of s... Closed
Backwards Compatibility: Fully Compatible
Backport Requested:
v4.0, v3.6
Sprint: Sharding 2018-04-23, Sharding 2018-05-07, Sharding 2018-07-30
Participants:

 Description   

Example of chatty logging:

2017-08-22T12:02:14.386+1000 I SHARDING [Balancer] Refreshing chunks for collection mytest.test1 based on version 0|0||000000000000000000000000
2017-08-22T12:02:14.387+1000 I SHARDING [CatalogCacheLoader-0] Refresh for collection mytest.test1 took 0 ms and found version 1|0||599b909d11c6b22dd4ad5548

These logs don't convey knowledge to our users and are not actionable. On the config server, they can spam to a user with many sharded collection in our auto-balancing code every 10 seconds because we force refresh for every chunk the balancer attempts to move.

The logs come from the CatalogCache and the CatalogCacheLoader.

The logs were useful while we were trying to stabilize the new/modified refresh logic, but less so now, and our testing can retain the same information with log-level 1 set.



 Comments   
Comment by Githook User [ 07/Sep/18 ]

Author:

{'name': 'Cheahuychou Mao', 'email': 'cheahuychou.mao@mongodb.com', 'username': 'cheahuychou'}

Message: SERVER-30841 Lower the amount of metadata refresh logging

(cherry picked from commit 8b066e35dd7c5a29e17f2d4b1cab69e984fadebc)
Branch: v3.6
https://github.com/mongodb/mongo/commit/0e88cdca534251e6675a6b6b55f7877c693aa505

Comment by Githook User [ 06/Sep/18 ]

Author:

{'name': 'Cheahuychou Mao', 'email': 'cheahuychou.mao@mongodb.com', 'username': 'cheahuychou'}

Message: SERVER-30841 Lower the amount of metadata refresh logging

(cherry picked from commit 8b066e35dd7c5a29e17f2d4b1cab69e984fadebc)
Branch: v4.0
https://github.com/mongodb/mongo/commit/fa32ebcfd379c3baa5dbe7c1273a636a66056033

Comment by Sigal Sh [X] [ 30/Jul/18 ]

What are the chances to get this fix in version 3.6?

 

Thanks in advance

Comment by Githook User [ 25/Jul/18 ]

Author:

{'username': 'cheahuychou', 'name': 'Cheahuychou Mao', 'email': 'cheahuychou.mao@mongodb.com'}

Message: SERVER-30841 Lower the amount of metadata refresh logging
Branch: master
https://github.com/mongodb/mongo/commit/8b066e35dd7c5a29e17f2d4b1cab69e984fadebc

Comment by Esha Maharishi (Inactive) [ 19/Jul/18 ]

Lgtm, suggestion to have it say

"from version X to version Y took Z ms"

rather than

"at version X took Z ms and found version Y"

Comment by Kaloian Manassiev [ 19/Jul/18 ]

For log level 1, there will not be any change from what it is now (except the extra "at version" component):

2017-08-22T12:02:14.386+1000 I SHARDING [Balancer] Refreshing chunks for collection mytest.test1 based on version 0|0||000000000000000000000000
2017-08-22T12:02:14.387+1000 I SHARDING [CatalogCacheLoader-0] Refresh for collection mytest.test1 at version 0|0||000000000000000000000000 took 0 ms and found version 1|0||599b909d11c6b22dd4ad5548

 

For log level 0, if the version of the metadata didn't change there will be nothing logged. If the version of the metadata changed, there will be 1 line logged with the following content (note the addition of the "at version" component to compensate for not logging the "Refreshing chunks..." line):

2017-08-22T12:02:14.387+1000 I SHARDING [CatalogCacheLoader-0] Refresh for collection mytest.test1 at version 0|0||000000000000000000000000 took 0 ms and found version 1|0||599b909d11c6b22dd4ad5548

Comment by Esha Maharishi (Inactive) [ 19/Jul/18 ]

kaloian.manassiev, can you show what the level 0 and level 1 log lines will be for a single refresh after the change?

Comment by Randolph Tan [ 19/Jul/18 ]

kaloian.manassiev: sounds good to me

Comment by Kaloian Manassiev [ 18/Jul/18 ]

Like Dianna mentions, this verbose logging on each refresh was useful while we had problems due to refresh stalls and it was beneficial to know where refresh waits are starting and ending. But with the introduction of the refresh FTDC metrics and since we have not seen any stalls, we could remove a large fraction of them. We should still keep the ones which report collection version changes in order to allow us to investigate bugs.

Here is what I propose:

  • Bump the log verbosity of the refresh start message to log level 1
  • Upon successful refresh completion, only log at log level 0 if the collection version/epoch changed in any way (this includes the collection switched from sharded to unsharded). Otherwise, log the end of the refresh at log level 1. The check for whether the collection version changed can be done by storing the current collection version here and then comparing it when refresh completes.

renctan, esha.maharishi - can you double check this for me? These changes will be done in master and backported all the way to 3.4. They will be done for the collection refresh path only, since this is what generates most of the log spam. I wouldn't touch the database refresh since it happens so rarely.

Comment by Githook User [ 26/Apr/18 ]

Author:

{'email': 'kaloian.manassiev@mongodb.com', 'username': 'kaloianm', 'name': 'Kaloian Manassiev'}

Message: SERVER-30841 Lower the logging verbosity in ShardServerCatalogCacheLoader
Branch: master
https://github.com/mongodb/mongo/commit/a39601ed33bbcf138d8ba644ff680bf1ff23564f

Generated at Thu Feb 08 04:25:11 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.