[SERVER-22250] Diagnostic log messages missing debug information for query operations with execution times close to "slowms" Created: 20/Jan/16  Updated: 06/Dec/22

Status: Backlog
Project: Core Server
Component/s: Diagnostics, Querying
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: J Rassi Assignee: Backlog - Query Execution
Resolution: Unresolved Votes: 0
Labels: query-44-grooming
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
related to SERVER-17862 Unify stats reporting for log/profile... Closed
is related to SERVER-22252 Diagnostic log messages missing debug... Backlog
Assigned Teams:
Query Execution
Operating System: ALL
Participants:

 Description   

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


Generated at Thu Feb 08 03:59:50 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.