定位一个slow-request

写在前面

喜欢ceph的话欢迎关注奋斗的cepher微信公众号阅读更多好文！

slow req在ceph集群的运行中时常会出现，调查slow req有时候很容易，可能就是简单的由坏道引起的磁盘缓慢，或者是网络丢包，也有可能是很复杂的存储池相关的问题，另外，时钟问题也可能导致slow req，这个就比较隐蔽，有时候想不到，本篇提供的是比较简单的slow req场景排查，并提出解决思路。

开始

首先是监控提示存储池出现流量归0的情况，这可是大事，不管是测试集群还是生产集群，正常写入的流量出现归0意味着存储出大问题了，因此快速排查，发现在这段时间集群有slow req：

通常osd的slow req不会导致存储池流量完全归0，如果是某些组件出问题导致的slow，例如丢包、慢盘，那么流量应该是波动的，这就有点奇怪，另外，slow req存在一定的时间后，就自行消失了，有一定的周期性，必现的问题好查，不过目前集群是没有slow req的，那么排查怎么展开呢？

故障排查，如果没有现场，那么首先应该想到的是看日志，而这种集群级别的问题，应该要先考虑看monitor的日志，从监控得到slow req的时间，对monitor的日志进行定位，发现当时确实有slow req

2024-08-06 01:50:49.351 7f3ba09b1700  0 log_channel(cluster) log [WRN] : Health check update: 50 slow ops, oldest one blocked for 48 sec, osd.2009 h
as slow ops (SLOW_OPS)
2024-08-06 01:50:54.354 7f3ba09b1700  0 log_channel(cluster) log [WRN] : Health check update: 33 slow ops, oldest one blocked for 50 sec, osd.2009 h
as slow ops (SLOW_OPS)
......

从该日志，可以知道出slow的osd是osd.2009，那么接下来不用说，就是直接去osd.2009看它当时的日志了，根据时间点进行定位，发现了slow req的日志：

2024-08-06 01:50:34.369 7fc527ea5700  0 log_channel(cluster) log [WRN] : slow request osd_op(client.669525420.0:1894713815 9.10 9.269e4d50 (undecoded) ondisk+read+known_if_redirected e37528) initiated 2024-08-06 11:45:00.604352 currently queued for pg

很明显了，这个信息，既然osd已经报了slow，那确实是慢了，接下来，常规操作就是查看osd日志的上下文看看它在干什么，有没有相关的IO错误之类的，以及dmesg -T查看硬件是否有报错，但是，因为松鼠哥环境的监控比较完备，通过看图，在对应时间点一下子就看出是存储池进行数据删除的GC回收导致压力过大引发slow req(so，就是监控的重要性，千万不要忽视监控系统)，这里日志除了能看出有slow req外，还有一个重要信息，就是slow的op属于哪个存储池，这条日志信息的对应代码位置为：

code:src/osd/OSD.cc
      if (op.get_initiated() < too_old) {
        stringstream ss;
        ss << "slow request " << op.get_desc()
           << " initiated "
           << op.get_initiated()
           << " currently "
           << op.state_string();
        lgeneric_subdout(cct,osd,20) << ss.str() << dendl;
        if (log_aggregated_slow_op) {
          if (const OpRequest *req = dynamic_cast<const OpRequest *>(&op)) {
            uint8_t op_type = req->state_flag();
            auto m = req->get_req<MOSDFastDispatchOp>();
            uint64_t poolid = m->get_spg().pgid.m_pool;
            slow_op_types[op_type]++;
            if (poolid > 0 && poolid <= (uint64_t) osdmap->get_pool_max()) {
              slow_op_pools[poolid]++;
            }
          }
        } else {
          clog->warn() << ss.str();
        }

可以看到，这个op显示的信息中，op.get_desc()这个函数的输出可能比较关键，通过对比，发现它输出的信息跟dump osd的perf信息一致，从而，osd_op(client.669525420.0:1894713815 9.10 9.269e4d50 (undecoded) ondisk+read+known_if_redirected e37528)这个信息，client表示的是哪个客户端，对象存储通常我们不关注它，接下来的9.10这个字段，是对应的pg的id，这个比较有用，不仅让我们知道它是哪个存储池的op，还能通过ceph pg map pgid的方式知道它涉及哪些osd，后面的e37528是osdmap的版本号，特殊场景下也很有用(比如回滚osdmap版本，比如抽出该版本中的crushmap等骚操作)。

定位到是存储池9的op产生了slow，接着看，发现这个id为9是对象存储的.rgw.meta存储池，这个存储池很少被关注到，为何它slow会导致对象存储写入受阻呢？

经过调查发现，当rgw做GC回收的时候，需要去访问这个meta池的少量元数据，这个过程可能会锁对应的pg，由于这个锁比较大，锁的时间很长的话，会导致其他的op得不到osd资源从而引发slow req，导致写入操作出问题。

解决思路比较简单了，因为meta池所分配的pg数量和osd数量都很少，如果GC速度过快，就容易出现锁长时间占用资源的问题，因此为该存储池增加OSD并增加这个存储池的pg数，就能很好地解决这个slow req的问题。

总结

松鼠哥喜欢富有挑战的问题排查，就像一个侦探为了查出真相而进行各种努力和尝试，利用现有知识和对原理的理解进行整合并提出调查思路，一步步发现问题的真相，最终发现问题的起因，从而得出解决方案，收获成就感。

这种过程相对简单的slow算是基操了，本来不想写，但是呢，很多次有老铁咨询问题的时候，竟然不会主动去看日志，或者根本就不知道该看什么日志，提出的问题也是抓不到重点，因此松鼠哥觉得基操也可以写写，毕竟很多同学还是新手~

希望对大家有帮助。
喜欢ceph的话欢迎关注奋斗的cepher微信公众号阅读更多好文！