SERVER-50559 Don't log waiting change stream getMores as slow queries

3 files changed, 26 insertions, 3 deletions

diff --git a/etc/backports_required_for_multiversion_tests.yml b/etc/backports_required_for_multiversion_tests.yml
index b4112b37ce4..6ef6afa9482 100644
--- a/etc/backports_required_for_multiversion_tests.yml
+++ b/etc/backports_required_for_multiversion_tests.yml
@@ -202,6 +202,8 @@ last-lts:
       test_file: jstests/sharding/txn_writes_during_movechunk.js
     - ticket: SERVER-57772
       test_file: jstests/sharding/rewrite_state_change_errors.js
+    - ticket: SERVER-50559
+      test_file: jstests/sharding/log_remote_op_wait.js
 
   # Tests that should only be excluded from particular suites should be listed under that suite.
   suites:
diff --git a/jstests/sharding/log_remote_op_wait.js b/jstests/sharding/log_remote_op_wait.js
index 200f2bbcc9f..06bd3a9809a 100644
--- a/jstests/sharding/log_remote_op_wait.js
+++ b/jstests/sharding/log_remote_op_wait.js
@@ -11,7 +11,6 @@ st.stopBalancer();
 
 const dbName = st.s.defaultDB;
 const coll = st.s.getDB(dbName).getCollection('profile_remote_op_wait');
-const shardDB = st.shard0.getDB(dbName);
 
 coll.drop();
 assert.commandWorked(st.s.adminCommand({enableSharding: dbName}));
@@ -96,9 +95,11 @@ cursor.hasNext();
     assert.lte(remoteOpWait, duration);
 }
 
-// A changestream is a type of aggregation, so it reports remoteOpWait.
+// A changestream is a type of aggregation, so it reports remoteOpWait. The initial $changeStream
+// 'aggregate' command never pauses execution while awaiting data, and so we expect the remoteOpWait
+// time to be less than or equal to the total execution duration.
 const watchComment = 'example_watch_should_have_remote_op_wait';
-coll.watch([], {comment: watchComment}).hasNext();
+const csCursor = coll.watch([], {comment: watchComment});
 {
     const mongosLog = assert.commandWorked(st.s.adminCommand({getLog: "global"}));
     const line = findMatchingLogLine(mongosLog.log, {msg: "Slow query", comment: watchComment});
@@ -108,6 +109,21 @@ coll.watch([], {comment: watchComment}).hasNext();
     assert.lte(remoteOpWait, duration);
 }
 
+// A $changeStream getMore may pause execution while awaiting data if no results are currently
+// available. In this case, it is possible for the total execution time to be less than the
+// remoteOpWait time.
+assert(!csCursor.hasNext());
+{
+    const mongosLog = assert.commandWorked(st.s.adminCommand({getLog: "global"}));
+    const line = findMatchingLogLine(
+        mongosLog.log, {msg: "Slow query", comment: watchComment, command: "getMore"});
+    assert(line, "Failed to find a log line matching the comment");
+    const remoteOpWait = getRemoteOpWait(line);
+    const duration = getDuration(line);
+    assert.lte(duration, 100);
+    assert.gte(remoteOpWait, 900);
+}
+
 // An equivalent .find() does not include remoteOpWaitMillis.
 const findComment = 'example_find_should_not_have_remote_op_wait';
 coll.find().sort({x: 1}).comment(findComment).next();
diff --git a/src/mongo/s/query/blocking_results_merger.cpp b/src/mongo/s/query/blocking_results_merger.cpp
index 7f9edc2cb0e..011fc120c28 100644
--- a/src/mongo/s/query/blocking_results_merger.cpp
+++ b/src/mongo/s/query/blocking_results_merger.cpp
@@ -96,6 +96,11 @@ StatusWith<ClusterQueryResult> BlockingResultsMerger::awaitNextWithTimeout(
         auto event = nextEventStatus.getValue();
 
         const auto waitStatus = doWaiting(opCtx, [this, opCtx, &event]() {
+            // Time that an awaitData cursor spends waiting for new results is not counted as
+            // execution time, so we pause the CurOp timer.
+            CurOp::get(opCtx)->pauseTimer();
+            ON_BLOCK_EXIT([&] { CurOp::get(opCtx)->resumeTimer(); });
+
             return _executor->waitForEvent(
                 opCtx, event, awaitDataState(opCtx).waitForInsertsDeadline);
         });