How to find queries that timed out in MongoDB?

Question

Is it possible to find queries in the system.profile-Collection of a MongoDB-database that did not finish due to a timeout?

I found some queries that ran longer than the time specified in $maxTimeMS.

db.coll.find(
  { millis: {$gt: 1300}, "command.maxTimeMS": NumberLong(1300) },
  {millis: 1}
).sort(
  {millis: -1}
)

But they only ran a couple of milliseconds longer, and did not have a field error or timeout. Are there fields that indicate a timeout?

Answer 1

On a pretty large dataset I tested a query that times out after 10 seconds:

db.collection.find({"foo": "bar"}).maxTimeMS(10000)

(In my case the collection has > 100 GB of data and no index on the field foo). I searched for the query using:

db.system.profile.find({"query.query" : { "foo" : "bar" }}).limit(5).sort({ts: -1}).pretty()

and found that the fields exception and exceptionCode are filled:

"exception" : "operation exceeded time limit",
"exceptionCode" : 50,

So searching for the field exception should give you the desired result:

db.system.profile.find({ "exception" : { "$exists" : 1 } }).limit(5).sort({ts: -1}).pretty()

And if you explicitly look for queries that timed out, try:

db.system.profile.find( {"exceptionCode": 50} ).sort( {ts: -1} ).pretty()

Answer 2

MongoDB targets operations for termination if the associated cursor exceeds its allotted time limit(maxTimeMS). I believe the few millis more come from two things.

1) There should be an internal process that checks periodically so you will get the check interval overhead (for example every 1ms)

2) MongoDB terminates operations that exceed their allotted time limit, using the same mechanism as db.killOp(). MongoDB only terminates an operation at one of its designated interrupt points. To reach the interrupt point it might take few millis.