SERVER-35982 Include hash of plan cache key in cache transition log lines

4 files changed, 50 insertions, 11 deletions

diff --git a/jstests/noPassthrough/log_and_profile_query_hash.js b/jstests/noPassthrough/log_and_profile_query_hash.js
index 97da3dec2da..8c9db4e7102 100644
--- a/jstests/noPassthrough/log_and_profile_query_hash.js
+++ b/jstests/noPassthrough/log_and_profile_query_hash.js
@@ -118,5 +118,31 @@
     assert.neq(hashValues[0], hashValues[1]);
     assert.eq(hashValues[1], hashValues[2]);
 
+    // Test that the expected queryHash is included in the transitional log lines when an inactive
+    // cache entry is created.
+    assert.commandWorked(testDB.setLogLevel(1, "query"));
+    const testInactiveCreationLog = {
+        comment: "Test Creating inactive entry.",
+        test: function(db, comment) {
+            assert.eq(0,
+                      db.test.find({b: {$lt: 12}, a: {$eq: 500}})
+                          .sort({a: -1})
+                          .comment(comment)
+                          .itcount(),
+                      'unexpected document count');
+        },
+        hasQueryHash: true
+
+    };
+    const onCreationHash = runTestsAndGetHash(testDB, testInactiveCreationLog);
+    const log = assert.commandWorked(testDB.adminCommand({getLog: "global"})).log;
+
+    // Fetch the line that logs when an inactive cache entry is created for the query with queryHash
+    // onCreationHash. Confirm only one line does this.
+    const creationLogList = log.filter(
+        logLine => (logLine.indexOf("Creating inactive cache entry for query shape query") != -1 &&
+                    logLine.indexOf(String(onCreationHash)) != -1));
+    assert.eq(1, creationLogList.length);
+
     MongoRunner.stopMongod(conn);
 })();
diff --git a/src/mongo/db/query/get_executor.cpp b/src/mongo/db/query/get_executor.cpp
index 9ca28b322fa..0dae9645c93 100644
--- a/src/mongo/db/query/get_executor.cpp
+++ b/src/mongo/db/query/get_executor.cpp
@@ -38,7 +38,6 @@
 
 #include "mongo/base/error_codes.h"
 #include "mongo/base/parse_number.h"
-#include "mongo/base/simple_string_data_comparator.h"
 #include "mongo/db/catalog/index_catalog.h"
 #include "mongo/db/exec/cached_plan.h"
 #include "mongo/db/exec/collection_scan.h"
@@ -352,9 +351,7 @@ StatusWith<PrepareExecutionResult> prepareExecution(OperationContext* opCtx,
         auto planCacheKey = collection->infoCache()->getPlanCache()->computeKey(*canonicalQuery);
 
         // Fill in opDebug information.
-        boost::optional<uint32_t> hash =
-            SimpleStringDataComparator::kInstance.hash(StringData(planCacheKey));
-        CurOp::get(opCtx)->debug().queryHash = hash;
+        CurOp::get(opCtx)->debug().queryHash = PlanCache::computeQueryHash(planCacheKey);
 
         // Try to look up a cached solution for the query.
         if (auto cs =
diff --git a/src/mongo/db/query/plan_cache.cpp b/src/mongo/db/query/plan_cache.cpp
index 9e4fb5edf93..f132dc077b9 100644
--- a/src/mongo/db/query/plan_cache.cpp
+++ b/src/mongo/db/query/plan_cache.cpp
@@ -47,6 +47,7 @@
 #include "mongo/db/query/query_knobs.h"
 #include "mongo/db/query/query_solution.h"
 #include "mongo/util/assert_util.h"
+#include "mongo/util/hex.h"
 #include "mongo/util/log.h"
 #include "mongo/util/mongoutils/str.h"
 #include "mongo/util/transitional_tools_do_not_use/vector_spooling.h"
@@ -728,12 +729,14 @@ void PlanCache::encodeKeyForProj(const BSONObj& projObj, StringBuilder* keyBuild
  * - The new entry should be marked 'active'
  */
 PlanCache::NewEntryState PlanCache::getNewEntryState(const CanonicalQuery& query,
+                                                     uint32_t queryHash,
                                                      PlanCacheEntry* oldEntry,
                                                      size_t newWorks,
                                                      double growthCoefficient) {
     NewEntryState res;
     if (!oldEntry) {
         LOG(1) << "Creating inactive cache entry for query shape " << redact(query.toStringShort())
+               << " and queryHash " << unsignedIntToFixedLengthHex(queryHash)
                << " with works value " << newWorks;
         res.shouldBeCreated = true;
         res.shouldBeActive = false;
@@ -745,12 +748,14 @@ PlanCache::NewEntryState PlanCache::getNewEntryState(const CanonicalQuery& query
         // occur if many MultiPlanners are run simultaneously.
 
         LOG(1) << "Replacing active cache entry for query " << redact(query.toStringShort())
-               << " with works " << oldEntry->works << " with a plan with works " << newWorks;
+               << " and queryHash " << unsignedIntToFixedLengthHex(queryHash) << " with works "
+               << oldEntry->works << " with a plan with works " << newWorks;
         res.shouldBeCreated = true;
         res.shouldBeActive = true;
     } else if (oldEntry->isActive) {
         LOG(1) << "Attempt to write to the planCache for query " << redact(query.toStringShort())
-               << "with a plan with works " << newWorks
+               << " and queryHash " << unsignedIntToFixedLengthHex(queryHash)
+               << " with a plan with works " << newWorks
                << " is a noop, since there's already a plan with works value " << oldEntry->works;
         // There is already an active cache entry with a higher works value.
         // We do nothing.
@@ -768,7 +773,8 @@ PlanCache::NewEntryState PlanCache::getNewEntryState(const CanonicalQuery& query
             oldEntry->works + 1u, static_cast<size_t>(oldEntry->works * growthCoefficient));
 
         LOG(1) << "Increasing work value associated with cache entry for query "
-               << redact(query.toStringShort()) << " from " << oldEntry->works << " to "
+               << redact(query.toStringShort()) << " and queryHash "
+               << unsignedIntToFixedLengthHex(queryHash) << " from " << oldEntry->works << " to "
                << increasedWorks;
         oldEntry->works = increasedWorks;
 
@@ -779,8 +785,9 @@ PlanCache::NewEntryState PlanCache::getNewEntryState(const CanonicalQuery& query
         // inactive entry's works. We use this as an indicator that it's safe to
         // cache (as an active entry) the plan this query used for the future.
         LOG(1) << "Inactive cache entry for query " << redact(query.toStringShort())
-               << " with works " << oldEntry->works
-               << " is being promoted to active entry with works value " << newWorks;
+               << " and queryHash " << unsignedIntToFixedLengthHex(queryHash) << " with works "
+               << oldEntry->works << " is being promoted to active entry with works value "
+               << newWorks;
         // We'll replace the old inactive entry with an active entry.
         res.shouldBeCreated = true;
         res.shouldBeActive = true;
@@ -818,15 +825,24 @@ Status PlanCache::set(const CanonicalQuery& query,
     const size_t newWorks = why->stats[0]->common.works;
     stdx::lock_guard<stdx::mutex> cacheLock(_cacheMutex);
     bool isNewEntryActive = false;
+    uint32_t queryHash;
     if (internalQueryCacheDisableInactiveEntries.load()) {
         // All entries are always active.
         isNewEntryActive = true;
+        queryHash = PlanCache::computeQueryHash(key);
     } else {
         PlanCacheEntry* oldEntry = nullptr;
         Status cacheStatus = _cache.get(key, &oldEntry);
         invariant(cacheStatus.isOK() || cacheStatus == ErrorCodes::NoSuchKey);
+        if (oldEntry) {
+            queryHash = oldEntry->queryHash;
+        } else {
+            queryHash = PlanCache::computeQueryHash(key);
+        }
+
         auto newState = getNewEntryState(
             query,
+            queryHash,
             oldEntry,
             newWorks,
             worksGrowthCoefficient.get_value_or(internalQueryCacheWorksGrowthCoefficient));
@@ -837,7 +853,6 @@ Status PlanCache::set(const CanonicalQuery& query,
         isNewEntryActive = newState.shouldBeActive;
     }
 
-    uint32_t queryHash = computeQueryHash(key);
     auto newEntry = std::make_unique<PlanCacheEntry>(solns, why.release(), queryHash);
     const QueryRequest& qr = query.getQueryRequest();
     newEntry->query = qr.getFilter().getOwned();
diff --git a/src/mongo/db/query/plan_cache.h b/src/mongo/db/query/plan_cache.h
index 729cdafed3a..b0b767c13ea 100644
--- a/src/mongo/db/query/plan_cache.h
+++ b/src/mongo/db/query/plan_cache.h
@@ -396,7 +396,7 @@ public:
      * The return value will provide the "state" of the cache entry, as well as the CachedSolution
      * for the query (if there is one).
      */
-    GetResult get(const PlanCacheKey& query) const;
+    GetResult get(const PlanCacheKey& key) const;
 
     /**
      * If the cache entry exists and is active, return a CachedSolution. If the cache entry is
@@ -483,6 +483,7 @@ private:
     };
 
     NewEntryState getNewEntryState(const CanonicalQuery& query,
+                                   uint32_t queryHash,
                                    PlanCacheEntry* oldEntry,
                                    size_t newWorks,
                                    double growthCoefficient);