-
Type:
Bug
-
Resolution: Unresolved
-
Priority:
Major - P3
-
None
-
Affects Version/s: None
-
Component/s: Diagnostics, Querying
-
Query Execution
-
ALL
There is a race condition in the logic that decides whether or not to gather stats information from query operations. As a result, query operations that are logged because their execution time exceeds the server's "slowms" value will be missing certain diagnostic information, if their execution time is very close to "slowms".
This is a regression that was introduced in version 2.6.0. This following list specifies the symptoms of this issue on a per-branch basis:
- 2.6.x series: "nscanned" and "nscannedObjects" fields missing from diagnostic log messages for queries
- 3.0.x series: not affected.
- 3.2.x series: "planSummary" field missing from diagnostic log messages for queries
The following script will reproduce this issue:
db.foo.drop();
db.foo.insert({});
while (true) { db.foo.find({$where: "sleep(100); return true;"}).itcount(); }
When run against a 3.2.1 mongod, the server produces log messages similar to the following. Notice the lack of the "planSummary" field in the second line.
2016-01-20T17:04:12.160-0500 I COMMAND [conn1] command test.foo command: find { find: "foo", filter: { $where: "sleep(100); return true;" } } planSummary: COLLSCAN keysExamined:0 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:124 locks:{ Global: { acquireCount: { r: 4 } }, MMAPV1Journal: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { R: 2 } } } protocol:op_command 101ms
2016-01-20T17:04:12.548-0500 I COMMAND [conn1] command test.foo command: find { find: "foo", filter: { $where: "sleep(100); return true;" } } keysExamined:0 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:124 locks:{ Global: { acquireCount: { r: 4 } }, MMAPV1Journal: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { R: 2 } } } protocol:op_command 101ms
Similarly, see the following excerpt from the server log when the script is run against a 2.6.11 mongod ("nscanned" and "nscannedObjects" are missing from the second line):
2016-01-20T17:07:35.753-0500 [conn1] query test.foo query: { $where: "sleep(100); return true;" } planSummary: COLLSCAN ntoreturn:0 ntoskip:0 nscanned:1 nscannedObjects:1 keyUpdates:0 numYields:1 locks(micros) r:200399 nreturned:1 reslen:42 101ms
2016-01-20T17:07:36.536-0500 [conn1] query test.foo query: { $where: "sleep(100); return true;" } planSummary: COLLSCAN ntoreturn:0 ntoskip:0 keyUpdates:0 numYields:0 locks(micros) r:101058 nreturned:1 reslen:42 101ms
- is related to
-
-
- Backlog
-
- related to
-
SERVER-17862 Unify stats reporting for log/profiler across CRUD operations
-
- Closed
-