interconnect诊断
➢ 问题
SQL 执行挂起,进程 hang 在数据发送或者接受中
➢ 分析&&解答
- 检查进程状态确认是否是相关问题
有时候会遇到 QD 运行不退出,挂住的情况,此时在上边看到除了 QD 进程外还有至少一个 QE 进程处于未退出状态,通过使用 hawq SSH 配合 ps 命令可进行检查,观察 QD 的 connection 号码,找到和其配套的 QE 进程都有哪些从而避免并行 SQL 的干扰。比如下面就是客户现场的具体进程状态,供参考:
[bigdata-w-011] gpadmin 202850 599486 0 15:30 ? 00:00:02 postgres: port 40000, llys llysdb 10.223.6.8(55393) con83087 seg6 cmd10725 slice21 MPPEXEC SELECT
[bigdata-w-011] gpadmin 202852 599486 0 15:30 ? 00:00:01 postgres: port 40000, llys llysdb 10.223.6.8(55395) con83087 seg8 idle
[bigdata-w-011] gpadmin 202855 599486 0 15:30 ? 00:00:01 postgres: port 40000, llys llysdb 10.223.6.8(55407) con83087 seg6 idle
[bigdata-w-011] gpadmin 202862 599486 0 15:30 ? 00:00:03 postgres: port 40000, llys llysdb 10.223.6.8(55429) con83087 seg7 idle
[bigdata-w-011] gpadmin 202863 599486 0 15:30 ? 00:00:03 postgres: port 40000, llys llysdb 10.223.6.8(55435) con83087 seg7 cmd10725 slice21 MPPEXEC SELECT
[bigdata-w-011] gpadmin 202864 599486 0 15:30 ? 00:00:01 postgres: port 40000, llys llysdb 10.223.6.8(55451) con83087 seg6 idle
[bigdata-w-011] gpadmin 202874 599486 0 15:30 ? 00:00:01 postgres: port 40000, llys llysdb 10.223.6.8(55469) con83087 seg7 idle
[bigdata-w-011] gpadmin 202875 599486 0 15:30 ? 00:00:01 postgres: port 40000, llys llysdb 10.223.6.8(55473) con83087 seg9 idle
[bigdata-w-011] gpadmin 202877 599486 0 15:30 ? 00:00:02 postgres: port 40000, llys llysdb 10.223.6.8(55477) con83087 seg8 cmd10725 slice21 MPPEXEC SELECT
[bigdata-w-011] gpadmin 202881 599486 0 15:30 ? 00:00:01 postgres: port 40000, llys llysdb 10.223.6.8(55481) con83087 seg6 idle
[bigdata-w-011] gpadmin 202887 599486 0 15:30 ? 00:00:03 postgres: port 40000, llys llysdb 10.223.6.8(55485) con83087 seg8 idle
[bigdata-w-011] gpadmin 202889 599486 0 15:30 ? 00:00:01 postgres: port 40000, llys llysdb 10.223.6.8(55495) con83087 seg8 idle
[bigdata-w-011] gpadmin 202893 599486 0 15:30 ? 00:00:02 postgres: port 40000, llys llysdb 10.223.6.8(55507) con83087 seg9 cmd10725 slice21 MPPEXEC SELECT
[bigdata-w-011] gpadmin 202896 599486 0 15:30 ? 00:00:01 postgres: port 40000, llys llysdb 10.223.6.8(55513) con83087 seg6 idle
[bigdata-w-011] gpadmin 202901 599486 0 15:30 ? 00:00:04 postgres: port 40000, llys llysdb 10.223.6.8(55515) con83087 seg7 cmd10725 slice5 MPPEXEC SELECT
[bigdata-w-011] gpadmin 202991 599486 0 15:30 ? 00:00:04 postgres: port 40000, llys llysdb 10.223.6.8(55891) con83087 seg7 cmd10725 slice8 MPPEXEC SELECT
[bigdata-w-011] gpadmin 202995 599486 0 15:30 ? 00:00:04 postgres: port 40000, llys llysdb 10.223.6.8(55911) con83087 seg7 cmd10725 slice1 MPPEXEC SELECT
其中特别注意 cmdid 的匹配问题,如果 QD 端 SQL 运行是挂住的情况,QD 的 cmdid 在进程列表的显示是小于 QE 进程中 cmdid 的,差值为 1. 所以使用相同的连接号码比较合适有效,例如上例中的 con83087。
上例中,通常最后的 slice 进程需要最后退出,所以大量的 slice21 进程残留,首先需要检查残留的小号码 slice 进程号的进程,如本例中 slice1 slice5 的是需要特别研究和作为入手点的,因为大号码 slice 号的进程是要消费小号码 slice 号进程的数据输出。并且这种残留可能发生在多个节点上,不一定只在一个节点上,所以需要到所有节点检查进程。
其中特别注意 不同 slice 号码进程组直接不是简单的递增消费关系,即不是 slice5 只消费 slice4 的数据,不是 slice21 只消费 slice20 的数据,这个需要 explain SQL 之后对照检查 slice 间的依赖关系确认,如本例中,slice21 事实上是直接消费 slice1 的数据的。 - 检查进程调用栈
发现小号码 slice 号残留的 QE 进程后,使用 gdb 或者 lldb 可以挂载进目标进程,一般执行方式:
gdb /usr/local/hawq/bin/postgres -p
进入后,首先检查线程信息和主要线程的调用栈:
● 检查线程列表的 gdb 命令为 info threads, lldb 命令为 thread list。
● 选择某个线程作为检查对象的 gdb 命令为 thread , lldb 命令为 thread select 。
● 确认了需要观察的线程后,执行 bt 命令,打开调用栈,gdb 和 lldb 命令一样。如下例为调用栈的样子。
● 特别注意:退出 gdb 或者 lldb 挂载 用命令 quit,而不要简单的杀进程或者不退出,这样会导致后续进程运行的各种问题。
如果需要更详细 gdb 或者 lldb 命令 参照该链接 https://lldb.llvm.org/lldb-gdb.html
Thread 1 (Thread 0x7fcc9d38fdc0 (LWP 414876)):
#0 0x00007fcc99704a3d in poll () from /lib64/libc.so.6
#1 0x00000000008b0174 in pollAcks ()
#2 0x00000000008af0cf in SendChunkUDP ()
#3 0x00000000008a32ae in SendTupleChunkToAMS ()
#4 0x00000000008a04b3 in SendTuple ()
#5 0x0000000000655df3 in ExecMotion ()
#6 0x0000000000633ce8 in ExecProcNode ()
#7 0x000000000062e20f in ExecutePlan ()
#8 0x000000000062ddee in ExecutorRun ()
#9 0x000000000076505a in PortalRun ()
#10 0x00000000007606f3 in PostgresMain ()
#11 0x000000000071cac4 in ServerLoop ()
#12 0x0000000000719a85 in PostmasterMain ()
#13 0x000000000068d5a9 in main ()
对于 postgres 进程,我们几乎首先关注和发现问题都要从有 PostmasterMain()的线程看起,如上例。调用栈的概念就好比函数 PostmasterMain 调用 ServerLoop(), ServerLoop()再调用 PostgreMain(), 依此类推,知道#0 的位置表示当前暂停的位置。注意我们用 gdb 或者 lldb 挂载进去之后进程会自动暂停运行,我们检查调用栈等一系列操作都是出于进程暂停运行的状态。退出 gdb 或者 lldb 后,进程会继续正常运行。
回到本话题的检测,在客户使用老执行器 interconnect 时,我们发现进程在等待发送完成的话,一定可以从调用栈中发现:SendChunkUDP() 它在调用 pollAcks();如果进程在等待接受,一定可以欧诺个调用栈中发现 receiveChunksUDP()。上例是典型的发送 hang,下面给出接受 hang 的栈例子。
Thread 1 (Thread 0x7f470ea0edc0 (LWP 343797)):
#0 0x00007f470b523cf2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00000000008afbdf in receiveChunksUDP ()
#2 0x00000000008ae653 in RecvTupleChunkFromAnyUDP ()
#3 0x00000000008a07c0 in RecvTupleFrom ()
#4 0x0000000000655f6e in ExecMotion ()
#5 0x0000000000633ce8 in ExecProcNode ()
#6 0x000000000062e20f in ExecutePlan ()
#7 0x000000000062ddee in ExecutorRun ()
#8 0x000000000076505a in PortalRun ()
#9 0x0000000000761c4d in exec_simple_query ()
#10 0x000000000075e5be in PostgresMain ()
#11 0x000000000071cac4 in ServerLoop ()
#12 0x0000000000719a85 in PostmasterMain ()
#13 0x000000000068d5a9 in main () - 导出 interconnect 的连接信息
基本原理是用 lldb 或者 gdb 挂入然后调用一个内部已经写好的函数,把内部数据导出到指定的文本文件中。该函数名如下,因此我们调用它的时候需要提供 pEntry 和 fname。pEntry 是需要从调用栈中找出来,不同类型的 slice 找法略不同, fname 是一个字符串指定输出的文件名,例如"/home/gpadmin/dumpfile1"。
void
dumpConnections(ChunkTransportStateEntry *pEntry, const char *fname);
导出连接信息的命令是:
- gdb /usr/local/hawq/bin/postgres -p
- bt 检查是否为发送/接受阻塞期待的调用栈,检查上节参考样例
- f 2 一般可以找到使用中的 pEntry
- call dumpConnections(pEntry, "") 完成导出
- 获取其它数据辅助解读文件
- quit
- 识别一个 slice 进程是纯发送进程
通过 explain SQL 可以得到执行的 SQL 会分割成多少个 slice,处于最下层的 slice 则为纯发送的。如果在该 slice 编号的进程中看到发送等待的地方则应该找到 SendChunkUDP,gdb 中使用 f 2 找到 SendChunkUDP 后,其中应有一个变量 pEntry 保存目标发送连接的信息,pEntry 中包含多个链接信息,为了获取当前实际使用哪个索引的链接,则分两个情况,取决于 motion 的类型
无论哪种 MOTION,在导出文件中都会看到多个连接信息,具体连接数和 QE 数一致。一般对于处于发送阻塞状态进程,
● BROADCAST MOTION, 则需要 gdb 中使用 f 3, 然后 p index 找到具体索引号
● REDISTRIBUTION MOTION, 则需要 gdb 中使用 f 4, 然后 p targetRoute 找到具体索引号
一个发送连接导出信息可能如下,其中
● 第一行给出连接总数,本例中一共 27 个连接,因为有 27 个 QE。
● 然后根据获得的连接索引号,去查看相应信息,例如如果得到的号码为 1 则应该检查 conns[1]。
● 从连接信息中可清楚获得连接对端进程号,对端地址,如下例中 conns[0]中对端进程号为 673540,对端地址 10.223.6.1:33190
● 从连接信息中可获得本地发送缓冲区是否还有可用的空间,下例中 conns[0]中 capacity=4 表示还有,如果 capacity=0 则表示没有,一般没有 capacity 是发送阻塞的表面原因。
● 查看消息基于序列号的发送和消费进展,如下例 conns[0]中 sentSeq=8 receivedAckSeq=8 consumedSeq=8 表示已经发了 8 个,收到了 8 个的 ack 消息对端已经处理了 8 个。
● sndQueue List 在不空的情况下表示没有发送到对端且没有被消费的消息,下例中 conns[1]包含了 4 个发送成功,但还没被对端消费的包。
● unackQueue List 不空则表示有发过去包但没收到 ack 的情况。
Entry connections: conn num 27
==================================
conns[0] motNodeId=4: remoteContentId=0 pid=673540 sockfd=-1 remote=10.223.6.1:33190 local= capacity=4 sentSeq=8 receivedAckSeq=8 consumedSeq=8 rtt=7010 dev=8458 deadlockCheckBeginTime=20108339420276 route=0 msgSize=428 msgPos=(nil) recvBytes=0 tupleCount=1 waitEOS=0 stillActive=1 stopRequested=0 state=6
conn_info [DATA: seq 9 extraSeq 0]: motNodeId 4, crc 0 len 8188 srcContentId 26 dstDesContentId 0 srcPid 479615 dstPid 673540 srcListenerPort 31505 dstListernerPort 33190 sendSliceIndex 4 recvSliceIndex 21 sessionId 5199 icId 1 flags 0
sndQueue List Length 0
unackQueue List Length 0
conns[1] motNodeId=4: remoteContentId=1 pid=673545 sockfd=-1 remote=10.223.6.1:12331 local= capacity=0 sentSeq=4 receivedAckSeq=4 consumedSeq=0 rtt=11819 dev=9348 deadlockCheckBeginTime=20108339420048 route=1 msgSize=428 msgPos=(nil) recvBytes=0 tupleCount=1 waitEOS=0 stillActive=1 stopRequested=0 state=6
conn_info [DATA: seq 9 extraSeq 0]: motNodeId 4, crc 0 len 8188 srcContentId 26 dstDesContentId 1 srcPid 479615 dstPid 673545 srcListenerPort 31505 dstListernerPort 12331 sendSliceIndex 4 recvSliceIndex 21 sessionId 5199 icId 1 flags 0
sndQueue List Length 4
Node 0, linkptr 0x352aca0 Packet Content [DATA: seq 5 extraSeq 0]: motNodeId 4, crc 0 len 8052 srcContentId 26 dstDesContentId 1 srcPid 479615 dstPid 673545 srcListenerPort 31505 dstListernerPort 12331 sendSliceIndex 4 recvSliceIndex 21 sessionId 5199 icId 1 flags 0
Node 1, linkptr 0x3930c70 Packet Content [DATA: seq 6 extraSeq 0]: motNodeId 4, crc 0 len 8100 srcContentId 26 dstDesContentId 1 srcPid 479615 dstPid 673545 srcListenerPort 31505 dstListernerPort 12331 sendSliceIndex 4 recvSliceIndex 21 sessionId 5199 icId 1 flags 0
Node 2, linkptr 0x3536f40 Packet Content [DATA: seq 7 extraSeq 0]: motNodeId 4, crc 0 len 8140 srcContentId 26 dstDesContentId 1 srcPid 479615 dstPid 673545 srcListenerPort 31505 dstListernerPort 12331 sendSliceIndex 4 recvSliceIndex 21 sessionId 5199 icId 1 flags 0
Node 3, linkptr 0x354b3a0 Packet Content [DATA: seq 8 extraSeq 0]: motNodeId 4, crc 0 len 8188 srcContentId 26 dstDesContentId 1 srcPid 479615 dstPid 673545 srcListenerPort 31505 dstListernerPort 12331 sendSliceIndex 4 recvSliceIndex 21 sessionId 5199 icId 1 flags 0
5. 识别一个 slice 进程是收发进程
因为 QE 一定向 QD 汇总数据,所以 QE 一定是一个发送进程,是否有收数据能力,要看计划中是否有向下的儿子 slice,有就一定是有收的需要。
对于检查接收连接的进程,调用 dumpConnections 前需要执行 p ic_control_info.isSender=0 触发导出接收数据。其它过程与上述方法没区别,一般接收数据是从连接中任意一个有数据就可以处理,所以不需要检查 targetRoute 等。
一个例子如下,其中
● 第一行给出连接总数,本例中一共 27 个连接,因为有 27 个 QE。
● 从连接信息中可清楚获得连接对端进程号,对端地址,如下例中 conns[0]中对端进程号为 673564,检查 ps 可以找到对端进程在哪里
● 从连接信息中可获得本地接收缓冲区是否还有待消费的数据,下例中没有带消费数据,如果没有 则接收数据的进程在阻塞是有理由的,如果有待消费的数据,则原理上不应该产生接收阻塞。
Entry connections: conn num 27
conns[0] motNodeId=13: remoteContentId=0 pid=673564 sockfd=-1 remote= local= capacity=0 sentSeq=0 receivedAckSeq=0 consumedSeq=0 rtt=0 dev=0 deadlockCheckBeginTime=0 route=0 msgSize=0 msgPos=0x7fbbb02cff30 recvBytes=0 tupleCount=0 waitEOS=0 stillActive=0 stopRequested=0 state=0
conn_info [ACK: seq 2 extraSeq 1]: motNodeId 13, crc 0 len 0 srcContentId 0 dstDesContentId 14 srcPid 673564 dstPid 239741 srcListenerPort 38422 dstListernerPort 26501 sendSliceIndex 13 recvSliceIndex 21 sessionId 5199 icId 1 flags 9
pkt_q_size=0 pkt_q_head=1 pkt_q_tail=1 pkt_q=0x3217318
conns[1] motNodeId=13: remoteContentId=0 pid=673569 sockfd=-1 remote= local= capacity=0 sentSeq=0 receivedAckSeq=0 consumedSeq=0 rtt=0 dev=0 deadlockCheckBeginTime=0 route=1 msgSize=0 msgPos=0x7fbbb02dbf90 recvBytes=0 tupleCount=0 waitEOS=0 stillActive=0 stopRequested=0 state=0
conn_info [ACK: seq 2 extraSeq 1]: motNodeId 13, crc 0 len 0 srcContentId 1 dstDesContentId 14 srcPid 673569 dstPid 239741 srcListenerPort 43855 dstListernerPort 26501 sendSliceIndex 13 recvSliceIndex 21 sessionId 5199 icId 1 flags 9
pkt_q_size=0 pkt_q_head=1 pkt_q_tail=1 pkt_q=0x3217348