发布于

Interconnect模块诊断方法

模块介绍

Interconnect 模块的作用是在多个节点之间交换大量数据,默认使用基于 UDP 协议的实现。新执行器针对原有的 UDP Interconnect 做了进一步优化,下文将分别介绍两者的诊断方法。


诊断方法

首先检查进程状态确认是否可能是 interconnect 相关问题

有时候会遇到 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 <pid>,也可以使用 lldb。
进入后,首先检查线程信息和主要线程的调用栈:

  • 检查线程列表的 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

老 udp interconnect 诊断流程

首先查看进程当前栈帧

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 ()

我们可以导出当前连接的所有信息,基本原理是用 lldb 或者 gdb 挂入然后调用一个内部已经写好的函数,把内部数据导出到指定的文本文件中。该函数名如下,

void dumpConnections(ChunkTransportStateEntry *pEntry, const char *fname);

因此我们调用它的时候需要提供 pEntry 和 fname。pEntry 是需要从调用栈中找出来,不同类型的 slice 找法略不同, fname 是一个字符串指定输出的文件名,例如"/home/gpadmin/dumpfile1"。

导出连接信息的命令是:

  1. gdb /usr/local/hawq/bin/postgres -p
  2. bt 检查是否为发送/接受阻塞期待的调用栈,检查上节参考样例
  3. f 2 一般可以找到使用中的 pEntry
  4. call dumpConnections(pEntry, "") 完成导出
  5. 获取其它数据辅助解读文件
  6. quit

诊断纯发送进程

通过 explain SQL 可以得到执行的 SQL 会分割成多少个 slice,处于最下层的 slice 则为纯发送的。如果在该 slice 编号的进程中看到发送等待的地方则应该找到 SendChunkUDP,gdb 中使用 f 2 找到 SendChunkUDP 后,其中应有一个变量 pEntry 保存目标发送连接的信息,pEntry 中包含多个链接信息,为了获取当前实际使用哪个索引的链接,则分两个情况,取决于 motion 的类型。

无论哪种 MOTION,在导出文件中都会看到多个连接信息,具体连接数和 QE 数一致。一般对于处于发送阻塞状态进程。

常见的 motion 类型有:

  • 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

诊断收发进程

因为 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

新 udp interconnect 诊断流程

栈帧

新 interconnect 老 interconnect 栈帧略有不同

sender 如下

* thread #1
  * frame #0: 0x00007fff693cd3d6 poll + 10
    frame #1: 0x000000010f145808 interconnect::UdpCommunicator::tryPoll(this=<unavailable>, timeout=<unavailable>)
    frame #2: 0x000000010f153bf5 interconnect::UdpSender::sendChunk(interconnect::IcConnection*) [inlined] interconnect::UdpSender::pollAcks(this=0x00007f8b82604e00, timeout=<unavailable>)
    frame #3: 0x000000010f153be8 interconnect::UdpSender::sendChunk(this=0x00007f8b82604e00, conn=0x00007f8b82615520)
    frame #4: 0x000000010f153a64 interconnect::UdpSender::send(this=0x00007f8b82604e00, recvRoute=<unavailable>, data="", len=120000) 

receiver 如下

* thread #1
  * frame #0: 0x00007fff6948a425 _pthread_cond_wait + 698
    frame #1: 0x00007fff66559623 std::__1::condition_variable::__do_timed_wait(std::__1::unique_lock<std::__1::mutex>&, std::__1::chrono::time_point<std::__1::chrono::system_clock, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000000000l> > >) + 93
    frame #2: 0x000000010f149f49 interconnect::UdpReceiver::receiveChunks(int) [inlined] std::__1::cv_status std::__1::condition_variable::wait_for<long long, std::__1::ratio<1l, 1000l> >(this=0x0000000111593108, __lk=0x000070000c08cd40, __d=<unavailable>)
    frame #3: 0x000000010f149eb7 interconnect::UdpReceiver::receiveChunks(this=0x00007ffee10be2a8, sendSlice=1)
    frame #4: 0x000000010f149955 interconnect::UdpReceiver::receive(this=0x00007ffee10be2a8, sendSlice=1, realRoute=<unavailable>, readOne=true, action=function<void (std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > &)> @ 0x000070000c08ce20)>)
    

导出连接信息

导出函数原型为:

void udpSenderDumpSlice(int32_t slice, const char* filename);

void udpSenderDumpAll(const char* filename);

void udpSenderDiagnose(const char* filename);

void udpReceiverDumpSlice(int32_t slice, const char* filename);

void udpReceiverDumpAll(const char* filename);

void udpReceiverDiagnose(const char* filename);

导出连接信息的命令是:

  1. lldb /usr/local/hawq/bin/postgres -p <pid>
  2. bt 检查是否为发送/接受阻塞期待的调用栈,检查上节参考样例
  3. 用 p 指令调用函数,如 p udpReceiverDumpAll("/home/gpadmin/dump.txt")
  4. quit,记得通过 quit 来退出 lldb

对于 udpSenderDumpSlice/udpReceiverDumpSlice 需要提供 slice id,可以 ps -ef | grep <pid>,此时 ps 的结果中中应当有 slice id,如下,slice id 为 2。

500379 16.8  0.2 1693664 543740 ?      RNsl 15:31   0:07 postgres: port 40000, gpadmin sysbenchte... [local] con238 seg7 cmd10 slice2 MPPEXEC SELECT

自动诊断

新 UDP Interconnect Debug 接口在设计时就预先考虑了一些可能的异常情况,udpSenderDiagnose/udpReceiverDiagnose 就是用于自动检测可能有异常的连接。 通常情况下,如果怀疑一个进程中 interconnect hung 了,那么应该首先调用 udpSenderDiagnose/udpReceiverDiagnose 进行检查。


receiver 导出信息格式

UDP IC 的通信方式是将要传输的数据划分为多个小的数据包进行传输,每个包有一个唯一的递增的序号,序号从 1 开始。

recvSlice[0], sendSlice[1], recvExecId[0], sendExecId[0]分别表示收的 slice id、发的 slice id、接收方的 qe id 和发送方的 qe id。

seq 表示期待收到的下一个包的序号。

extraSeq:表示被消费了的包的最大序号。

remoteHostname 和 remotePort:连接对应的 sender 的 ip 和端口

stopRequested:limit 语句会导致 receiver 在收取一定量数据后要求 sender 停止发送,stopRequested 为 true 时表示 receiver 要求 sender 停止。

stillActive:传输是否完成,hung 了的连接通常 stillActive 为 true。

pktQueue 表示收到了但还没有被消费的包的队列,pktQueueSize 指示队列中包的数量,pktQueueHead 和 pktQueueTail 指定队列起始位置和结束位置。

sessionId[0], commandId[0]
recvSlice[0], sendSlice[1]
recvExecId[0], sendExecId[0]
 flags[0x1], seq[2], extraSeq[0]
 remoteHostname[127.0.0.1], remotePort[54111]
  stopRequested[false], stillActive[true]
  pktQueueSize[1], pktQueueHead[0], pktQueueTail[1]
    currentConsumedBuff[none], currentUncompletedTupleBatch[0/0]
  pktQueue: {
    0: QID0_0_0_1_0_0, flags[0x0], seq[1], extraSeq[0]
    1: EMPTY
    2: EMPTY
    3: EMPTY
    4: EMPTY
    5: EMPTY
    6: EMPTY
    7: EMPTY
  }

通常情况下,可能的卡住的情况有:

  1. 端口不通,此时在 receiver 端无法 dump 出对应的连接,因为连接只有收到第一个包时才会建立。
  2. 网络环境非常糟糕,当丢包率较高时,传输速度会非常低,外在表现可能近似于 hung 了,此时可以多次 dump 连接查看是否 seq 是否变化。
  3. receiver 主线程卡住,如死循环等。此时 dump 的现象是 pktQueue 满。
  4. 此外还可能有 nf_conntrack:table full、机器间 mtu 对应不上、ipv6 和 ipv4 进行通信等原因。

sender 导出信息格式

因为 UDP 是不可靠传输,因此每发送一个包,都需要来自 receiver 的确认,只有收到确认后我们才能知道包已经被 receiver 正确的接收了。

unackQueue 表示发送了的,但还没有被确认的包的队列,retry 表示重传次数。

capacity:表示发送窗口大小。

sessionId[0], commandId[0], recvSlice[0], sendSlice[1], recvExecId[0], sendExecId[0]
 flags[0x0], seq[9], extraSeq[0], remoteHostname[127.0.0.1], remotePort[58158]
  stillActive[true], capacity[7], sentSeq[1], receivedAckSeq[0], consumedSeq[0], rtt[20000], dev[0], connState[0],
  unackQueue: {
    0: QID0_0_0_1_0_0, flags[0x0], len[8192], seq[1], extraSeq[0], retry[29]
  }

通常情况下,可能的 hung 的情况有:

  1. 端口不通,此时在 sender 端的 dump 结果中,能够发现包的 retry 次数非常高。
  2. 网络环境非常糟糕,当丢包率较高时,传输速度会非常低,外在表现可能近似于 hung 了,此时可以多次 dump 连接查看是否 seq 是否变化。
  3. 远程的 receiver 卡住,一直不消费包,如死循环等。此时 dump 的现象是 unackQueue 空,capacity 为 0。

diagnose 接口

diagnose 接口能够识别上述提到的几种情况。

当 udp 端口不通时,会有以下信息。

==================================================
UdpSender: 0x7f9e96e04b20 Diagnose
  Connection can't receive any ack packet after waiting for 10 minutes from receiver.
  Please check if receiver is running normally and the port
  which receiver is listening on is working.
---------------------------
sessionId[0], commandId[2], recvSlice[0], sendSlice[1], recvExecId[0], sendExecId[7]
 flags[0x0], seq[9], extraSeq[0], remoteHostname[127.0.0.1], remotePort[62875]
  stillActive[true], capacity[7], sentSeq[1], receivedAckSeq[0], consumedSeq[0], rtt[20000], dev[0], connState[0],
  unackQueue: {
    0: QID0_2_0_1_0_7, flags[0x0], len[8192], seq[1], extraSeq[0], retry[15]
  }

在 Receiver 端稍有不同,此时会报告缺少某个连接,如下,需要检测 64436 端口是否正常。

  1. 当发送 slice 只有一个 qe 执行时,此时由于 direct dispatch 的原因,其 qe 序号不能确定,需要查询 plan。
==================================================
UdpReceiver Diagnose
  Connection can't receive any packet after waiting for 0 minutes.
  Please check if sender is running normally and the port[64436]
  which receiver is listening on is working.
-------------------------------
Missing Connection: sessionId[0], commandId[0], recvSlice[0], sendSlice[1], recvExecId[0], sendExecId is unknown because of direct dispatch.
  1. 没有 direct dispatch 的情况下,会报告缺少哪些连接,然后可以查询 plan 相关信息获取对应的 QE 的信息。
==================================================
UdpReceiver Diagnose
  Connection can't receive any packet after waiting for 0 minutes.
  Please check if sender is running normally and the port[57156]
  which receiver is listening on is working.
-------------------------------
Missing Connection: sessionId[0], commandId[2], recvSlice[0], sendSlice[1], recvExecId[0], sendExecId[0]
Missing Connection: sessionId[0], commandId[2], recvSlice[0], sendSlice[1], recvExecId[0], sendExecId[6]
Missing Connection: sessionId[0], commandId[2], recvSlice[0], sendSlice[1], recvExecId[0], sendExecId[7]

当 Receiver 不消费包时,这种情况不一定是 interconnect 出现问题,需要排查远端的 QE 进程的主线程在做什么。可以通过 SSH 到对应机器,然后 lsof -i 57461 查看哪个进程在监听端口,然后用 lldb 查看该进程。

==================================================
UdpSender: 0x7fc6b5705210 Diagnose
  Connection has received enough packets, but receiver never consumed them.
  Please check if main thread of receiver is running normally.
---------------------------
sessionId[0], commandId[2], recvSlice[0], sendSlice[1], recvExecId[0], sendExecId[6]
 flags[0x0], seq[17], extraSeq[0], remoteHostname[127.0.0.1], remotePort[57461]
  stillActive[true], capacity[0], sentSeq[8], receivedAckSeq[8], consumedSeq[0], rtt[10726], dev[6111], connState[1],
  unackQueue: {
  }

当连接保持了非常久时,不一定是 hung,有可能是网络情况糟糕,传输速度非常低。可以先 quit,让进程运行一会,然后过一会再用 lldb 挂上来,查看 seq、receivedAck、consumedSeq、unackQueue 是否变化。

==================================================
UdpSender: 0x7fef5e4093b0 Diagnose
  Connection has kept for 30 minutes.
  This doesn't indicate an error. Please check the connnection seq and extraSeq after a while to make sure it is running normally.
  Seq and extraSeq are expected to be increased after a while.
---------------------------
sessionId[0], commandId[0], recvSlice[0], sendSlice[1], recvExecId[0], sendExecId[0]
 flags[0x0], seq[348091], extraSeq[0], remoteHostname[127.0.0.1], remotePort[64706]
  stillActive[true], capacity[3], sentSeq[348090], receivedAckSeq[348085], consumedSeq[348085], rtt[112], dev[100], connState[1],
  unackQueue: {
    0: QID0_0_0_1_0_0, flags[0x0], len[8192], seq[348086], extraSeq[0], retry[0]
    1: QID0_0_0_1_0_0, flags[0x0], len[8192], seq[348087], extraSeq[0], retry[0]
    2: QID0_0_0_1_0_0, flags[0x0], len[8192], seq[348088], extraSeq[0], retry[0]
    3: QID0_0_0_1_0_0, flags[0x0], len[8192], seq[348089], extraSeq[0], retry[0]
    4: QID0_0_0_1_0_0, flags[0x0], len[5916], seq[348090], extraSeq[0], retry[0]
  }

也可以进一步调用相关接口,查看网络情况。

Receiver: 由于每个进程只会启动一个 Receiver,因此可以用以下接口获取数据,

void udpReceiverStatistics(const char* filename);

输出格式如下,可以通过查看 receivedPkt 来判断收到的包的数量。当 disordered 和 duplicated 占 receivedPkt 的比例较高时,则说明网络糟糕。

UdpReceiver: receivedPkt: 386832, receivedDataPkt: 386832, receivedBadPkt: 0, disordered: 0, duplicated: 0, Data: [pktPerRecvmmsg 1.00, notRecv: 15.1%]

Sender:由于每个进程会启动多个 Sender,因此 udpSenderStatistics 会输出所有 sender 的统计信息

void udpSenderStatistics(const char* filename);
UdpSender: sentPkt: 386832, duplicate: 0, disordered: 0, retransmition: 0
receivedPkt: 344684,  receivedBadPkt: 0, receivedAck: 320973
firstPktRetransmition: 0
uselessAck: 12078, singleAck: 11633, stausQuery: 0, 
ack: [pktPerRecvmmsg 1.00, notRecv: 39.8%], data: [pktNumPerSendmmsg 2.52]

通常应该查看 retransmition、duplicate、disordered,如果这些值占 sentPkt 的比例较高,则说明网络情况糟糕。

如果想看某一个 Sender 的统计数据,则可以使用以下命令,其中 0x7fce5ef09c20 替换为要查看的 sender 的地址。UdpSender 的地址在 UdpSender 的 dump 方法输出中。

p ((interconnect::UdpSender*)0x7fce5ef09c20)->statistics("/home/gpadmin/statistics.txt")

目前默认的检测时间为 10 分钟,即 dignose 会跳过创建了不足 10 分钟或者不活跃的连接,若要修改这个时间,可以在 lldb 中调用以下接口,注意参数单位为秒。

p udpSetDiagnoseTimeout(seconds)
评论(5)
  • oushu6079 回复

    如果 tcpdump 发现 Receiver 所在机器确实收到了包,但网卡收不到包的话,可以用 dropwatch 查一下丢包位置。如果发现 inet_frag_evictor 丢包特别多,可以考虑调大 net.ipv4.ipfrag_high_thresh 和 net.ipv4.ipfrag_low_thresh 到 41943040 和 31457280

  • 亚平宁的眼泪
    亚平宁的眼泪 回复

    好贴 收藏了

  • oushu6079 回复

    有些时候需要排除网络丢包的具体原因,可以首先通过 udp 的 dump 接口拿到一条连接两端的 ip 和端口,然后用 nc 命令测试连通性。

    以新 interconnect 为例:找到 slice 最小的进程,然后 lldb 后,执行:p udpSenderDiagnose("/tmp/t.log")。会有类似以下输出

    UdpSender: 0x7f9e96e04b20 Diagnose
      Connection can't receive any ack packet after waiting for 10 minutes from receiver.
      Please check if receiver is running normally and the port
      which receiver is listening on is working.
    ---------------------------
    sessionId[0], commandId[2], recvSlice[0], sendSlice[1], recvExecId[0], sendExecId[7]
     flags[0x0], seq[9], extraSeq[0], remoteHostname[127.0.0.1], remotePort[62875]
      stillActive[true], capacity[7], sentSeq[1], receivedAckSeq[0], consumedSeq[0], rtt[20000], dev[0], connState[0],
      unackQueue: {
        0: QID0_2_0_1_0_7, flags[0x0], len[8192], seq[1], extraSeq[0], retry[15]
      }
    

    此时可以监听本地网卡,查看包是否被发送成功。首先获取发送端端口号,在 lldb 中执行 p ((interconnect::UdpSender*)0x7f9e96e04b20)->listenPort_,其中具体的地址为 udpSenderDiagnose 输出中 UdpSender 后紧接着的地址。然后 tcpdump udp port 发送端口。如果发现没有丢包则继续排查。如果丢包可以参照之后排查远端接收丢包类似的方式排查发送为什么丢包。

    如果发送端没有问题,则需要登录 remoteHostname,然后执行 tcpdump udp port remotePort,如果有输出则可以判定包已经被发送到了目标机器,可以排除交换机之类的网络问题,否则需要查看是否是网卡丢包,通过 ethtool -S 网卡 | grep rx 查看网卡丢包错误,也可以通过 ifconfig 查看是否丢包严重。

    如果 tcpdump 显示收到了数据包,接下来需要排查操作系统是否发生严重丢包,可以执行 cat /proc/net/udp 查看每个 udp socket 的丢包情况,也可以通过 cat /proc/net/snmp | grep 'Udp' 查看 udp 整体丢包情况。以 snmp 为例,可以认为 InErrors/InDatagrams 就是丢包率,如果丢包率很高,则可以认为操作系统丢包严重。

    -bash-4.2$ cat /proc/net/snmp | grep 'Udp' 
    Udp: InDatagrams NoPorts InErrors OutDatagrams RcvbufErrors SndbufErrors InCsumErrors
    Udp: 138186338994 373891009 7205817 138631292571 7205817 0 0
    

    如果知道操作系统丢包验证,可以通过 dropwatch 或者 sudo perf record -g -a -e skb:kfree_skb 获取系统丢包时刻的栈,再继续排查。

  • oushu6079 回复

    可以检查不同机器之间的 mtu,如果不一样需要改成一样。如果 udp 会出错误,可以把 udp 的包改成 1400 字节,new_ic_udp_packet_size=1400,改完需要重启。

    再不行可以把 new_interconnect_timeout_check 设置成 off,等待复现后联系研发人员排查问题。

  • oushu6079 回复

    如果网络不通,可以拿到连接两端的 ip 和 port,在接收端用 nc -lu port 监听,然后在发送端用 nc -u -p src_port dst_ip dst_port,查看是否能够通信。

test