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

Include query planning details on query log lines

    • Fully Compatible
    • Query F (02/01/16), Query 10 (02/22/16)

      The work completed for this ticket was to add two new fields to the slow query log lines and to the entries in the system.profile collection:

      • fromMultiPlanner indicates whether or not multiple candidate plans were evaluated before choosing a winning execution plan for the query. This flag will be false if the query plan was generated based on a plan cache entry or if there was any a single possible execution plan. It will only appear in the log or in system.profile if it has a value of true.
      • replanned indicates whether or not the CachedPlanStage replanning logic kicked in during the execution of this plan. For more details on replanning, see SERVER-15225. The flag will only appear in the log or in system.profile if it has a value of true.

      Original Description

      Currently when looking at a query log line it's impossible to tell whether or not query planning happened. This makes it hard to know if the query was slow for inherent reasons, or slow because planning occurred (and maybe many plans were tried).

      It would be great if the query log line could indicate whether or not query planning happened, and if so some basic stats about the planning stage, e.g. number of plans run, the w value of the winning (cached) plan (i.e. the number of "work"s required for the plan to win), whether or not the plan was cached (since sometimes it's not), etc.

      For example something like (spaces added for clarity only):

      Unable to find source-code formatter for language: diff. Available languages are: actionscript, ada, applescript, bash, c, c#, c++, cpp, css, erlang, go, groovy, haskell, html, java, javascript, js, json, lua, none, nyan, objc, perl, php, python, r, rainbow, ruby, scala, sh, sql, swift, visualbasic, xml, yaml
      -2015-05-06T06:02:45.723Z [conn448577] query foo.bar query: { ... } planSummary: IXSCAN { ... } cursorid:121216921046                                  ntoreturn:0 ntoskip:0 nscanned:68339 nscannedObjects:3143 keyUpdates:0 numYields:3055 locks(micros) r:5188128 nreturned:101 reslen:424024 9789ms
      +2015-05-06T06:02:45.723Z [conn448577] query foo.bar query: { ... } planSummary: IXSCAN { ... } cursorid:121216921046 nplans:3 nworks:101 planCached:1 ntoreturn:0 ntoskip:0 nscanned:68339 nscannedObjects:3143 keyUpdates:0 numYields:3055 locks(micros) r:5188128 nreturned:101 reslen:424024 9789ms
      

            Assignee:
            david.storch@mongodb.com David Storch
            Reporter:
            kevin.pulo@mongodb.com Kevin Pulo
            Votes:
            0 Vote for this issue
            Watchers:
            10 Start watching this issue

              Created:
              Updated:
              Resolved: