有一天忽然收到我们 ADB PG 测试实例重启的报警, 当时上去看了下发现是实例部署个关于内存控制的参数没配置合适导致计算节点 OOM 了, 恰好当时 master 在处于恢复残留两阶段事务的关键链路, 发现无法链接 segment, 毕竟此时 segment 处于 recovery mode, 便 PANIC 退出了. 当时按照预案配置好相关参数, 理论上是需要一次重启才能使实例生效的, 但当时并未立刻重启, 而是想着等待下次实例再次 oom 导致重启时也能生效. 便不再管他了.
直到当天下午又一次收到该实例重启报警, 当时以为仍是 OOM 导致的, 便没立刻处理. 等到抽个闲空登上去细看时, 才发现情况有些不对, 这个触发重启的堆栈不太眼熟:
(gdb) bt
#0 0x00002b00f7c63625 in raise () from /lib64/libc.so.6
#1 0x00002b00f7c64e05 in abort () from /lib64/libc.so.6
#2 0x000000000088aefc in errfinish (dummy=<value optimized out>) at elog.c:716
#3 0x00000000007ca881 in ProcessInterrupts () at postgres.c:3593
#4 0x000000000091355c in CdbCheckDispatchResultInt (ds=0x7fffe1ee9820, waitMode=DISPATCH_WAIT_NONE) at cdbdisp.c:931
#5 CdbCheckDispatchResult (ds=0x7fffe1ee9820, waitMode=DISPATCH_WAIT_NONE) at cdbdisp.c:759
#6 0x0000000000914cb3 in cdbdisp_dispatchDtxProtocolCommand (dtxProtocolCommand=<value optimized out>, flags=<value optimized out>,
dtxProtocolCommandLoggingStr=0xc226f8 "Retry Distributed Commit Prepared", gid=0x2b0101d267f0 "1576092984-0070204406", gxid=70204406, errmsgbuf=0x7fffe1ee98b0,
numresults=0x7fffe1ee98cc, badGangs=0x7fffe1ee9a0f "", direct=0x7fffe1ee9a00, argument=0x0, argumentLength=0) at cdbdisp.c:1142
根据堆栈看到此时 ProcessInterrupts 在处理 ClientConnectionLost 事件, 预期是输出一条 FATAL 日志并终止当前 backend, 只不过由于某些原因, 这个 FATAL 日志被 elog 升级为 PANIC 导致 master 进入了 recovery mode 并被触发了重启. 在 ADB PG 中, elog 是会在一些条件下将 FATAL 升级为 PANIC, 比如 PG 自身会在 FATAL 日志出现在 critical section 中时将其升级为 PANIC; GP 自身也会在当 FATAL 日志出现在两阶段事务重试阶段时升级为 PANIC. 考虑到 ProcessInterrupts 一定不会在 critical section 内调用以及 PANIC 时的堆栈, 可以看到是由于此时 FATAL 出现在两阶段事务重试阶段被升级为的 PANIC. (我觉得嘛这里就不应该在两阶段事务重试链路调用 ProcessInterrupts 的, 毕竟像这里 case, 两阶段事务的重试实际上是成功了的, 只不过由于一个无关紧要的 ClientConnectionLost 导致实例 PANIC 了.
那为啥会出现 “Retry Distributed Commit Prepared” 这种场景呢? 这里先简单不严谨地介绍一下 GP 内的两阶段事务处理: 当 master 收到用户发来的 COMMIT 请求时, 便会对所有参与事务的 segment 下发 PREPARE TRANSACTION 请求, 当 segment 收到该请求并完成处理之后便会进入 DTX_CONTEXT_QE_PREPARED 状态, 表现为全局变量 DistributedTransactionContext 的值为 DTX_CONTEXT_QE_PREPARED. 当 master 收到所有 segment 成功响应之后, 便会再次对所有 segment 下发 COMMIT PREPARED 请求(见 CommitTransaction() 中的 notifyCommittedDtxTransaction() 调用), master 自身会进入 DTX_STATE_NOTIFYING_COMMIT_PREPARED 状态, 若 COMMIT PREPARE 请求未被所有 segment 成功处理, master 会进入到 DTX_STATE_RETRY_COMMIT_PREPARED 状态表明需要重试. 具体重试工作将在 EndCommand() 中的 doDtxPhase2Retry() 调用内进行. 所以回到我们这里 case, 表明此时 segment 由于某些原因未完成 COMMIT PREPARE 请求, 导致 master 进入了 DTX_STATE_RETRY_COMMIT_PREPARED 状态, 难道 segment 又 OOM 了?
继续往前翻了下 master 日志, 发现有点像 OOM.
2019-12-12 15:29:54.273937 CST|zhanyi|hidva|48326|con15897 cmd29|:-THREAD 47284570294016: Dispatcher encountered connection error on seg0 180.76.167.43:3333 pid=23333: server closed the connection unexpectedly.
找了个报错 segment 登录上去看了下它的日志, 发现与 OOM 没啥关系:
p39747 180.76.167.43(46753) zhanyi hidva 2019-12-12 09:16:01 CST XX000 conn14986 seg1 629426884408471 th47927873468736 execute FATAL: Unexpected segment distribute transaction context: 'Segment Prepared' (xact.c:3323)
这表明是 segment 在处于 DTX_CONTEXT_QE_PREPARED 状态时又一次尝试开启一个新事务导致的报错. 不太对, 正常情况下当 segment 知道自己在 DTX_CONTEXT_QE_PREPARED 状态时不应该尝试开启事务的, something was wrong. 好在这里的 FATAL 输出了一些堆栈能让我们看到此时 segment 在准备处理收到的 NOTIFY 消息, 所以准备调用 StartTransaction() 开启新事务. 等等为啥这里会涉及到 LISTEN/NOTIFY 链路??? 这里我们再简单介绍下 PG 中的 LISTEN/NOTIFY 链路:
当 PG backend 收到 LISTEN 请求之后, 会往 pg_listener 表中插入一条记录来表明本次 LISTEN. 当 PG backend 收到 NOTIFY 请求之后, 其会扫描 pg_listener 找出对应记录, 然后更新该记录的 notification 字段来, 之后该 backend 还会往 LISTEN 所在 backend 发送 SIGUSR2 信号来通知一下.
但是看了下我们这个 case 中出现 FATAL 日志的 backend 日志上下文, 并没有找到任何 LISTEN 请求的迹象, 而且 utility 模式连接 segment 之后发现 pg_listener 中记录也为空, pg_filedump 看了下 pg_listener 对应 heap file 确实没有任何记录添加过.
所以导致 segment backend FATAL 终止的原因就是: segment backend 收到了一个意外的 SIGUSR2 信号导致其在完成 PREPARE TRANSACTION 请求之后进入 idle 状态时, 在 prepare_for_client_read() 函数内调用 EnableNotifyInterrupt() 检测有无 NOTIFY 消息时发现 notifyInterruptOccurred 真的为 true, 于是开始调用 ProcessIncomingNotify() 处理这次 NOTIFY, 之后在调用 StartTransaction() 时 FATAL 终止退出! (所以我觉得这里在 prepare_for_client_read() 中当处于 DTX_CONTEXT_QE_PREPARED 状态时就不该调用 ProcessIncomingNotify 的, 推迟到后续阶段调用==
所以是哪个家伙给我们发送的 SIGUSR2 信号啊!
后续: 事实上这里我们仅是从现有日志中推测出有人给我们发送了 SIGUSR2 信号, 但并没有找到切实证据, 试着查看 bash history 发现没有 kill 记录, last 看了下登录历史更是发现事发时间没人登录过服务器… 所以
