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

Always print planSummary if a query was involved

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor - P4
    • Resolution: Duplicate
    • Affects Version/s: 2.6.6, 2.8.0-rc5
    • Fix Version/s: None
    • Component/s: Diagnostics, Logging
    • Labels:
      None
    • Operating System:
      ALL
    • Steps To Reproduce:
      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.

      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.

        Attachments

          Issue Links

            Activity

              People

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

                Dates

                Created:
                Updated:
                Resolved: