SLOW READPROCESSOR；ERROR SLOW BLOCKRECEIVER错误日志分析

一、现象

1、flink job log

2022-05-17 02:48:25,688 INFO org.apache.hadoop.hdfs.DataStreamer                         [] - Slow ReadProcessor read fields for block BP-1487117196-110.246.92.211-1641695608175:blk_1305548153_236768430 took 44369ms (threshold=30000ms); ack: seqno: 2041 reply: SUCCESS reply: SUCCESS reply: SUCCESS downstreamAckTimeNanos: 44349240826 flag: 0 flag: 0 flag: 0, targets: [DatanodeInfoWithStorage[110.246.92.130:9866,DS-3ee15ef0-7de4-49ed-b031-1a2769cd9a97,DISK], DatanodeInfoWithStorage[110.246.92.217:9866,DS-382900d8-67b2-4aa0-8a66-e1ea435aaba4,DISK], DatanodeInfoWithStorage[110.246.92.218:9866,DS-e28bb23b-7a03-498a-b8a2-859382ad300e,DISK]]

2、hadoop datanode log

2022-05-24 01:27:12,269 WARN  [DataXceiver for client DFSClient_NONMAPREDUCE_-1719586450_1 at /110.246.92.219:60654 [Receiving block BP-1487117196-110.246.92.211-1641695608175:blk_1328326532_260060124]] datanode.DataNode (BlockReceiver.java:manageWriterOsCache(934)) - Slow manageWriterOsCache took 510ms (threshold=300ms), volume=file:/data/hadoop/, blockId=1328326532

二、问题分析及处理

1、在每个DataNode上运行以下命令来收集所有Slow消息的计数

$ egrep -o "Slow.*?(took|cost)" hadoop-root-datanode-datanode-1.out | sort | uniq -c
   1105 Slow BlockReceiver write data to disk cost
    330 Slow BlockReceiver write packet to mirror took
    102 Slow flushOrSync took
   5031 Slow manageWriterOsCache took
    388 Slow PacketResponder send ack to upstream took

现象	原因
集群负载高	如果你的集群处于或接近资源上限（内存，cpu或磁盘），则你在处理作业时，你的集群可能无法确保数据本地化，因此需要在网络上传输数据块。如果是这种情况，由于使用集群上的额外负载来传输数据块，因此可能会在作业或数据节点中看到WARN消息。
Slow BlockReceiver write packet to mirror	这表明在网络上写入块时有延迟
Slow BlockReceiver write data to disk cost	这表示在将块写入OS缓存或磁盘时存在延迟
Slow flushOrSync	这表示在将块写入OS缓存或磁盘时存在延迟
Slow manageWriterOsCache	这表示在将块写入OS缓存或磁盘时存在延迟

需要注意的是，在生产环境的正常负载下，一些集群的WARN消息在datanode日志中是正常的。当单个节点具有比正常情况更多的上述WARN消息时，表明存在底层硬件问题。

2、如果单个节点的一个或多个类别的”Slow“消息比其他主机的”Slow“消息数量多出数量级，则需要调查底层硬件问题。

3、如果Slow消息数最多的是Slow BlockReceiver write packet tomirror took，请通过以下命令的输出来调查可能的网络问题：

• ifconfig -a(定期检查问题主机上增加的errors和dropped的数量，往往代表的是网卡，网线或者上游的网络有问题)
• netstat -s（与正常节点相比，查找大量重新传输的数据包或其他异常高的指标）。
• netstat -s | grep -i retrans（整个集群执行）。 （在一个或多个节点上查找大于正常的计数）。

4、如果Slow消息最多的是一些其他消息，请使用以下命令检查磁盘问题：

• iostat[高iowait百分比，超过15%]
• iostat -x和sar -d（特定分区的高await或％util）
• dmesg (磁盘错误)
• 使用smartctl对磁盘进行健康检查：停止受影响节点的所有Hadoop进程，然后运行sudo smartctl -H /dev/<disk>，检查HDFS使用的每块<disk>

三、iostat 用法

iostat [选项] [<时间间隔>] [<次数>]

命令参数：

• -c： 显示CPU使用情况
• -d： 显示磁盘使用情况
• -N： 显示磁盘阵列(LVM) 信息
• -n： 显示NFS 使用情况
• -k： 以 KB 为单位显示
• -m： 以 M 为单位显示
• -t： 报告每秒向终端读取和写入的字符数和CPU的信息
• -V： 显示版本信息
• -x： 显示详细信息
• -p：[磁盘] 显示磁盘和分区的情况

示例1：

显示所有设备负载情况

$ iostat
Linux 4.18.0-305.3.1.el8_4.x86_64 (datanode-1)     05/27/2022     _x86_64_    (56 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           1.61    0.00    0.86    0.03    0.00   97.50

Device             tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
sdc              10.58       359.21      1883.53 4304228032 22569192188
sde              10.71       378.36      1894.66 4533707080 22702573592
sdf              10.70       382.28      1895.95 4580623920 22717997980
sdh              10.70       378.91      1903.69 4540288592 22810744428
sdi              10.66       358.34      1902.37 4293810648 22794905924
sdg              10.71       372.79      1902.01 4466956568 22790663472
sdd              10.60       358.42      1891.27 4294701984 22661970536
sda              11.67       383.96      1913.88 4600786635 22932900259
sdb              10.61       359.89      1887.82 4312299484 22620539680
dm-0              0.71         1.13         9.16   13594428  109721860
dm-1              0.32         0.41         0.88    4918668   10528140
dm-2              4.93       382.41      1903.85 4582230392 22812647732

cpu属性值说明：

• %user：CPU处在用户模式下的时间百分比。
• %nice：CPU处在带NICE值的用户模式下的时间百分比。
• %system：CPU处在系统模式下的时间百分比。
• %iowait：CPU等待输入输出完成时间的百分比。
• %steal：管理程序维护另一个虚拟处理器时，虚拟CPU的无意识等待时间百分比。
• %idle：CPU空闲时间百分比。

dis磁盘属性值说明：

• device:磁盘名称
• tps:每秒钟发送到的I/O请求数
• Blk_read/s:每秒读取的block数
• Blk_wrtn/s:每秒写入的block数
• Blk_read:读入的block总数
• Blk_wrtn:写入的block总数.

注意：

如果%iowait的值过高，表示硬盘存在I/O瓶颈，%idle值高，表示CPU较空闲，如果%idle值高但系统响应慢时，有可能是CPU等待分配内存，此时应加大内存容量。%idle值如果持续低于10，那么系统的CPU处理能力相对较低，表明系统中最需要解决的资源是CPU。

实例2：
间隔1秒，总共显示5次

iostat 1 5

每隔2秒,显示一次设备统计信息.

iostat -d 2

每隔2秒,显示一次设备统计信息.总共输出3次.

iostat -d 2 3

每隔2秒显示一次sda, sdb两个设备的扩展统计信息,共输出3次.

iostat -x sda sdb 2 3

每隔2秒显示一次sda及上面所有分区的统计信息,共输出3次.

iostat -p sda 2 3

以M为单位显示所有信息

iostat -m

显示指定硬盘信息

iostat -d sda

报告每秒向终端读取和写入的字符数

iostat -t

查看TPS和吞吐量信息

iostat -d -k 1 1

查看设备使用率（%util）、响应时间（await）

iostat -d -x -k 1 1

参数说明：

• rrqm/s: 每秒进行 merge 的读操作数目。即 rmerge/s
• wrqm/s: 每秒进行 merge 的写操作数目。即 wmerge/s
• r/s: 每秒完成的读 I/O 设备次数。即 rio/s
• w/s: 每秒完成的写 I/O 设备次数。即 wio/s
• rkB/s: 每秒读K字节数。是 rsect/s 的一半，因为每扇区大小为512字节。
• wkB/s: 每秒写K字节数。是 wsect/s 的一半。
• avgrq-sz: 平均每次设备I/O操作的数据大小 (扇区)。
• avgqu-sz: 平均I/O队列长度。
• rsec/s: 每秒读扇区数。即 rsect/s
• wsec/s: 每秒写扇区数。即 wsect/s
• r_await:每个读操作平均所需的时间
• 不仅包括硬盘设备读操作的时间，还包括了在kernel队列中等待的时间。
• w_await:每个写操作平均所需的时间
• 不仅包括硬盘设备写操作的时间，还包括了在kernel队列中等待的时间。
• await: 平均每次设备I/O操作的等待时间 (毫秒)。
• svctm: 平均每次设备I/O操作的服务时间 (毫秒)。
• %util: 一秒中有百分之多少的时间用于 I/O 操作，即被io消耗的cpu百分比

注意：

如果 %util 接近 100%，说明产生的I/O请求太多，I/O系统已经满负荷，该磁盘可能存在瓶颈。如果 svctm 比较接近 await，说明 I/O 几乎没有等待时间；如果 await 远大于 svctm，说明I/O 队列太长，io响应太慢，则需要进行必要优化。如果avgqu-sz比较大，也表示有当量io在等待。

查看cpu状态，间隔1秒显示一次，总共显示2次

iostat -c 1 2