线上有个操作卡住了,怎么找到它、怎么杀掉它、杀掉之后客户端看到什么?maxTimeMS 又是怎么回事?这篇逐个验证。
找到 1 个 appName=slowfind 的进行中操作
字段: ['active', 'appName', 'client', 'clientMetadata', 'command', 'connectionId', 'currentOpTime', 'currentQueue', 'desc', 'flowControlStats', 'host', 'isFromPriorityPortConnection', 'isFromUserConnection', 'lockStats', 'locks', 'lsid', 'microsecs_running', 'ns', 'numInterruptChecks', 'numYields', 'op', 'opid', 'planSummary', 'priorityLowered', 'queryFramework', 'queryShapeHash', 'queues', 'redacted', 'secs_running', 'threaded', 'totalAdmissions', 'totalTimeQueuedMicros', 'type', 'waitingForFlowControl', 'waitingForLock', 'wasDeprioritized', 'wasLoadShed', 'wasMarkedNonDeprioritizable']
{"type": "op", "op": "query", "ns": "test.t", "active": true, "secs_running": 0, "microsecs_running": 801191, "planSummary": "COLLSCAN", "numYields": 0, "appName": "slowfind", "client": "127.0.0.1:50940", "desc": "conn11"}
command = {"find": "t", "filter": {"$where": "sleep(1000) || true"}, "limit": 1, "lsid": {"id": "b'\\xbfG\\x93\\x12\\xd5\\x1aD\\xb8\\x86TA\\x87V]\\xcaZ'"}, "$db": "test"}
不去管它,该查询总共跑了 2.6 秒后正常返回$currentOp 聚合阶段列出进行中的操作:op、ns、planSummary、microsecs_running,还有完整的 command。
找到 opid = 26625(secs_running = 0)
killOp 返回: {'info': 'attempting to kill op', 'ok': 1.0}
受害者在 killOp 之后 0.0 秒返回(不杀的话要跑约 3 秒,见上一节): code = 11601, codeName = Interrupted, errmsg = Executor error during find command: test.t :: caused by :: wasm epoch interrupt: kill pending, full killOp 用 opid 杀操作,返回 attempting to kill op;受害者很快收到 11601 Interrupted。
where_sleep:killOp 之后 0.00 秒结束; 错误 11601 Interrupted scan_sort:killOp 之后 0.00 秒结束; 错误 11601 Interrupted
$where 里的 sleep 和 $function 里的 JS 计算循环,killOp 之后都立刻结束。
maxTimeMS = 1000:1.02 秒后返回错误 code = 50 MaxTimeMSExpired Executor error during find command: test.t :: caused by :: wasm epoch interrupt: kill pend
maxTimeMS 让服务端自己到点中止,错误码是 50 MaxTimeMSExpired,不是 11601。
secs_running ≥ 1 的 query:3 个: [('worker0', 1), ('worker1', 1), ('worker2', 1)]
idleCursors: [{"type": "idleCursor", "ns": "test.t", "cursor": {"nDocsReturned": 10, "noCursorTimeout": false, "originatingCommand": {"find": "t"}}}]用 $match 按 secs_running 找长时间运行的操作;idleCursors: true 能看到空闲的游标。
{"desc": "Checkpointer", "appName": null, "op": "none", "ns": "", "active": true}
{"desc": "JournalFlusher", "appName": null, "op": "none", "ns": "", "active": true}
{"desc": "conn6", "appName": null, "op": "command", "ns": "admin.$cmd", "active": true}
{"desc": "conn8", "appName": null, "op": "command", "ns": "admin.$cmd.aggregate", "active": true}
{"desc": "conn12", "appName": "victim", "op": "command", "ns": "admin.$cmd", "active": true}
{"desc": "conn22", "appName": "worker0", "op": "command", "ns": "admin.$cmd", "active": true}
{"desc": "conn21", "appName": "worker1", "op": "command", "ns": "admin.$cmd", "active": true}
{"desc": "conn23", "appName": "worker2", "op": "command", "ns": "admin.$cmd", "active": true}
共 8 条。其中 ns = admin.$cmd.aggregate 的那条就是这次 $currentOp 自己空闲时 $currentOp 也有后台线程(Checkpointer、JournalFlusher)、连接上的命令和它自己这一条。