bigywater.tech
MongoDB · 82

currentOp 与 killOp

线上有个操作卡住了,怎么找到它、怎么杀掉它、杀掉之后客户端看到什么?maxTimeMS 又是怎么回事?这篇逐个验证。

11601
killOp 之后客户端收到的错误码(Interrupted),约 0.0 秒返回
50
maxTimeMS 到期的错误码 MaxTimeMSExpired,1.02 秒后返回
2.6 秒
不杀的话这条 $where 查询的总耗时

$currentOp

实测 · 本机执行输出
  找到 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。

killOp

实测 · 本机执行输出
  找到 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

实测 · 本机执行输出
  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)、连接上的命令和它自己这一条。

分步演示

currentOp 与 killOp
本步的对象

    本文用到的工具与边界

    • 本机 macOS 27 arm64 / MongoDB 9.0.2(Homebrew 的 mongod、mongos)/ mongosh 2.12.0 / pymongo 4.18.3;每个实验在临时目录里起全新的 mongod(独立 dbpath,端口 9900 以上,只监听 127.0.0.1,WiredTiger 缓存 0.25 GB),需要副本集或分片集群时在本机起多个进程;命令输出来自真实的 mongosh,批量写入、计时与多线程用 pymongo;计时用 time.perf_counter,数字每次运行会有小幅抖动,ObjectId、时间戳等每次运行都不同。单机 mongod,20 万个文档的集合;用 $where 的 sleep(1000) 和 $function 的 JS 循环造“慢操作”
    • 没有验证:killOp 对正在等锁、正在写盘(checkpoint)、正在提交事务的操作;killOp 对分片集群(mongos 上的 opid 格式 shard:opid);currentOp 的 idleConnections/idleSessions 选项;权限(inprog、killop)要求;killOp 对 getMore 与游标的行为;killSessions 与 killAllSessions;JS 引擎是 wasm 的细节只从错误信息里看到了 "wasm epoch interrupt"
    京ICP备2026067502号-1京公网安备11010502063487号