Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-16931

Always print planSummary if a query was involved

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Minor - P4 Minor - P4
    • None
    • Affects Version/s: 2.6.6, 2.8.0-rc5
    • Component/s: Diagnostics, Logging
    • Labels:
      None
    • ALL
    • Hide

      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.

      Show
      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.

      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.

            Assignee:
            matt.kangas Matt Kangas
            Reporter:
            victor.hooi Victor Hooi
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: