SERVER-40416 Add logging to fts document source

4 files changed, 48 insertions, 2 deletions

diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index de531be80e8..42ef17cf216 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -659,6 +659,9 @@ string OpDebug::report(Client* client,
 
     OPDEBUG_TOSTRING_HELP(nShards);
     OPDEBUG_TOSTRING_HELP(cursorid);
+    if (mongotCursorId) {
+        s << " mongot: " << makeSearchBetaObject().toString();
+    }
     OPDEBUG_TOSTRING_HELP(ntoreturn);
     OPDEBUG_TOSTRING_HELP(ntoskip);
     OPDEBUG_TOSTRING_HELP_BOOL(exhaust);
@@ -761,6 +764,9 @@ void OpDebug::append(const CurOp& curop,
 
     OPDEBUG_APPEND_NUMBER(nShards);
     OPDEBUG_APPEND_NUMBER(cursorid);
+    if (mongotCursorId) {
+        b.append("mongot", makeSearchBetaObject());
+    }
     OPDEBUG_APPEND_BOOL(exhaust);
 
     OPDEBUG_APPEND_OPTIONAL("keysExamined", additiveMetrics.keysExamined);
@@ -856,6 +862,16 @@ BSONObj OpDebug::makeFlowControlObject(FlowControlTicketholder::CurOp stats) con
     return builder.obj();
 }
 
+BSONObj OpDebug::makeSearchBetaObject() const {
+    BSONObjBuilder cursorBuilder;
+    invariant(mongotCursorId);
+    cursorBuilder.append("cursorid", mongotCursorId.get());
+    if (msWaitingForMongot) {
+        cursorBuilder.append("timeWaitingMillis", msWaitingForMongot.get());
+    }
+    return cursorBuilder.obj();
+}
+
 
 namespace {
 
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index ba1438f92a5..1c537770907 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -168,6 +168,11 @@ public:
      */
     BSONObj makeFlowControlObject(FlowControlTicketholder::CurOp flowControlStats) const;
 
+    /**
+     * Make object from $searchBeta stats with non-populated values omitted.
+     */
+    BSONObj makeSearchBetaObject() const;
+
     // -------------------
 
     // basic options
@@ -185,6 +190,10 @@ public:
     long long ntoskip{-1};
     bool exhaust{false};
 
+    // For searchBeta.
+    boost::optional<long long> mongotCursorId{boost::none};
+    boost::optional<long long> msWaitingForMongot{boost::none};
+
     bool hasSortStage{false};  // true if the query plan involves an in-memory sort
 
     bool usedDisk{false};  // true if the given query used disk
diff --git a/src/mongo/executor/task_executor_cursor.cpp b/src/mongo/executor/task_executor_cursor.cpp
index 4d636b27be8..316561d2987 100644
--- a/src/mongo/executor/task_executor_cursor.cpp
+++ b/src/mongo/executor/task_executor_cursor.cpp
@@ -37,6 +37,8 @@
 #include "mongo/db/query/cursor_response.h"
 #include "mongo/db/query/getmore_request.h"
 #include "mongo/db/query/killcursors_request.h"
+#include "mongo/util/scopeguard.h"
+#include "mongo/util/time_support.h"
 
 namespace mongo {
 namespace executor {
@@ -132,9 +134,14 @@ void TaskExecutorCursor::_getNextBatch(OperationContext* opCtx) {
         return;
     }
 
+    auto clock = opCtx->getServiceContext()->getPreciseClockSource();
+    auto dateStart = clock->now();
     // pull out of the pipe before setting cursor id so we don't spoil this object if we're opCtx
     // interrupted
-    auto out = uassertStatusOK(_pipe.consumer.pop(opCtx));
+    auto out = _pipe.consumer.pop(opCtx);
+    auto dateEnd = clock->now();
+    _millisecondsWaiting += std::max(Milliseconds(0), dateEnd - dateStart);
+    uassertStatusOK(out);
 
     // If we had a cursor id, set it to 0 so that we don't attempt to kill the cursor if there was
     // an error
@@ -146,7 +153,7 @@ void TaskExecutorCursor::_getNextBatch(OperationContext* opCtx) {
     // is done.
     _cbHandle.reset();
 
-    auto cr = uassertStatusOK(CursorResponse::parseFromBSON(out));
+    auto cr = uassertStatusOK(CursorResponse::parseFromBSON(out.getValue()));
 
     // If this was our first batch
     if (_cursorId == -1) {
diff --git a/src/mongo/executor/task_executor_cursor.h b/src/mongo/executor/task_executor_cursor.h
index 173229419c9..2e650fcee23 100644
--- a/src/mongo/executor/task_executor_cursor.h
+++ b/src/mongo/executor/task_executor_cursor.h
@@ -39,6 +39,7 @@
 #include "mongo/db/namespace_string.h"
 #include "mongo/executor/remote_command_request.h"
 #include "mongo/executor/task_executor.h"
+#include "mongo/util/duration.h"
 #include "mongo/util/net/hostandport.h"
 #include "mongo/util/producer_consumer_queue.h"
 
@@ -88,6 +89,16 @@ public:
      */
     boost::optional<BSONObj> getNext(OperationContext* opCtx);
 
+    const CursorId getCursorId() const {
+        return _cursorId;
+    }
+
+    Milliseconds resetWaitingTime() {
+        auto toRet = _millisecondsWaiting;
+        _millisecondsWaiting = Milliseconds(0);
+        return toRet;
+    }
+
 private:
     /**
      * Runs a remote command and pipes the output back to this object
@@ -124,6 +135,9 @@ private:
     // >1 - Cursor is live on the remote
     CursorId _cursorId = -1;
 
+    // This is a sum of the time spent waiting on remote calls.
+    Milliseconds _millisecondsWaiting = Milliseconds(0);
+
     // Namespace after we resolved the initial request
     NamespaceString _ns;