osd慢请求排查的一般思路

2022-07-06

字数统计: 2.4k字 | 阅读时长≈ 9分

应读者朋友的邀请做一些思路解读

写在前面

松鼠哥的ceph专业课程上线啦！
面向新手同学，从0实战，全面入门ceph安装部署与运维，有需要的同学赶紧扫码订购吧：

前阵子有读者朋友留言，希望松鼠哥讲讲慢请求的排查相关，本想上周写一下，奈何太忙，线上问题多，还要各种性能测试、硬件调研，今天忙里偷闲创作一波，好饭不怕晚！

开始之前，照例还是要打一波招聘广告，我们这边是天翼云科技的媒体存储组，目前我们仍在招聘存储研发、存储运维及相关组件开发的人才，有意向换工作的老铁可以试试，简历发一发，我们这边还是很不错的，千万不要错过

开始

首先明确，slow req，可以说是ceph运行维护过程中经常遇到且排查难度较大的问题，它形成的原因比较多，很多情况下排查难度很大，但是slow req往往预示着集群是存在问题的，所以我们又不能不排查，由此，本篇便是力所能及地做一些经验之谈

如果集群有slow req，一般来说会有几种现象，最严重也是最明显的，是业务侧感知到写入的延时明显变大，集群侧，则会有如下现象

1、ceph -s有提示，例如

1	321 slow ops, oldest one blocked for 82668 sec, daemons [osd.128,mon.mon2.sn.cn,mon.mon1.cn] have slow ops.

这种提示明确了slow req发生的对象，当op超过一个阈值，就会在ceph -s的输出中显示slow的情况，出现这种现象就说明slow req的问题比较严重了，已经到了明显要提示的程度，这里osd.128是要排查的，而mon的slow一般来说，我们的处理办法比较简单粗暴，就是restart一下对应的mon即可，因为mon的slow往往是由于其他组件的slow导致的，问题不在mon，如果重启mon后问题仍在，就要继续调查日志了，看看是哪里引起的，一般重启完mon之后，mon的slow提示就会消失

2、在osd日志或者message中有显示，例如

May 16 15:27:25 osd-node-05 ceph-osd: 2022-05-16 15:27:25.293 7fe9baa3c700 -1 osd.129 122179 get_health_metrics reporting 1 slow ops, oldest is osd_op(client.2277913.0:4347978200 5.893s0 5:c916b58e:::45dc82e0-df12-4d41-b6ba-e2f9076b9d1c.105661.6__shadow_.Lz446vGpSl7iRkblkHJtVTKO9J0MK9v_6:head [call refcount.put] snapc 0=[] ondisk+write+known_if_redirected e122175)

这种osd日志本身打的log，因为严重程度较情，所以集群那边暂时不会显示出来，但是这也预示着这个osd是有风险的，这种比较隐蔽，不容易发现，一个集群这么多盘，哪有时间逐个去看它的日志看看有没有slow呢

排查

思路上，我们要清晰，slow req的形成原因比较多，业务数据写入集群所经过的大部分路径，都有可能导致op变慢从而出现slow

首当其冲的，是硬件，当我们发现有slow reqd的时候，应该最先怀疑硬件问题，排查的第一步是网络，定位到slow req的节点

1、ping，看看丢包情况，看看ping包的延时情况，是否稳定，如果忽高忽低，相差很大，那很有可能是网络问题引起的op传输受到影响

2、iperf3打流，如果ping没有问题，就看下iperf3的tcp打流情况，是否跑下来tcp有问题，网络质量好不好

3、查看dmesg，看看网卡是否有相关报错信息，最常见的就是网卡发生了UP/Down，可能是线坏了或者插头松了，UP/Down会导致传输进行时产生丢包，tcp产生丢包对传输性能影响很大

4、selinux和firewall的排查，看下有没有可能是某些特定端口的包被挡了

以上几个步骤，排查下对网络情况就有了底

其次，是看下系统负载情况以及磁盘的情况，如果系统负载过大，会导致osd得不到足够的计算资源，op队列处理不及时，op就slow了

针对磁盘的情况，手段有这么几种

1、iostat -x sd*，单独看看磁盘是不是跑满了，读写延时是不是很大，如果磁盘持续繁忙，处理不了这么多op，也会slow

2、dmesg -T，查看最近一段时间，磁盘有没有硬件报错，尤其是IO error方面的信息，如果有，不用想了换盘吧

3、查看osd的日志，看下日志中有没有IO相关的日志，有时候dmesg那边的日志还没有显示，但是osd日志已经显示有IO问题了；另外，如果osd日志中没有IO报错，大部分日志都是rocksdb的日志，就有可能是因为rocksdb的compaction导致磁盘的性能短暂被db榨干，从而osd无法获取到IO资源来处理op，也会导致slow，这种情况没有什么办法，因为compaction是没有办法避免的，要么就给osd搞ssd，加快这段操作的速度

4、如果上述排查未发现任何异常，就要看下iotopl了，看下磁盘正在进行的IO大概情况，以及使用perf top -p xx的方式，分析osd到底在做什么，甚至可以定位到代码的函数中，看下这部分操作会不会影响op处理

最后，如果经过排查，环境硬件都没有问题，slow还是多，那么就要分析一下op的具体处理流程了

因为osd.128是因为坏盘产生的slow req，已经被处理了所以换osd.129来看下op流程

ceph daemon osd.129 dump_historic_ops_by_duration
"description": "osd_op(client.5710671.0:911515330 5.169as0 5:5969a3d9:::a6d19067-0ebc-4320-b176-6f902d463f77.298537.1__shadow_.hLHnv2N2acmbbO99OVJlov-DCq0_B6l_1:head [call refcount.put] snapc 0=[] ondisk+write+known_if_redirected e75969)",
            "initiated_at": "2022-05-17 14:56:02.920176",
            "age": 533.331712,
            "duration": 0.496794,
            "type_data": {
                "flag_point": "commit sent; apply or cleanup",
                "client_info": {
                    "client": "client.5710671",
                    "client_addr": "10.95.154.134:0/4118870958",
                    "tid": 911515330
                },
                "events": [
                    {
                        "time": "2022-05-17 14:56:02.920176",
                        "event": "initiated"
                    },
                    {
                        "time": "2022-05-17 14:56:02.920176",
                        "event": "header_read"
                    },
                    {
                        "time": "2022-05-17 14:56:02.920185",
                        "event": "throttled"
                    },
                    {
                        "time": "2022-05-17 14:56:02.920213",
                        "event": "all_read"
                    },
                    {
                        "time": "2022-05-17 14:56:02.920276",
                        "event": "dispatched"
                    },
                    {
                        "time": "2022-05-17 14:56:02.920286",
                        "event": "queued_for_pg"
                    },
                    {
                        "time": "2022-05-17 14:56:02.929867",
                        "event": "reached_pg"
                    },
                    {
                        "time": "2022-05-17 14:56:02.939236",
                        "event": "started"
                    },
                    {
                        "time": "2022-05-17 14:56:02.940487",
                        "event": "sub_op_started"
                    },
                    {
                        "time": "2022-05-17 14:56:02.942894",
                        "event": "sub_op_committed"
                    },
                    {
                        "time": "2022-05-17 14:56:03.416938",
                        "event": "commit_sent"
                    },
                    {
                        "time": "2022-05-17 14:56:03.416970",
                        "event": "done"
                    }
                ]

这是一个完整的op处理流程，我们最关心的，是这个op的duration字段，它表示了这个op处理的时间开支，从initiated到done，我们可以看到处理步骤中的每一步所消耗的时间，这个op从接收到处理完成返回，花费了0.496794s，这个时间算多吗？总体来说有点多，它是一个ssd+HDD的osd，这个操作花费了差不多0.5s是算比较慢的了，看一下流程，发现多数时间在sub_op_committed，这个过程表示的是将数据提交给磁盘到返回所花费的时间，算比较慢了，不过还没到slow req的程度，再看看它的磁盘情况

1 2	Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sdn 99.00 2635.00 239.00 92.00 1384.00 10908.00 74.27 4.55 13.75 18.45 1.54 0.53 17.60

可以看到，r_await和w_await都比较高，而且queue都挺长的，有较多的写和部份的读，这么看，磁盘本身还是挺慢的

1 2	[root@osd-node-005 twj]# ceph osd df\|grep 129 129 hdd 7.29999 1.00000 7.4 TiB 4.9 TiB 2.4 TiB 67.21 0.97 243

看到这个osd已经使用了67.21%，写得挺满了，一般来说osd使用越多空间，其性能就会越差，因为后续的读写都可能会触发到之前的数据，所以当集群使用到后期，性能会降低也不奇怪

综上，排查了一圈，这个osd虽然没有slow，但是本身处理是比较慢了，有可能是集群读写压力较大，又或者写入的对象过多过小

总结

本篇简单介绍了一下集群slow req的形成及排查的一般思路，这些都是我们在日常维护中常用的一些手段方法，在多数情况下slow req都能在某个步骤中被排查出来，但是，受限于对ceph的认知，仍然有不少情况的slow req我们是排查不到的，实在不行就只能是大力出奇迹，重启看看。

不管怎么说，排查处理问题通常只是事后的补救，最高明的维护不是我们处理了多少问题，处理问题有多快，而是我们在设计之初，就把不该出现的问题全部规避掉

本文作者： 奋斗的松鼠
本文链接： http://www.strugglesquirrel.com/2022/07/06/osd慢请求排查的一般思路/
版权声明： 本博客所有文章除特别声明外，创作版权均为作者个人所有，未经允许禁止转载！