SERVER-40416 Add logging to fts document source

2 files changed, 23 insertions, 2 deletions

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;