The slow query workflow: profiler, logs, explain, fix

conceptThe concept

1. Find: slow query log lines (operations above slowms, default 100 ms), the database profiler (system.profile), db.currentOp() for what is running now, and monitoring tools (mongostat, FTDC charts).
2. Prioritise: rank query shapes by total time (count x average), not by the single slowest execution. A 20 ms query run 50,000 times a minute matters more than a 5 s report run nightly.
3. Diagnose: planSummary (COLLSCAN? which index?), keysExamined / docsExamined versus nreturned, hasSortStage, planningTimeMicros, lock and storage waits. Reproduce with explain("executionStats").
4. Fix: add or reorder an index (ESR), change the query (projection, avoid unanchored regex, avoid $ne), change the schema (computed/subset), or move the workload (secondary, analytics node).
5. Verify: explain again, watch latency percentiles, check write impact of new indexes, add maxTimeMS to protect the system.

whyWhy it matters

Performance work without a process turns into guessing. This loop is what interviewers want to hear for "the application is slow, what do you do?", and it is what keeps production stable.

Use caseReal-world scenario

CPU on the primary jumps to 90% after a release. The slow log shows thousands of find on orders with planSummary: COLLSCAN and docsExamined: 5000 for nreturned: 3, filtered on payment.status and sorted by createdAt. A new index { "payment.status": 1, createdAt: -1 } built during low traffic brings CPU back to 15%.

Try itExamples

Run and edit these in the interactive lesson.

db.setProfilingLevel(1, { slowms: 5 })
db.orders.find({ "payment.status": "awaiting" }).sort({ createdAt: -1 }).limit(10).toArray().length
db.orders.find({ "shipping.city": "Pune", total: { $gt: 1000 } }).toArray().length
db.system.profile.find({}, { op: 1, ns: 1, command: 1, planSummary: 1, keysExamined: 1, docsExamined: 1, nreturned: 1, millis: 1 }).sort({ ts: -1 }).limit(2)

db.system.profile.aggregate([
  { $group: { _id: { ns: "$ns", plan: "$planSummary" }, count: { $sum: 1 }, totalMs: { $sum: "$millis" }, avgDocs: { $avg: "$docsExamined" } } },
  { $sort: { totalMs: -1 } }
])

db.orders.find({ "payment.status": "awaiting" }).sort({ createdAt: -1 }).limit(10).explain("executionStats")
db.orders.createIndex({ "payment.status": 1, createdAt: -1 })
db.orders.find({ "payment.status": "awaiting" }).sort({ createdAt: -1 }).limit(10).explain("executionStats")

db.orders.find({ "shipping.city": "Pune" }).maxTimeMS(2000).limit(3).toArray().length
db.currentOp({ active: true, secs_running: { $gt: 5 } })
db.setProfilingLevel(0)

internalsUnder the hood

The profiler writes to a capped collection system.profile on each node (level 1: slow ops only, level 2: everything; level 2 is expensive). Slow operations are also logged as JSON lines with attr.queryHash/planCacheKey, so you can aggregate logs by shape. On Atlas (7.1+), $queryStats exposes aggregated query statistics per shape; it is not a self-managed feature, so on your own clusters you get the same view from the slow-query log grouped by queryHash, or from PMM Query Analytics.

Avoid / preferDo this, not that

db.setProfilingLevel(2)   // and leave it on

db.setProfilingLevel(1, { slowms: 100, sampleRate: 0.5 })

db.system.profile.find().sort({ millis: -1 }).limit(1)

db.system.profile.aggregate([
  { $group: { _id: { ns: "$ns", plan: "$planSummary" }, n: { $sum: 1 }, totalMs: { $sum: "$millis" } } },
  { $sort: { totalMs: -1 } }, { $limit: 5 }
])

PitfallsCommon mistakes

• Leaving profiler level 2 on in production.
• Optimizing the slowest single query instead of the biggest total consumer.
• Adding an index for every slow query without checking existing indexes that could be extended (prefix reuse).
• Not testing index builds and their write overhead on a production-like dataset.
• Fixing a query on the primary while forgetting that secondaries serve reads with different plan caches and index usage counters.

LimitsWhen not to use it

The profiler is per database and per node, and writes to the node it profiles. On a busy production system rely on the slow query log and a tool that aggregates it (PMM Query Analytics, for example) rather than leaving the profiler on.

SecuritySecurity notes

Profiler entries and slow-query log lines include query filters with their literal values, so they can contain personal data. Restrict who can read system.profile and the log files, and consider log redaction where available.

ChallengeTry it yourself

db.setProfilingLevel(1, { slowms: 0 })
db.orders.find({ status: "paid" }).toArray().length
db.products.find({ category: "books" }).toArray().length
db.system.profile.aggregate([
  { $group: { _id: { ns: "$ns", plan: "$planSummary" }, ops: { $sum: 1 }, docsExamined: { $sum: "$docsExamined" }, returned: { $sum: "$nreturned" } } },
  { $sort: { docsExamined: -1 } }
])

InterviewQuestions you should be able to answer

QuizCheck your understanding

4 questions with instant feedback in the interactive lesson; a wrong answer goes into your review deck.