Monitoring, Profiler & Slow Queries

explain() answers the question "how does this query run?". In a live application the first problem is different: users say the orders page is slow, and you do not yet know which query is to blame. Monitoring tools answer "what is the server doing, and which operations are slow?". Once you have found the culprit, you go back to explain() and indexes to fix it.

In this lesson you will read the slow query log, switch on the database profiler, find and stop long-running operations, put time limits on queries, and learn which numbers to watch on a dashboard. Start with freshly loaded data and use shop on a local server; a few of these commands are not allowed on Atlas Free clusters, as noted below.

What to watch

A database that "feels slow" is usually short of one resource. These are the measurements every MongoDB dashboard shows, whether it is Atlas, Compass or a tool such as Grafana:

The working set is the data and indexes that your application touches regularly. When the working set fits in memory, MongoDB is fast; when it does not, every query waits for the disk. Many "MongoDB is slow" problems are really "the indexes no longer fit in RAM" problems.

The slow query log

Every mongod writes a log, and by default it records any operation that takes longer than 100 milliseconds. Each entry is one line of JSON with the message "Slow query". Inside its attr part you find the namespace (ns), the command, planSummary (such as COLLSCAN or IXSCAN { customerId: 1 }), the keys and documents examined and the duration in milliseconds.

The log is the cheapest monitoring you have, because it is always on. On a self-managed server, look in the log file set in the configuration; on Windows the installer puts it under the MongoDB data folder. In mongosh you can read recent lines with db.adminCommand({ getLog: 'global' }). Search the log for COLLSCAN together with large docsExamined values: those are your missing indexes.

The database profiler

The profiler records operations into a special collection called system.profile in each database, so you can query them like any other data. It has three levels:

• 0: off (the default). Slow operations still go to the log.
• 1: record operations slower than slowms (100 ms unless you change it).
• 2: record every operation. Useful for a few minutes on a development machine; far too heavy for production.

Switch it to level 2 on your practice server, run a query, then read what was recorded:

db.setProfilingLevel(2)
db.orders.find({ status: 'pending' })
db.system.profile.find(
  { ns: 'shop.orders', op: 'query' },
  { _id: 0, op: 1, ns: 1, keysExamined: 1, docsExamined: 1, nreturned: 1, planSummary: 1 }
).sort({ ts: -1 }).limit(1)

{ was: 0, slowms: 100, sampleRate: 1, ok: 1 }
[
  {
    op: 'query',
    ns: 'shop.orders',
    keysExamined: 0,
    docsExamined: 12,
    nreturned: 2,
    planSummary: 'COLLSCAN'
  }
]

(The two pending orders printed by the find() are not shown.) setProfilingLevel() returns the previous settings, which is why it says was: 0; on a replica set the reply also contains cluster time fields. The profile entry shows the problem at a glance: 12 documents examined to return 2, using a collection scan. Add an index and the next entry changes:

db.orders.createIndex({ status: 1 })
db.orders.find({ status: 'pending' })
db.system.profile.find(
  { ns: 'shop.orders', op: 'query' },
  { _id: 0, op: 1, ns: 1, keysExamined: 1, docsExamined: 1, nreturned: 1, planSummary: 1 }
).sort({ ts: -1 }).limit(1)

status_1
[
  {
    op: 'query',
    ns: 'shop.orders',
    keysExamined: 2,
    docsExamined: 2,
    nreturned: 2,
    planSummary: 'IXSCAN { status: 1 }'
  }
]

When you finish, turn it off again with db.setProfilingLevel(0). In production, use level 1 with a sensible threshold, for example db.setProfilingLevel(1, { slowms: 200 }), or add sampleRate: 0.1 to record only a tenth of slow operations. Profiler settings are lost when the server restarts unless they are in the configuration file. system.profile is a small capped collection, so old entries are overwritten automatically.

Long-running operations: currentOp and killOp

Sometimes the problem is happening right now: a report started by someone in the finance team has been scanning a huge collection for ten minutes. The $currentOp stage, run on the admin database, lists operations in progress. Filter it to the long-running ones:

db.getSiblingDB('admin').aggregate([
  { $currentOp: { allUsers: true } },
  { $match: { active: true, secs_running: { $gte: 5 } } },
  { $project: { opid: 1, op: 1, ns: 1, secs_running: 1, planSummary: 1, client: 1 } }
])

Each result has an opid. If an operation is clearly harmful, stop it with db.killOp(<opid>), using the number from the output. The operation is stopped at its next safe point, not instantly, and the client that started it receives an error. Kill only operations you understand: stopping an index build or a replication process can cause more trouble than it solves. The older db.currentOp() helper returns the same information and you will see it in many runbooks.

Put a time limit on queries

Prevention is better than killing. maxTimeMS() tells the server to give up on an operation after a number of milliseconds:

db.orders.find({ customerId: 1 }).sort({ date: -1 }).maxTimeMS(2000)

If the limit is reached, the query fails with a MaxTimeMSExpired error instead of running on. Drivers accept the same option, for example { maxTimeMS: 2000 } in the Node.js driver. A search page that cannot answer in two seconds is better off showing a friendly error than tying up the server. MongoDB 8.0 also added a server-wide defaultMaxTimeMS setting for read operations, described in What's New in MongoDB 8 & 9.0.

Command-line tools: mongostat and mongotop

The MongoDB Database Tools, which you installed for Backup & Restore, include two live monitors:

mongostat --uri="mongodb://127.0.0.1:27017" 5
mongotop --uri="mongodb://127.0.0.1:27017" 5

mongostat prints one line every 5 seconds with counts of inserts, queries, updates, deletes and commands, plus connections and cache usage, a little like top for the whole server. mongotop shows, for each collection, how much time the server spent reading and writing it in that interval, which quickly reveals the "hot" collection. Both are handy during a load test or an incident.

A routine for a slow page

When a page is reported as slow, work through these steps:

1. Reproduce it and note the time.
2. Look for slow log entries or profiler entries for the collections behind that page around that time.
3. Copy the slow query and run it with explain('executionStats').
4. Compare documents examined with documents returned, and look for COLLSCAN or SORT stages.
5. Fix the index (ESR order, see Indexing Strategy in Depth), the query or the schema, and measure again.
6. Add a maxTimeMS limit if the query can ever be expensive.

Common mistakes

• Leaving the profiler at level 2. It records every operation and adds load; use level 1 or turn it off.
• Measuring on tiny data. Everything is fast on twelve documents. Test slow queries against realistic volumes.
• Killing operations blindly. Check op, ns and the client first; never kill internal or replication operations.
• Watching only CPU. A slow database is more often short of memory for the working set, or missing an index.
• No time limits. One runaway report can slow every customer; set maxTimeMS on heavy queries.

Key points

• The slow query log records operations above 100 ms by default, with plan summaries and counts.
• The profiler stores operations in system.profile: level 1 for slow ones, level 2 for all, level 0 off.
• $currentOp lists operations in progress and db.killOp(opid) stops one.
• maxTimeMS() makes a query fail instead of running too long.
• mongostat and mongotop show live server and per-collection activity; Atlas dedicated clusters add Query Profiler and Performance Advisor.
• Find the slow query first, then fix it with explain() and better indexes.

db.setProfilingLevel(1, { slowms: 0 })
db.products.find({ category: 'Audio' })
db.products.find({ price: { $lt: 1000 } })
db.products.countDocuments({ stock: 0 })
db.system.profile.find(
  { ns: 'shop.products' },
  { _id: 0, op: 1, planSummary: 1, docsExamined: 1 }
).sort({ ts: -1 })
db.setProfilingLevel(0)