[SERVER-16931] Always print planSummary if a query was involved Created: 20/Jan/15  Updated: 25/Jun/15  Resolved: 20/Jan/15

Status: Closed
Project: Core Server
Component/s: Diagnostics, Logging
Affects Version/s: 2.6.6, 2.8.0-rc5
Fix Version/s: None

Type: Bug Priority: Minor - P4
Reporter: Victor Hooi Assignee: Matt Kangas
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-16847 Diagnostic log output for all query c... Closed
Operating System: ALL
Steps To Reproduce:

1. Perform a remove operation that takes longer than 100ms to execute (or set logLevel: 1).
2. Open up the logfile, and look for the recorded event. The planSummary is not printed.

Participants:

 Description   

Loglines for a find query will print their planSummary, which is very useful for debugging performance/index issues.

However, it would appear that other operations that involve a query (e.g. remove, update, upsert) don't seem to print a planSummary. For example (MongoDB 2.6.6):

2015-01-14T13:11:07.647-0900 [conn201097] remove foo.bar query: { Timestamp: { $gte: new Date(-62135596800000), $lt: new Date(1421259150000) } } ndeleted:366 keyUpdates:0 numYields:2 locks(micros) w:65471 266ms

I have also tested this in MongoDB 2.8.0-rc5. Find query does have planSummary:

2015-01-20T12:41:11.894+1100 I QUERY    [conn3] query cats.mycats query: { name: "Ernie" } planSummary: IXSCAN { name: 1.0 } ntoreturn:0 ntoskip:0 nscanned:1 nscannedObjects:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:83 7ms

Other types of queries do not:

2015-01-20T12:41:43.638+1100 I WRITE    [conn3] update cats.mycats query: { name: "Ernie" } update: { name: "Ernie", traits: [ "cute" ], age: 2.0 } nscanned:1 nscannedObjects:1 nMatched:1 nModified:1 keyUpdates:0 writeConflicts:0 numYields:0 2ms
2015-01-20T12:41:43.639+1100 I COMMAND  [conn3] command cats.$cmd command: update { update: "mycats", updates: [ { q: { name: "Ernie" }, u: { name: "Ernie", traits: [ "cute" ], age: 2.0 }, multi: false, upsert: false } ], ordered: true } keyUpdates:0 writeConflicts:0 numYields:0 reslen:55 3ms

2015-01-20T12:41:56.118+1100 I WRITE    [conn3] remove cats.mycats query: { name: "Stan" } ndeleted:1 keyUpdates:0 writeConflicts:0 numYields:0 1ms
2015-01-20T12:41:56.118+1100 I COMMAND  [conn3] command cats.$cmd command: delete { delete: "mycats", deletes: [ { q: { name: "Stan" }, limit: 0.0 } ], ordered: true } keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 3ms

It would be good if a planSummary could always be printed when a query is involved.



 Comments   
Comment by Ramon Fernandez Marina [ 20/Jan/15 ]

Dup of SERVER-16847.

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