Ceph云盘util频繁100%性能问题分析过程记录

2020-09-24更新

这两天又遇到了类似问题，也是initiated阶段耗时特别长，几秒到几十秒，就怀疑是这个问题，打开debug_optracker=5，果然还是all_read耗时很长，找到卷所在的虚拟机以及虚拟机所在的计算节点，然后跟osd节点互ping 4k大包，结果如下：

网络问题原因还在分析中。

问题症状

popo群用户报障，hzabj-ysf-nginx-08.server.163.org这台机器IO总是100%，哨兵监控截图如下：

初步分析

首先查看打桩卷监控，根据历史日志（日志是我之前修改librados代码加上的)可以了解这个物理池经常有超过3s的IO（一般我们认为超过3s就会导致io util 100%）：

通过这个日志就基本可以排除是用户自己磁盘IO繁忙导致的util 100%了。

否则就要先确认用户自己的IO繁忙程度，可以看下哨兵监控（根据主机名前缀搜索一般能搜到）或者找NVS组查看云主机磁盘监控信息，如果本身已经比较繁忙，比如达到了云盘的QoS限制（iops、bps），那首先怀疑他们业务的问题导致的100%。

进一步分析

之前这个存储池的打桩卷已经偶有告警，一直误以为是存储池比较繁忙导致的，因此首先看了下物理池上的2个逻辑池的负载，看起来不忙（对ssd pool来说不到5千的iops应该算比较空闲了）。

之后根据打桩卷日志中的对象进行分析，可以看出还是有一定的规律的，就是告警的对象有很多重复，所以就怀疑跟特定pg或者osd有关，但有不能肯定，因为经过ceph osd map查看对应的osd，还是比较分散的。

再进一步就是查看ceph.log及ceph-osd.log，结果是一无所获，没有有效日志。

之后就是怀疑有慢盘，查看osd的perf dump信息，分析osd的journal相关延时，发现比较正常，但op_w_latency比较高，说明盘ok，但是op就是处理的慢，看物理机的基础监控也ok。

此时就比较棘手了。

只能打开osd_enable_op_tracker = true这个配置项并重启osd了，重启osd也要挑一个重点怀疑的对象，挑选比较简单，就是根据打桩卷的告警中的对象对应的osd，查看哪个osd被对应的次数最多，就挑他先重启打开。

其中xxx就是所有打桩卷日志中告警的对象名称列表。

然后截取yyy中的osd列表，进行排序，查看最多出现的那个osd。

挑选的osd是osd.1908，之后提at单进行重启（先手工修改/etc/ceph/ceph.conf中的配置项：osd_enable_op_tracker = true），之后重启这个osd，重启过程比较平稳，没有造成抖动（一般来说停止启动间隔时间比较短的情况下都不会造成明显抖动）。

重启之后就等着问题出来就行，tailf看着打桩卷的日志，发现有超过3s的就对osd.1908执行sudo ceph daemon osd.1908 dump_historic_ops命令查看op耗时，发现有很多op是在等其他副本返回（sub_op_commit_rec这个事件比较耗时）。

可惜的是H版本没有把这个事件对应的osd id打印出来（L版本已加，已经pick到我们的H版本），无从知晓是哪个副本osd返回慢，于是只能挑选出现比较频繁的osd（两个副本）都继续打开osd_enable_op_tracker并重启osd。

重启之后看到repop的耗时也比较长，但耗时的阶段比较奇怪（在reached_pg之前，这个是dequeue_op的第一个阶段）：

但是还不清楚具体是在enqueue_op还是dequeue_op阶段比较慢。于是只能打开osd日志（debug_osd=15），查看具体慢在哪里，日志看到耗时确实在enqueue的时候就比较长：

另外通过日志还确认了一点，只有osd_repop才enqueue比较慢，正常的osd_op都没问题（二者入队的队列都是同一个）。

通过在开发环境gdb调试确认二者的处理流程没有区别：

这就更奇怪了，enqueue_op其实做的事情非常简单，就是把op丢到osd的op处理队列就返回了，cpu也不忙，内存也剩余非常多，没理由这么慢，但通过日志可以确认慢的过程肯定在上面的调用栈里面。

首先怀疑是pg锁导致的问题，但还是有点疑问，业务并不繁忙，每个op正常应该处理很快，pg锁应该不会占用太长时间，当然除非是有bug。

问题分析到这里基本就有点郁闷了。只能继续撸代码看看有没有可以进一步打开的日志供我们确认问题。

还好有op tracker，我之前在基于它增加日志的时候，看到了一些日志可以打出来，我想看的日志是op什么时候收到的，什么时候分发的，

于是我把op tracker日志级别调到5（debug_optracker=5），日志就出来了：

可以明显看到是慢在从throttled到all_read这段时间，这部分代码是在src\msg\simple\Pipe.cc的Pipe::read_message里：

都是tcp_read相关操作，于是怀疑是cluster网络问题，也解释了为啥之后repop慢（它走的cluster网，而主osd处理的op则走的是public网），看起来离真相越来越近了。

之后通过ping 10.122.192.146 -s 4096 测试cluster网络，发现有异常：

于是找sa查看网络是否有问题，sa经过猜测，认为是bond的一个网卡有问题，就停掉一个eth0试验，观察一晚上没问题，问题解决了。

但问题的根本原因还是没有找到，于是第二天再次把eth0网卡up起来，跑了一天还是正常的。目前还没有找到问题出在哪儿，哨兵上查看网卡监控都是正常的。

只是机房给出的交换机信息里有异常（大量input errors和17个aborts），但也没能解释出现这些错误的原因：