在 OceanBase 数据库中,当内部线程在尝试获取锁的时长超过 1 秒时,会在 observer.log 中记录类似 WARN [COMMON] low_lock (ob_latch.cpp:817) ... The Latch wait too much time ... 的告警日志。在排查加锁时间长相关的问题时可以通过该日志的 p2 字段来获取当前持有该锁的线程。
当某个线程使用 ObLatch::low_lock() 函数尝试获取锁时,若重试次数超过该锁的 max_yield_cnt_,该线程将被加入等待事件。如果等待事件的时长超过 1 秒,系统在日志中会输出类似以下格式的 WARN 日志:
observer.log.20221114121153:[2022-11-14 12:11:02.224578] WARN {COMMON] low_lock (ob_latch.cpp:817) [6672][0][XXXXXXXXXXX-XXXXXXXXXXXXXXXX-0-0] [1t=4] [dc=0] The Latch wait too much time, (dsi->get_curr_wait()=event_no:28, p1:140270962502720, p2:3221233226, p3:1, wait_begin_time:1668399060230969, wait_end_time:1668399062223798, wait_time:1992828,timeout_ms:9223372036854775, level:0, parent:0, event_id:15004, event_name:"latch: default spin rwlock wait", param1:"address", param2:"number", params:"tries",lbt=("0x£6109c5 0x4a9f6a ......")
在该日志中,event_no 与 event_name 相对应,代表当前等待事件为:oceanbase 默认自旋读写锁;p1 与 param1 相对应,为事件参数1,代表锁的地址;p2 与 param2 相对应,代表锁的 value;p3 与 param3 相对应,在当前锁等待事件中无意义。
通过利用以下命令,可以利用锁的 value--p2 来获得当前占有该锁的线程,从而搜索附近的 observer 日志,排查诊断加锁时间长相关的问题。
python -c "c= p2的值 ;print(c & ~(1 << 30 | 1 << 31))"
在如下示例中,当前持有该锁的线程号为 7754。
python -c "c= 3221233226;print(c & ~(1 << 30 | 1 << 31))"
7754
适用版本
OceanBase 数据库所有版本。