[SERVER-18468] Include query planning details on query log lines Created: 14/May/15  Updated: 15/May/18  Resolved: 02/Feb/16

Status: Closed
Project: Core Server
Component/s: Diagnostics, Querying
Affects Version/s: None
Fix Version/s: 3.2.5, 3.3.2

Type: Improvement Priority: Major - P3
Reporter: Kevin Pulo Assignee: David Storch
Resolution: Done Votes: 0
Labels: code-only
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Documented
is documented by DOCS-7076 Document new log/profiler flags "from... Closed
Related
related to SERVER-18466 Log when and why a query shape begins... Closed
Backwards Compatibility: Fully Compatible
Backport Completed:
Sprint: Query F (02/01/16), Query 10 (02/22/16)
Participants:

 Description   

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



 Comments   
Comment by Githook User [ 18/Mar/16 ]

Author:

{u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'}

Message: SERVER-18468 add 'fromMultiPlanner' and 'replanned' flags to slow command logs

(cherry picked from commit be9dbd36a1dc86249601252b37d00b046f4a6629)
Branch: v3.2
https://github.com/mongodb/mongo/commit/9c5bca6f5952f102c738a3bb14c03d0e82e9ca54

Comment by Githook User [ 02/Feb/16 ]

Author:

{u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'}

Message: SERVER-18468 add 'fromMultiPlanner' and 'replanned' flags to slow command logs
Branch: master
https://github.com/mongodb/mongo/commit/be9dbd36a1dc86249601252b37d00b046f4a6629

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