SERVER-25951 Report additional metrics in getMore slowms logging

2 files changed, 40 insertions, 0 deletions

diff --git a/src/mongo/db/commands/getmore_cmd.cpp b/src/mongo/db/commands/getmore_cmd.cpp
index acee5db9e97..bb545b2ebff 100644
--- a/src/mongo/db/commands/getmore_cmd.cpp
+++ b/src/mongo/db/commands/getmore_cmd.cpp
@@ -299,6 +299,12 @@ public:
         exec->reattachToOperationContext(txn);
         exec->restoreState();
 
+        auto planSummary = Explain::getPlanSummary(exec);
+        {
+            stdx::lock_guard<Client>(*txn->getClient());
+            CurOp::get(txn)->setPlanSummary_inlock(planSummary);
+        }
+
         uint64_t notifierVersion = 0;
         std::shared_ptr<CappedInsertNotifier> notifier;
         if (isCursorAwaitData(cursor)) {
@@ -319,6 +325,13 @@ public:
         BSONObj obj;
         PlanExecutor::ExecState state;
         long long numResults = 0;
+
+        // We report keysExamined and docsExamined to OpDebug for a given getMore operation. To
+        // obtain these values we need to take a diff of the pre-execution and post-execution
+        // metrics, as they accumulate over the course of a cursor's lifetime.
+        PlanSummaryStats preExecutionStats;
+        Explain::getSummaryStats(*exec, &preExecutionStats);
+
         Status batchStatus = generateBatch(cursor, request, &nextBatch, &state, &numResults);
         if (!batchStatus.isOK()) {
             return appendCommandStatus(result, batchStatus);
@@ -363,6 +376,13 @@ public:
             }
         }
 
+        PlanSummaryStats postExecutionStats;
+        Explain::getSummaryStats(*exec, &postExecutionStats);
+        CurOp::get(txn)->debug().keysExamined =
+            postExecutionStats.totalKeysExamined - preExecutionStats.totalKeysExamined;
+        CurOp::get(txn)->debug().docsExamined =
+            postExecutionStats.totalDocsExamined - preExecutionStats.totalDocsExamined;
+
         if (shouldSaveCursorGetMore(state, exec, isCursorTailable(cursor))) {
             respondWithId = request.cursorid;
 
diff --git a/src/mongo/db/query/find.cpp b/src/mongo/db/query/find.cpp
index ce5ca434431..813b019aba7 100644
--- a/src/mongo/db/query/find.cpp
+++ b/src/mongo/db/query/find.cpp
@@ -386,6 +386,19 @@ QueryResult::View getMore(OperationContext* txn,
         PlanExecutor* exec = cc->getExecutor();
         exec->reattachToOperationContext(txn);
         exec->restoreState();
+
+        auto planSummary = Explain::getPlanSummary(exec);
+        {
+            stdx::lock_guard<Client>(*txn->getClient());
+            curop.setPlanSummary_inlock(planSummary);
+        }
+
+        // We report keysExamined and docsExamined to OpDebug for a given getMore operation. To
+        // obtain these values we need to take a diff of the pre-execution and post-execution
+        // metrics, as they accumulate over the course of a cursor's lifetime.
+        PlanSummaryStats preExecutionStats;
+        Explain::getSummaryStats(*exec, &preExecutionStats);
+
         PlanExecutor::ExecState state;
 
         generateBatch(ntoreturn, cc, &bb, &numResults, &slaveReadTill, &state);
@@ -415,6 +428,13 @@ QueryResult::View getMore(OperationContext* txn,
             generateBatch(ntoreturn, cc, &bb, &numResults, &slaveReadTill, &state);
         }
 
+        PlanSummaryStats postExecutionStats;
+        Explain::getSummaryStats(*exec, &postExecutionStats);
+        curop.debug().keysExamined =
+            postExecutionStats.totalKeysExamined - preExecutionStats.totalKeysExamined;
+        curop.debug().docsExamined =
+            postExecutionStats.totalDocsExamined - preExecutionStats.totalDocsExamined;
+
         // We have to do this before re-acquiring locks in the agg case because
         // shouldSaveCursorGetMore() can make a network call for agg cursors.
         //