偶小梦
发布于

interconnect诊断

➢ 问题
SQL 执行挂起,进程 hang 在数据发送或者接受中

➢ 分析&&解答

  1. 检查进程状态确认是否是相关问题
    有时候会遇到 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 的数据的。
  2. 检查进程调用栈
    发现小号码 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 ()
  3. 导出 interconnect 的连接信息
    基本原理是用 lldb 或者 gdb 挂入然后调用一个内部已经写好的函数,把内部数据导出到指定的文本文件中。该函数名如下,因此我们调用它的时候需要提供 pEntry 和 fname。pEntry 是需要从调用栈中找出来,不同类型的 slice 找法略不同, fname 是一个字符串指定输出的文件名,例如"/home/gpadmin/dumpfile1"。
    void
    dumpConnections(ChunkTransportStateEntry *pEntry, const char *fname);
    导出连接信息的命令是:
  1. gdb /usr/local/hawq/bin/postgres -p
  2. bt 检查是否为发送/接受阻塞期待的调用栈,检查上节参考样例
  3. f 2 一般可以找到使用中的 pEntry
  4. call dumpConnections(pEntry, "") 完成导出
  5. 获取其它数据辅助解读文件
  6. quit
  1. 识别一个 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

评论
    test