Skip to main content
MongoDB · lesson 10 of 10
MongoDB advanced Lesson 10 of 10

The 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

mongodb profiling performance monitoring slow-queries

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.

Frequently Asked Questions

How is the profiler different from calling explain() on a query?
explain() requires knowing which query to check in advance — it answers 'how does this specific query run.' The profiler runs continuously in the background, logging every operation slower than a configured threshold without any code changes, which is how a slow query gets found in the first place when nobody knew to suspect it.
Why did the slow operation show up as 'getmore' instead of 'find' in the profile?
A find() call that returns many documents doesn't do all its work in one round trip — the initial command opens a cursor quickly, and the actual document-by-document scanning happens across the getmore calls that follow as the client reads more of the result set. For a full collection scan returning thousands of documents, the getmore operations are where the real time is spent, which is exactly what the profiler logged here.
What's the setProfilingLevel(1, { slowms: 20 }) call actually doing?
Level 1 profiles only operations slower than the given slowms threshold (20 milliseconds here); level 0 disables profiling entirely, and level 2 logs every single operation regardless of speed — useful briefly for deep debugging, but far too much volume for anything but a short diagnostic session.
Can I search the profile log for a specific kind of problem, like queries that used no index?
Yes — system.profile is a normal (capped) collection, queryable like any other. Filtering on planSummary: "COLLSCAN" finds every logged operation that fell back to a full collection scan, which is a direct, no-explain-needed way to audit a production workload for missing indexes.
Is level-1 profiling safe to leave running in production?
It has real overhead — every profiled operation gets an extra write to system.profile, so a very high slowms threshold (only truly slow outliers) keeps the cost low, while level 2 or an aggressively low threshold on a busy server adds meaningful load. Most teams run level 1 with a threshold tuned to their actual latency budget, and reach for the more expensive settings only during active investigation.