MongoDB · lesson 10 of 10
Intermediate
6- 2 Embedding vs Referencing: A 5.9MB Document and a 50x Fetch Time
- 3 explain() Proves It: 200,000 Docs Scanned vs. a Covered Query That Touches Zero
- 4 The Aggregation Stage-Order Bug: Wrong Results, No Error
- 5 When the Aggregation Optimizer Can (and Can't) Use Your Index
- 6 Change Streams: Watching a Collection in Real Time (Replica Set Required)
- 7 Multi-Document Transactions: When One Update Isn't Enough
Advanced
3Also part of MongoDB
1The Profiler: Finding a Slow Query Without Knowing to Look for It
explain() answers 'is this specific query slow' — the profiler answers 'which of my queries are slow at all,' logging every operation over a threshold with its real execution stats, including the query plan, with no code changes needed.
By SkillByExample · Published
explain() answers “is this query slow.” The profiler answers “which of my queries are slow,”
without needing to already suspect one.
Turning it on
docker exec mongo-lesson mongosh --quiet --eval '
db = db.getSiblingDB("bookshop");
db.setProfilingLevel(1, { slowms: 20 });
'
{ was: 0, slowms: 100, slowinprogms: Long('5000'), sampleRate: 1, ok: 1 }
Level 1 logs only operations slower than slowms (here, 20ms) into a special collection,
system.profile — no application code changes, no explicit explain() call needed anywhere.
Running real traffic against it
docker exec mongo-lesson mongosh --quiet --eval '
db = db.getSiblingDB("bookshop");
db.books.find({ published_year: 2000 }).toArray().length;
'
docker exec mongo-lesson mongosh --quiet --eval '
db = db.getSiblingDB("bookshop");
db.books.find({ author: "Author 4999" }).toArray().length;
'
2666
40
One query with no index behind it (published_year, from the indexes lesson), one with an
index (author) — run as if nobody was watching for anything slow in particular.
Reading what the profiler caught
docker exec mongo-lesson mongosh --quiet --eval '
db = db.getSiblingDB("bookshop");
printjson(db.system.profile.find().sort({ts: -1}).limit(6).toArray().map(p => ({op: p.op, millis: p.millis, docsExamined: p.docsExamined, nreturned: p.nreturned, planSummary: p.planSummary})));
'
[
{ op: 'getmore', millis: 39, docsExamined: 192449, nreturned: 2565, planSummary: 'COLLSCAN' },
{ op: 'getmore', millis: 89, docsExamined: 192449, nreturned: 2565, planSummary: 'COLLSCAN' }
]
Two things worth noticing. First, only the unindexed query shows up at all — the
author-indexed lookup finished fast enough to never cross the 20ms threshold, so it left no
trace in the profile. Second, the logged operation type is getmore, not find: a query
returning thousands of documents does its real scanning work across the batched getmore
calls that follow the initial cursor open, and that’s where the 39-89ms actually went. Note
also planSummary: 'COLLSCAN' — the query plan is right there in the profile record, no
separate explain() call needed to know this one never used an index.
Auditing for missing indexes directly
docker exec mongo-lesson mongosh --quiet --eval '
db = db.getSiblingDB("bookshop");
print(db.system.profile.find({ planSummary: "COLLSCAN" }).count());
'
2
Filtering system.profile by planSummary: "COLLSCAN" finds every slow operation that fell
back to a full scan — a direct way to audit real production traffic for missing indexes,
without knowing in advance which query to check.
Turning it off
docker exec mongo-lesson mongosh --quiet --eval '
db = db.getSiblingDB("bookshop");
db.setProfilingLevel(0);
'
{ was: 1, slowms: 20, slowinprogms: Long('5000'), sampleRate: 1, ok: 1 }
was: 1 confirms the level it was at before this call — useful for scripts that want to
restore whatever setting was active after a temporary diagnostic session.
Practice
1. Check the current profiling status without changing it.
docker exec mongo-lesson mongosh --quiet --eval '
db = db.getSiblingDB("bookshop");
printjson(db.getProfilingStatus());
'
{ was: 0, slowms: 20, slowinprogms: Long('5000'), sampleRate: 1, ok: 1 }
getProfilingStatus() reads the configuration without toggling anything — the right call for
a monitoring script that needs to know the setting, not change it.
2. Find the single slowest operation ever recorded in the profile log.
docker exec mongo-lesson mongosh --quiet --eval '
db = db.getSiblingDB("bookshop");
printjson(db.system.profile.find().sort({ millis: -1 }).limit(1).toArray().map(p => ({op: p.op, millis: p.millis, planSummary: p.planSummary})));
'
[ { op: 'getmore', millis: 89, planSummary: 'COLLSCAN' } ]
Sorting by millis descending instead of ts (timestamp) surfaces the worst offender
directly, regardless of when it happened to run.
3. Count how many profiled operations used an index versus a full scan.
docker exec mongo-lesson mongosh --quiet --eval '
db = db.getSiblingDB("bookshop");
printjson(db.system.profile.aggregate([
{ $group: { _id: "$planSummary", count: { $sum: 1 } } }
]).toArray());
'
[ { _id: 'COLLSCAN', count: 2 } ]
Every single logged operation used COLLSCAN — the author-indexed query never appeared at
all, because it was too fast to cross the 20ms threshold. A busier, more varied production
workload would show a real mix of plan types here.
That closes the track. The thread through all ten lessons: MongoDB is strict about types and
honest about cost — a query never coerces "9.99" into 9.99, an unbounded array really does
grow past 5MB, an unindexed query really does scan every document, and a killed primary really
does take about as long to replace as the documentation says it should. Nothing in this track
asked you to trust a claim that wasn’t measured against a real, running deployment first.