Reading explain() Plans and the Database Profiler

An index only helps if the query planner chooses it, and the only way to know is to ask. explain() shows the plan MongoDB picked and, with execution statistics, how much work it did. The database profiler does the same job in reverse: it records the operations that were slow in production so you know which queries to explain. After this lesson you will be able to read a plan stage by stage, judge it from three numbers, force or verify index usage, and locate slow operations on a live server.

Verbosity Modes

| Mode | What you get | Runs the query? | |---|---|---| | explain() / "queryPlanner" | the winning plan and rejected plans | no | | explain("executionStats") | plus counters for the winning plan | yes | | explain("allPlansExecution") | plus counters for every candidate plan | yes |

executionStats is the everyday choice.

Reading the Winning Plan

A plan is a tree; each stage feeds the one above it through inputStage. Read it from the innermost stage outwards. On servers using the slot-based execution engine the tree sits under winningPlan.queryPlan.

javascript

// Without a suitable index
{ stage: "SORT", sortPattern: { createdAt: -1 },
  inputStage: { stage: "COLLSCAN", filter: { status: { $eq: "open" } } } }

// With { status: 1, createdAt: -1 }
{ stage: "FETCH", filter: { total: { $gt: 100 } },
  inputStage: { stage: "IXSCAN", indexName: "status_1_createdAt_-1",
                indexBounds: { status: ['["open", "open"]'], createdAt: ["[MaxKey, MinKey]"] } } }

| Stage | Meaning | |---|---| | COLLSCAN | read every document; fine for tiny collections, a red flag otherwise | | IXSCAN | walk an index within indexBounds | | FETCH | load full documents for the keys found | | SORT | in-memory sort (blocking, 100 MB limit) | | PROJECTION_COVERED | result built from index keys alone: no FETCH | | SORT_MERGE / OR | combine several index scans |

The Three Numbers That Matter

From executionStats, compare nReturned, totalKeysExamined and totalDocsExamined:

All three roughly equal: the index matches the query exactly.
Docs examined far larger than returned: the index is missing or not selective enough; the server fetched documents only to discard them in a FETCH filter.
Docs examined is 0: a covered query — every field in the filter, sort and projection lives in the index.
A SORT stage is present: the index order does not match the sort; revisit the ESR order.

javascript

// Covered: filter, sort and projection all inside { status: 1, createdAt: -1 }
db.orders.find({ status: "open" }, { _id: 0, status: 1, createdAt: 1 })
  .sort({ createdAt: -1 })
  .explain("executionStats").executionStats.totalDocsExamined   // 0

Steering the Planner

The planner tries candidate plans briefly, keeps the winner in the plan cache and reuses it for queries with the same shape. Sometimes you need to intervene:

javascript

db.orders.find({ status: "open" }).hint({ status: 1, createdAt: -1 })  // force an index
db.orders.find({ status: "open" }).hint({ $natural: 1 })              // force a scan
db.orders.getPlanCache().clear()                                     // after adding/dropping indexes

Treat hint() as a diagnostic tool; a plan that only works with a hint usually means the index design should change.

Finding Slow Queries: Profiler and Logs

Every mongod logs operations slower than slowms (100 ms by default) to its log file. The profiler stores the same information as documents in the capped system.profile collection of each database:

javascript

db.setProfilingLevel(1, { slowms: 50, sampleRate: 0.5 })  // level 1 = slow ops only
db.getProfilingStatus()

db.system.profile.find({ millis: { $gt: 50 } }, { op: 1, ns: 1, millis: 1, planSummary: 1, docsExamined: 1 })
  .sort({ ts: -1 }).limit(10)

planSummary is a one-line version of the plan (COLLSCAN or IXSCAN { status: 1 }), so a single query on system.profile lists every operation that scanned. Level 2 records everything and is only for short debugging sessions; set it back to 0 afterwards. For what is running right now, db.currentOp({ secs_running: { $gt: 5 } }) lists long operations and db.killOp(opid) stops one. Atlas exposes the same data in its Query Profiler and Performance Advisor.

Common Mistakes

Judging by time alone. A query that reads 2 million keys can be fast on a warm cache and terrible later; the examined counters do not lie.
Leaving profiling level 2 on in production; it adds write load to every operation.
Forgetting that explain("executionStats") runs the query, including full scans on large collections.

Key Takeaways

explain("executionStats") shows the winning plan tree and real counters; read stages from the innermost inputStage outwards.
COLLSCAN and blocking SORT stages signal a missing or badly ordered index.
Compare nReturned, totalKeysExamined and totalDocsExamined; a covered query examines zero documents.
hint() forces an index for diagnosis; clear the plan cache after changing indexes.
Profiling level 1 with slowms records slow operations in system.profile; planSummary reveals scans, and currentOp() shows what is running now.

Next lesson: The Aggregation Pipeline — transform and summarise data in stages with $match, $group, $project and $sort.