SERVER-62760 Implement CQF Query Logging

8 files changed, 143 insertions, 72 deletions

diff --git a/jstests/noPassthrough/query_engine_stats.js b/jstests/noPassthrough/query_engine_stats.js
index 250943806d1..48339e1927e 100644
--- a/jstests/noPassthrough/query_engine_stats.js
+++ b/jstests/noPassthrough/query_engine_stats.js
@@ -10,10 +10,10 @@
 load("jstests/libs/profiler.js");
 load("jstests/libs/sbe_util.js");  // For 'checkSBEEnabled()'.
 
-const conn = MongoRunner.runMongod({});
+let conn = MongoRunner.runMongod({});
 assert.neq(null, conn, "mongod was unable to start up");
 
-const db = conn.getDB(jsTestName());
+let db = conn.getDB(jsTestName());
 
 // This test assumes that SBE is being used for most queries.
 if (!checkSBEEnabled(db, ["featureFlagSbeFull"])) {
@@ -24,7 +24,7 @@ if (!checkSBEEnabled(db, ["featureFlagSbeFull"])) {
 
 assert.commandWorked(db.dropDatabase());
 
-const coll = db.collection;
+let coll = db.collection;
 
 // Set logLevel to 1 so that all queries will be logged.
 assert.commandWorked(db.setLogLevel(1));
@@ -40,78 +40,87 @@ assert.commandWorked(coll.insertMany([
     {_id: 3, a: 4, b: 2, c: 4}
 ]));
 
-const engine = {
-    find: {sbe: "sbe", classic: "classic"},
+const framework = {
+    find: {sbe: "sbe", classic: "classic", cqf: "findCQF"},
     aggregate: {
         sbeHybrid: "sbeHybrid",
         classicHybrid: "classicHybrid",
         sbeOnly: "sbeOnly",
-        classicOnly: "classicOnly"
+        classicOnly: "classicOnly",
+        cqf: "aggCQF"
     }
 };
 
-// Ensure the slow query log contains the correct information about the queryExecutionEngine used.
-function verifySlowQueryLog(expectedComment, execEngine) {
+/**
+ * Ensure the slow query log contains the correct information about the queryFramework used.
+ */
+function verifySlowQueryLog(expectedComment, queryFramework) {
     const logId = 51803;
     const expectedLog = {};
     expectedLog.command = {};
     expectedLog.command.comment = expectedComment;
-    if (execEngine) {
-        expectedLog.queryExecutionEngine = execEngine;
+    if (queryFramework) {
+        expectedLog.queryFramework = queryFramework;
     }
     assert(checkLog.checkContainsWithCountJson(db, logId, expectedLog, 1, null, true),
            "failed to find [" + tojson(expectedLog) + "] in the slow query log");
 }
 
-// Ensure the profile filter contains the correct information about the queryExecutionEngine used.
-function verifyProfiler(expectedComment, execEngine) {
+// Ensure the profile filter contains the correct information about the queryFramework used.
+function verifyProfiler(expectedComment, queryFramework) {
     const profileEntryFilter = {ns: "query_engine_stats.collection"};
     const profileObj = getLatestProfilerEntry(db, profileEntryFilter);
     try {
         assert.eq(profileObj.command.comment, expectedComment);
-        if (execEngine) {
-            assert.eq(profileObj.queryExecutionEngine, execEngine);
+        if (queryFramework) {
+            assert.eq(profileObj.queryFramework, queryFramework);
         }
     } catch (e) {
-        print('failed to find [{ "queryExecutionEngine" : "' + execEngine + '", { "comment" : "' +
+        print('failed to find [{ "queryFramework" : "' + queryFramework + '", { "comment" : "' +
               expectedComment + '"} }] in the latest profiler entry.');
         throw (e);
     }
 }
 
-// Create an object with the correct queryExecutionEngine counter values after the specified type of
+// Create an object with the correct queryFramework counter values after the specified type of
 // query.
-function generateExpectedCounters(execEngine) {
-    let counters = db.serverStatus().metrics.query.queryExecutionEngine;
+function generateExpectedCounters(queryFramework) {
+    let counters = db.serverStatus().metrics.query.queryFramework;
     assert(counters, "counters did not exist");
     let expected = Object.assign(counters);
-    switch (execEngine) {
-        case engine.find.sbe:
+    switch (queryFramework) {
+        case framework.find.sbe:
             expected.find.sbe = NumberLong(expected.find.sbe + 1);
             break;
-        case engine.find.classic:
+        case framework.find.classic:
             expected.find.classic = NumberLong(expected.find.classic + 1);
             break;
-        case engine.aggregate.sbeOnly:
+        case framework.find.cqf:
+            expected.find.cqf = NumberLong(expected.find.cqf + 1);
+            break;
+        case framework.aggregate.sbeOnly:
             expected.aggregate.sbeOnly = NumberLong(expected.aggregate.sbeOnly + 1);
             break;
-        case engine.aggregate.classicOnly:
+        case framework.aggregate.classicOnly:
             expected.aggregate.classicOnly = NumberLong(expected.aggregate.classicOnly + 1);
             break;
-        case engine.aggregate.sbeHybrid:
+        case framework.aggregate.sbeHybrid:
             expected.aggregate.sbeHybrid = NumberLong(expected.aggregate.sbeHybrid + 1);
             break;
-        case engine.aggregate.classicHybrid:
+        case framework.aggregate.classicHybrid:
             expected.aggregate.classicHybrid = NumberLong(expected.aggregate.classicHybrid + 1);
             break;
+        case framework.aggregate.cqf:
+            expected.aggregate.cqf = NumberLong(expected.aggregate.cqf + 1);
+            break;
     }
     return expected;
 }
 
-// Compare the values of the queryExecutionEngine counters to an object that represents the expected
+// Compare the values of the queryFramework counters to an object that represents the expected
 // values.
 function compareQueryEngineCounters(expectedCounters) {
-    let counters = db.serverStatus().metrics.query.queryExecutionEngine;
+    let counters = db.serverStatus().metrics.query.queryFramework;
     assert.docEq(counters, expectedCounters);
 }
 
@@ -119,23 +128,23 @@ function compareQueryEngineCounters(expectedCounters) {
 assert.commandWorked(db.adminCommand({setParameter: 1, internalQueryForceClassicEngine: true}));
 
 // Run a find command.
-let expectedCounters = generateExpectedCounters(engine.find.classic);
+let expectedCounters = generateExpectedCounters(framework.find.classic);
 let queryComment = "findSbeOff";
 assert.eq(coll.find({a: 3}).comment(queryComment).itcount(), 1);
-verifySlowQueryLog(queryComment, engine.find.classic);
+verifySlowQueryLog(queryComment, framework.find.classic);
 compareQueryEngineCounters(expectedCounters);
-verifyProfiler(queryComment, engine.find.classic);
+verifyProfiler(queryComment, framework.find.classic);
 
 // Run an aggregation that doesn't use DocumentSource.
-expectedCounters = generateExpectedCounters(engine.aggregate.classicOnly);
+expectedCounters = generateExpectedCounters(framework.aggregate.classicOnly);
 queryComment = "aggSbeOff";
 assert.eq(coll.aggregate([{$match: {b: 1, c: 3}}], {comment: queryComment}).itcount(), 1);
-verifySlowQueryLog(queryComment, engine.find.classic);
+verifySlowQueryLog(queryComment, framework.find.classic);
 compareQueryEngineCounters(expectedCounters);
-verifyProfiler(queryComment, engine.find.classic);
+verifyProfiler(queryComment, framework.find.classic);
 
 // Run an aggregation that uses DocumentSource.
-expectedCounters = generateExpectedCounters(engine.aggregate.classicHybrid);
+expectedCounters = generateExpectedCounters(framework.aggregate.classicHybrid);
 queryComment = "docSourceSbeOff";
 assert.eq(coll.aggregate(
                   [
@@ -146,31 +155,31 @@ assert.eq(coll.aggregate(
                   {comment: queryComment})
               .itcount(),
           0);
-verifySlowQueryLog(queryComment, engine.find.classic);
+verifySlowQueryLog(queryComment, framework.find.classic);
 compareQueryEngineCounters(expectedCounters);
-verifyProfiler(queryComment, engine.find.classic);
+verifyProfiler(queryComment, framework.find.classic);
 
 // Turn SBE on.
 assert.commandWorked(db.adminCommand({setParameter: 1, internalQueryForceClassicEngine: false}));
 
 // Run a find command.
-expectedCounters = generateExpectedCounters(engine.find.sbe);
+expectedCounters = generateExpectedCounters(framework.find.sbe);
 queryComment = "findSbeOn";
 assert.eq(coll.find({a: 3}).comment(queryComment).itcount(), 1);
-verifySlowQueryLog(queryComment, engine.find.sbe);
+verifySlowQueryLog(queryComment, framework.find.sbe);
 compareQueryEngineCounters(expectedCounters);
-verifyProfiler(queryComment, engine.find.sbe);
+verifyProfiler(queryComment, framework.find.sbe);
 
 // Run an aggregation that doesn't use DocumentSource.
-expectedCounters = generateExpectedCounters(engine.aggregate.sbeOnly);
+expectedCounters = generateExpectedCounters(framework.aggregate.sbeOnly);
 queryComment = "aggSbeOn";
 assert.eq(coll.aggregate([{$match: {b: 1, c: 3}}], {comment: queryComment}).itcount(), 1);
-verifySlowQueryLog(queryComment, engine.find.sbe);
+verifySlowQueryLog(queryComment, framework.find.sbe);
 compareQueryEngineCounters(expectedCounters);
-verifyProfiler(queryComment, engine.find.sbe);
+verifyProfiler(queryComment, framework.find.sbe);
 
 // Run an aggregation that uses DocumentSource.
-expectedCounters = generateExpectedCounters(engine.aggregate.sbeHybrid);
+expectedCounters = generateExpectedCounters(framework.aggregate.sbeHybrid);
 queryComment = "docSourceSbeOn";
 assert.eq(coll.aggregate(
                   [
@@ -181,9 +190,46 @@ assert.eq(coll.aggregate(
                   {comment: queryComment})
               .itcount(),
           0);
-verifySlowQueryLog(queryComment, engine.find.sbe);
+verifySlowQueryLog(queryComment, framework.find.sbe);
+compareQueryEngineCounters(expectedCounters);
+verifyProfiler(queryComment, framework.find.sbe);
+
+MongoRunner.stopMongod(conn);
+
+conn = MongoRunner.runMongod({restart: conn, setParameter: 'featureFlagCommonQueryFramework=1'});
+assert.neq(null, conn, "mongod was unable to start up");
+
+db = conn.getDB(jsTestName());
+
+assert.commandWorked(db.setLogLevel(1));
+assert.commandWorked(db.setProfilingLevel(2));
+
+coll = db.collection;
+
+// Run find using CQF
+expectedCounters = generateExpectedCounters(framework.find.cqf);
+queryComment = "cqfFind";
+assert.eq(coll.find({a: 1}).comment(queryComment).itcount(), 1);
+verifySlowQueryLog(queryComment, "cqf");
+compareQueryEngineCounters(expectedCounters);
+verifyProfiler(queryComment, "cqf");
+
+// Run aggregate using CQF
+expectedCounters = generateExpectedCounters(framework.aggregate.cqf);
+queryComment = "cqfAggregate";
+assert.eq(
+    coll.aggregate([{$match: {a: 1}}, {$project: {_id: 0}}], {comment: queryComment}).itcount(), 1);
+verifySlowQueryLog(queryComment, "cqf");
+compareQueryEngineCounters(expectedCounters);
+verifyProfiler(queryComment, "cqf");
+
+// Run CQF query which falls back to SBE (unsupported match expression)
+expectedCounters = generateExpectedCounters(framework.find.sbe);
+queryComment = "cqfFallback";
+assert.eq(coll.find({a: {$mod: [4, 0]}}).comment(queryComment).itcount(), 1);
+verifySlowQueryLog(queryComment, framework.find.sbe);
 compareQueryEngineCounters(expectedCounters);
-verifyProfiler(queryComment, engine.find.sbe);
+verifyProfiler(queryComment, framework.find.sbe);
 
 MongoRunner.stopMongod(conn);
 })();
diff --git a/jstests/noPassthrough/sbe_plan_cache_key_reporting.js b/jstests/noPassthrough/sbe_plan_cache_key_reporting.js
index 940b199dc27..3207d8a2f27 100644
--- a/jstests/noPassthrough/sbe_plan_cache_key_reporting.js
+++ b/jstests/noPassthrough/sbe_plan_cache_key_reporting.js
@@ -89,8 +89,8 @@ function assertQueryHashAndPlanCacheKey(sbe, classic) {
 
     assert.neq(sbe, null);
     assert.neq(classic, null);
-    assert.eq(sbe.queryExecutionEngine, "sbe", sbe);
-    assert.eq(classic.queryExecutionEngine, "classic", classic);
+    assert.eq(sbe.queryFramework, "sbe", sbe);
+    assert.eq(classic.queryFramework, "classic", classic);
 
     assertQueryHashAndPlanCacheKey(sbe, classic);
 })();
@@ -159,8 +159,8 @@ function assertQueryHashAndPlanCacheKey(sbe, classic) {
 
     assert.neq(sbe, null);
     assert.neq(classic, null);
-    assert.eq(sbe.attr.queryExecutionEngine, "sbe", sbe);
-    assert.eq(classic.attr.queryExecutionEngine, "classic", classic);
+    assert.eq(sbe.attr.queryFramework, "sbe", sbe);
+    assert.eq(classic.attr.queryFramework, "classic", classic);
 
     assertQueryHashAndPlanCacheKey(sbe.attr, classic.attr);
 })();
diff --git a/src/mongo/db/commands/cqf/cqf_aggregate.cpp b/src/mongo/db/commands/cqf/cqf_aggregate.cpp
index 100da0be582..b9f35c17bd4 100644
--- a/src/mongo/db/commands/cqf/cqf_aggregate.cpp
+++ b/src/mongo/db/commands/cqf/cqf_aggregate.cpp
@@ -29,6 +29,7 @@
 
 #include "mongo/db/commands/cqf/cqf_aggregate.h"
 
+#include "mongo/db/curop.h"
 #include "mongo/db/exec/sbe/abt/abt_lower.h"
 #include "mongo/db/pipeline/abt/abt_document_source_visitor.h"
 #include "mongo/db/pipeline/abt/match_expression_visitor.h"
@@ -335,6 +336,9 @@ std::unique_ptr<PlanExecutor, PlanExecutor::Deleter> getSBEExecutorViaCascadesOp
     const std::string collNameStr = nss.coll().toString();
     const std::string scanDefName = collNameStr + "_" + uuidStr;
 
+    auto curOp = CurOp::get(opCtx);
+    curOp->debug().cqfUsed = true;
+
     QueryHints queryHints = getHintsFromQueryKnobs();
 
     PrefixId prefixId;
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index 556128f6d87..8819832b6a2 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -868,7 +868,9 @@ void OpDebug::report(OperationContext* opCtx,
     }
 
     if (classicEngineUsed) {
-        pAttrs->add("queryExecutionEngine", classicEngineUsed.get() ? "classic" : "sbe");
+        pAttrs->add("queryFramework", classicEngineUsed.value() ? "classic" : "sbe");
+    } else if (cqfUsed) {
+        pAttrs->add("queryFramework", "cqf");
     }
 
     if (!errInfo.isOK()) {
@@ -1031,7 +1033,9 @@ void OpDebug::append(OperationContext* opCtx,
     }
 
     if (classicEngineUsed) {
-        b.append("queryExecutionEngine", classicEngineUsed.get() ? "classic" : "sbe");
+        b.append("queryFramework", classicEngineUsed.value() ? "classic" : "sbe");
+    } else if (cqfUsed) {
+        b.append("queryFramework", "cqf");
     }
 
     {
@@ -1307,9 +1311,11 @@ std::function<BSONObj(ProfileFilter::Args)> OpDebug::appendStaged(StringSet requ
         }
     });
 
-    addIfNeeded("queryExecutionEngine", [](auto field, auto args, auto& b) {
+    addIfNeeded("queryFramework", [](auto field, auto args, auto& b) {
         if (args.op.classicEngineUsed) {
-            b.append("queryExecutionEngine", args.op.classicEngineUsed.get() ? "classic" : "sbe");
+            b.append("queryFramework", args.op.classicEngineUsed.value() ? "classic" : "sbe");
+        } else if (args.op.cqfUsed) {
+            b.append("queryFramework", "cqf");
         }
     });
 
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index cdc5e4f20d7..4aa0ccb5bb3 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -263,13 +263,17 @@ public:
     boost::optional<uint32_t> queryHash;
 
     // Has a value if this operation is a query. True if the execution tree for the find part of the
-    // query was built using the classic query engine, false if it was built in SBE.
+    // query was built exclusively using the classic query engine, false if any part was built using
+    // SBE.
     boost::optional<bool> classicEngineUsed;
 
     // Has a value if this operation is an aggregation query. True if `DocumentSources` were
     // involved in the execution tree for this query, false if they were not.
     boost::optional<bool> documentSourceUsed;
 
+    // Indicates whether this operation used the common query framework (CQF).
+    bool cqfUsed{false};
+
     // Details of any error (whether from an exception or a command returning failure).
     Status errInfo = Status::OK();
 
diff --git a/src/mongo/db/curop_metrics.cpp b/src/mongo/db/curop_metrics.cpp
index 63537de8980..d51d86a7c14 100644
--- a/src/mongo/db/curop_metrics.cpp
+++ b/src/mongo/db/curop_metrics.cpp
@@ -82,7 +82,7 @@ void recordCurOpMetrics(OperationContext* opCtx) {
     if (auto n = debug.additiveMetrics.writeConflicts.load(); n > 0)
         writeConflictsCounter.increment(n);
 
-    queryEngineCounters.incrementQueryEngineCounters(CurOp::get(opCtx));
+    queryFrameworkCounters.incrementQueryEngineCounters(CurOp::get(opCtx));
 }
 
 }  // namespace mongo
diff --git a/src/mongo/db/stats/counters.cpp b/src/mongo/db/stats/counters.cpp
index e6099775e85..47f1016d9d5 100644
--- a/src/mongo/db/stats/counters.cpp
+++ b/src/mongo/db/stats/counters.cpp
@@ -335,7 +335,7 @@ NetworkCounter networkCounter;
 AuthCounter authCounter;
 AggStageCounters aggStageCounters;
 DotsAndDollarsFieldsCounters dotsAndDollarsFieldsCounters;
-QueryEngineCounters queryEngineCounters;
+QueryFrameworkCounters queryFrameworkCounters;
 
 OperatorCounters operatorCountersAggExpressions{"operatorCounters.expressions."};
 OperatorCounters operatorCountersMatchExpressions{"operatorCounters.match."};
diff --git a/src/mongo/db/stats/counters.h b/src/mongo/db/stats/counters.h
index 2e07b64fe3c..bd190a97e20 100644
--- a/src/mongo/db/stats/counters.h
+++ b/src/mongo/db/stats/counters.h
@@ -337,20 +337,21 @@ public:
 
 extern DotsAndDollarsFieldsCounters dotsAndDollarsFieldsCounters;
 
-class QueryEngineCounters {
+class QueryFrameworkCounters {
 public:
-    QueryEngineCounters()
-        : sbeFindQueryMetric("query.queryExecutionEngine.find.sbe", &sbeFindQueryCounter),
-          classicFindQueryMetric("query.queryExecutionEngine.find.classic",
-                                 &classicFindQueryCounter),
-          sbeOnlyAggregationMetric("query.queryExecutionEngine.aggregate.sbeOnly",
+    QueryFrameworkCounters()
+        : sbeFindQueryMetric("query.queryFramework.find.sbe", &sbeFindQueryCounter),
+          classicFindQueryMetric("query.queryFramework.find.classic", &classicFindQueryCounter),
+          cqfFindQueryMetric("query.queryFramework.find.cqf", &cqfFindQueryCounter),
+          sbeOnlyAggregationMetric("query.queryFramework.aggregate.sbeOnly",
                                    &sbeOnlyAggregationCounter),
-          classicOnlyAggregationMetric("query.queryExecutionEngine.aggregate.classicOnly",
+          classicOnlyAggregationMetric("query.queryFramework.aggregate.classicOnly",
                                        &classicOnlyAggregationCounter),
-          sbeHybridAggregationMetric("query.queryExecutionEngine.aggregate.sbeHybrid",
+          sbeHybridAggregationMetric("query.queryFramework.aggregate.sbeHybrid",
                                      &sbeHybridAggregationCounter),
-          classicHybridAggregationMetric("query.queryExecutionEngine.aggregate.classicHybrid",
-                                         &classicHybridAggregationCounter) {}
+          classicHybridAggregationMetric("query.queryFramework.aggregate.classicHybrid",
+                                         &classicHybridAggregationCounter),
+          cqfAggregationMetric("query.queryFramework.aggregate.cqf", &cqfAggregationQueryCounter) {}
 
     void incrementQueryEngineCounters(CurOp* curop) {
         auto& debug = curop->debug();
@@ -376,29 +377,39 @@ public:
                     sbeOnlyAggregationCounter.increment();
                 }
             }
+        } else if (debug.cqfUsed) {
+            if (cmdName == "find") {
+                cqfFindQueryCounter.increment();
+            } else {
+                cqfAggregationQueryCounter.increment();
+            }
         }
     }
 
-    // Query counters that record whether a find query was fully or partially executed in SBE, or
-    // fully executed using the classic engine. One or the other will always be incremented during a
-    // query.
+    // Query counters that record whether a find query was fully or partially executed in SBE, fully
+    // executed using the classic engine, or fully executed using the common query framework (CQF).
+    // One of these will always be incremented during a query.
     Counter64 sbeFindQueryCounter;
     Counter64 classicFindQueryCounter;
+    Counter64 cqfFindQueryCounter;
     ServerStatusMetricField<Counter64> sbeFindQueryMetric;
     ServerStatusMetricField<Counter64> classicFindQueryMetric;
+    ServerStatusMetricField<Counter64> cqfFindQueryMetric;
     // Aggregation query counters that record whether an aggregation was fully or partially executed
-    // in DocumentSource (an sbe/classic hybrid plan), or fully pushed down to the sbe/classic
-    // layer. Only incremented during aggregations.
+    // in DocumentSource (an sbe/classic hybrid plan), fully pushed down to the sbe/classic layer,
+    // or executed using CQF. These are only incremented during aggregations.
     Counter64 sbeOnlyAggregationCounter;
     Counter64 classicOnlyAggregationCounter;
     Counter64 sbeHybridAggregationCounter;
     Counter64 classicHybridAggregationCounter;
+    Counter64 cqfAggregationQueryCounter;
     ServerStatusMetricField<Counter64> sbeOnlyAggregationMetric;
     ServerStatusMetricField<Counter64> classicOnlyAggregationMetric;
     ServerStatusMetricField<Counter64> sbeHybridAggregationMetric;
     ServerStatusMetricField<Counter64> classicHybridAggregationMetric;
+    ServerStatusMetricField<Counter64> cqfAggregationMetric;
 };
-extern QueryEngineCounters queryEngineCounters;
+extern QueryFrameworkCounters queryFrameworkCounters;
 
 /**
  * Generic class for counters of expressions inside various MQL statements.