Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-74980

excessive logging of "Refreshed cached collection" log messages introduced in 5.0

    • Sharding EMEA
    • Fully Compatible
    • ALL
    • v7.0, v6.3, v6.0, v5.0
    • Hide

      Run a 5.0.15 sharded cluster with lots of collections

      Run a 5.0.15 sharded cluster with lots of collections
    • Sharding EMEA 2023-04-03, Sharding EMEA 2023-04-17, Sharding EMEA 2023-05-01, Sharding EMEA 2023-05-15

      We recently upgraded one of our clusters from 4.4.16 to 5.0.15. Prior to upgrading we saw about 50K "Refreshed cached collection" log messages per hour. Now we see about 50K per minute - an increase by 2 orders of magnitude.

      Looking at the source code, it looks like the lookupCollection method in catalog{_}cache.cpp was refactored in 5.0, resulting in a regression where the "Refreshed cached collection" message is always logged at level 0, versus in 4.4 where it was only logged at level 0 on the very first call or when the version had changed.

      From 4.4 (https://github.com/mongodb/mongo/blob/v4.4/src/mongo/s/catalog_cache.cpp#L756-L774):

      const int logLevel =                (!existingRoutingInfo ||                 (existingRoutingInfo &&                  routingInfoAfterRefresh->getVersion() != existingRoutingInfo->getVersion()))                ? 0                : 1; 

      From 5.0 (https://github.com/mongodb/mongo/blob/v5.0/src/mongo/s/catalog_cache.cpp#L667-L674):

      // logLevel
      isIncremental || newComparableVersion != previousVersion ? 0 : 1, 


      So the 4.4 logic was to to log at level 0 if it's the very first call for the collection (!existingRoutingInfo) or if the version has changed.

      In 5.0, the logic changed to log at level 0 if it's any call other than the very first call (isIncremental) or the version has changed. I believe this change in logic was unintentional, as it results in a huge amount of level 0 log spam. I think what was intended is:

       // logLevel
      !isIncremental || newComparableVersion != previousVersion ? 0 : 1, 

      Notice "isIncremental" was changed to "!isIncremental".

            sergi.mateo-bellido@mongodb.com Sergi Mateo Bellido
            ian.springer@salesforce.com Ian Springer
            0 Vote for this issue
            9 Start watching this issue