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):

-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