一次 jbd2进程导致磁盘 io 高的分析解决过程

故障现象

在3节点组成的大数据集群中,混部了 ES,kafka,zk,pg,mysql,spark,yarn,hdfs,以及业务的 etl 程序等组件。起初发现业务进程处理数据速度很慢,排查后发现数据盘 /data01 的 util 接近100%

但是磁盘吞吐量并不高,IO 流量只有2MB 左右,主要是由 w/s 导致,也就是写入的 iops 高,这种情况一般就是进程的 sync 操作密集。

分析过程

通过 iotop 来查看是哪个进程,显示为 jbd2

查阅一些资料后,了解到 jbd2进程负责 ext4这种日志文件系统的日志提交操作,关于jbd2引起磁盘 io 高,网上也有很多类似案例,总结起来有几方面原因:

  1. 系统 bug
  2. ext4文件系统的相关配置问题
  3. 其他进程的 fsync,sync 操作过于频繁

首先排除系统 bug因素,网络上反馈的问题在很低的版本,我们生产环境为 Centos 7.4,其次,查阅了 /proc/mounts 等信息,发现文件系统配置参数与其他环境差异不大,按照网上提供的关闭某些特性,降低 commit 频率等理论来说会有效果,但需要重新 mount 磁盘,相关组件都要重启,并且这看起来并非根本原因。

尝试分析 sync 调用,使用 sysdig 最方便,但现场环境安装很麻烦,因此开启几个内核 trace查看:

在 jbd2执行 flush 时输出日志

 

 

1

2

3

 

echo 1 > /sys/kernel/debug/tracing/events/jbd2/jbd2_commit_flushing/enable

 

 

在任意进程执行 sync 时输出日志

 

 

1

2

3

 

echo 1 > /sys/kernel/debug/tracing/events/ext4/ext4_sync_file_enter/enable

 

 

然后观察日志输出:

 

 

1

2

3

 

cat /sys/kernel/debug/tracing/trace_pipe

 

 

输出信息如下:

可以看到 jbd2和 java-17417进程有大量的 sync,瞬间刷出大量日志,因此基本确定 java-17417进程。17417为 java 进程的 tid,ps 看一下是哪个任务导致的:

 

 

1

2

3

 

ps -efL |grep 17417

 

 

-L 或-T 参数显示线程 id,ps 获取到 pid 和程序路径后,发现是 zk 进程,很让人疑惑,zk 怎么会大量 sync 呢,trace 一下他在做什么:

 

 

1

2

3

 

strace -f -p 17417

 

 

输出信息如下:

根据 fd 号去看看这是什么文件:

 

 

1

2

3

 

ll /proc/{zk_pid}/fd/74

 

 

发现是 log.xxx,是 zk 的事务日志,zk 频繁写事务日志,是由于对 zk 执行了大量写操作导致的。为了确认是 zk 引起的问题,将 zk 的数据路径修改到其他盘,重启 zk 节点,发现变成其他盘的 util 跑满了,到此为止确认是 zk 引起的。

解决方式

经过与业务沟通后,确认是业务进程设计不合理,对 zk 执行大量写操作,暂时采取临时措施,将 zk 的数据路径调整到系统盘,系统盘为 ssd

没有相关文章.

(转载请注明作者和出处 easyice.cn ,请勿用于任何商业用途)

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值