Minor - P4 ------------------------
Issue Description
------------------------
Note: As this pertains to logging queries in the mongod log, I have filed this under the JIRA under the SERVER project. If this is incorrect, please move to the appropriate project.
When you run an Atlas Search query that has $search and another stage following it (such as $match), the corresponding entry that gets logged for it in the mongod logs and which gets captured in the Atlas Profiler appears to be inaccurate, and it shows:
"keysExamined": 0, "docsExamined": 0, ... "numYields": 0, "nreturned": 1,
The "keysExamined": 0 makes sense, because no MongoDB index is used for the query. However, the "docsExamined": 0 is incorrect because, AFAIK, when you run an Atlas Search query, the mongod makes an API call to the mongot which returns the objectId and metada for the matched documents back to mongod. Then mongod will then fetch those documents that match that objectId and metadata, and return them to the user. Ergo, "docsExamined" should not be 0.
Also, the "numYields", which is a counter that reports the number of times the operation has yielded to allow other operations to complete, appears to be 0 even for long running operations, which does not seem accurate.
Note: The keysExamined and docsExamined appear only in the entries logged in the mongod log and the Profiler, for the Atlas Search query. If you run an explain plan with executionStats or allPlansExecution, it will not show the aforementioned metrics.
------------------------
Reproducer
------------------------
1. I set my cluster's profiling level to capture all queries in the mongod logs.
2. Then, I ran the following query several times on the cluster:
db.hotels1234.explain("allPlansExecution").aggregate([ { "$search": { "index": "dynamic_index", "wildcard": { "path": {"wildcard": "*"}, "query": "Ful*", "allowAnalyzedField": true } } }, { $match: { "name" : "Room1" }} ])
3. The above generated the following entry in the mongod log as well as the Profiler:
2021-03-22T15:55:49.338+0000 I COMMAND [conn331648] command fts_tests.hotels1234 appName: "MongoDB Shell" command: aggregate { aggregate: "hotels1234", pipeline: [ { $search: { index: "dynamic_index", wildcard: { path: { wildcard: "*" }, query: "Ful*", allowAnalyzedField: true } } }, { $match: { name: "Room1" } } ], cursor: {}, lsid: { id: UUID("78ca0a0d-56c8-4567-bc24-8bd7453dcf17") }, $clusterTime: { clusterTime: Timestamp(1616428538, 1), signature: { hash: BinData(0, 5A04F7969C5405962D0150A48F293912C65431AD), keyId: 6910165722823917570 } }, $db: "fts_tests" } mongot: { cursorid: 0, timeWaitingMillis: 11 } keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:1 reslen:309 locks:{ ReplicationStateTransition: { acquireCount: { w: 7 } }, Global: { acquireCount: { r: 7 } }, Database: { acquireCount: { r: 7 } }, Collection: { acquireCount: { r: 7 } }, Mutex: { acquireCount: { r: 7 } } } storage:{} protocol:op_msg 15ms
4. I ran explain("executionStats") which did not have keysExamined and docsExamined:
MongoDB Enterprise > db.hotels1234.explain("executionStats").aggregate([ ... { ... "$search": { ... "index": "dynamic_index", ... "wildcard": { ... "path": {"wildcard": "*"}, ... "query": "Ful*", ... "allowAnalyzedField": true ... } ... } ... }, ... { $match: { "name" : "Room1" }} ... ]) { "stages" : [ { "$_internalSearchBetaMongotRemote" : { "mongotQuery" : { "index" : "dynamic_index", "wildcard" : { "path" : { "wildcard" : "*" }, "query" : "Ful*", "allowAnalyzedField" : true } }, "explain" : { "type" : "BooleanQuery", "args" : { "must" : [ ], "mustNot" : [ ], "should" : [ { "type" : "MultiTermQueryConstantScoreWrapper", ... { "type" : "MultiTermQueryConstantScoreWrapper", "args" : { "queries" : [ { "type" : "DefaultQuery", "args" : { "queryType" : "WildcardQuery" }, "stats" : { "context" : { "nanosElapsed" : NumberLong(0) }, "match" : { "nanosElapsed" : NumberLong(0) }, "score" : { "nanosElapsed" : NumberLong(0) } } } ] }, "stats" : { "context" : { "nanosElapsed" : NumberLong(208006), "invocationCounts" : { "createWeight" : NumberLong(1), "createScorer" : NumberLong(3) } }, "match" : { "nanosElapsed" : NumberLong(0) }, "score" : { "nanosElapsed" : NumberLong(1172), "invocationCounts" : { "score" : NumberLong(1) } } } }, ...