Mongo maxTimeMS doens't kill query immediately

Question

• In my understanding maxTimeMS should kill the query immediately (+- 2,3 seconds) when query has gone over it's allotted time. However mongo is not killing the query immediately and taking too much time.

• Following output of currentOp() can be seen to observe this

{
    "inprog" : [
        {
            "opid" : 176078308,
            "active" : true,
            "secs_running" : 105,
            "op" : "query",
            "ns" : "xxx",
            "query" : {
                "aggregate" : "tweets",
                "pipeline" : [
                    {
                        "$match" : {
                            "gTs" : {
                                "$lte" : ISODate("2014-07-25T22:00:00Z"),
                                "$gte" : ISODate("2014-07-20T21:00:00Z")
                            },
                            "RE_H" : {
                                "$in" : [
                                    NumberLong("884327843395156951")
                                ]
                            }
                        }
                    },
                    {
                        "$match" : {
                            "$and" : [
                                {
                                    "l" : {
                                        "$in" : [
                                            "bandra",
                                            "mumbai",
                                            "thane",
                                            "bombay",
                                            "mahim"
                                        ]
                                    }
                                },
                                {
                                    "ts" : {
                                        "$lte" : ISODate("2014-07-25T21:16:00Z"),
                                        "$gte" : ISODate("2014-07-20T21:16:00Z")
                                    }
                                }
                            ]
                        }
                    },
                    {
                        "$project" : {
                            "!" : 1,
                            "s" : 1,
                            "nR" : 1,
                            "ts" : 1
                        }
                    }
                ],
                "cursor" : {
                    
                },
                "maxTimeMS" : 60000
            },
            "client" : "xxx.xxx.xxx.xxx",
            "desc" : "conn56556",
            "threadId" : "0x7f96e1cf6700",
            "connectionId" : 56556,
            "waitingForLock" : false,
            "numYields" : 4111,
            "lockStats" : {
                "timeLockedMicros" : {
                    "r" : NumberLong(16472467),
                    "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                    "r" : NumberLong(106194),
                    "w" : NumberLong(0)
                }
            }
        }
    ]
}

• This query has maxTimeMS as 60 seconds (60,000 ms) and it goes on for 105 seconds. In my opinion this is ridiculous. Mongo should not take more than 2, 3 seconds over 60 seconds to kill it.

• Can someone confirm if this is the expected behavior from Mongo?

Answer 1

Yes, this can be expected behavior. The two times being measured are somewhat different, secs_running is total elapsed time to run while maxTimeMS is actual running time:

currentOp.secs_running

The duration of the operation in seconds. MongoDB calculates this value by subtracting the current time from the start time of the operation.

http://docs.mongodb.org/manual/reference/method/db.currentOp/

cursor.maxTimeMS() Definition

New in version 2.6.

cursor.maxTimeMS()

Specifies a cumulative time limit in milliseconds for processing operations on a cursor.

and

A cursor’s idle time does not contribute towards its processing time.

http://docs.mongodb.org/manual/reference/method/cursor.maxTimeMS/#cursor.maxTimeMS

You can have other processes running at the same time, so in an extreme case with many heavy queries/updates going secs_running could be much larger than the desired maxTimeMS. In your case numYields of 4111 indicates it yielded processing 4111 times, during which elapsed time increased but processing time did not.