osd延时调查

 

写在前面

当集群压力较大，或者写了很多的数据的时候，很容易出现延时高的现象，除了建设早起避免坑之外，我们在日常维护中也应该多准备几手以备不时之需

最近我们有集群的osd写入延时经常飙得很高，有多高呢？35s。即使它是HDD盘，35s也是不可接受的，于是有了这篇排查手记

开始排查

现象很明显，客户端的连接会时不时断开，客户体验很不好，在集群查了一下osd的延时

sudo ceph osd perf |sort -nk3

发现有几个osd延时一直非常高，达到了10s以上！持续的高延时首先怀疑的是磁盘是不是有坏道

查看dmesg -T查看，发现系统没有IO方面的ERROR，查看osd日志，没事，smartctl -a /dev/sdx看了下，磁盘没有报错信息，em……

接下来，使用iostat -x 1 /dev/sdx查看这个盘的读写延时高不高，神奇的是，磁盘读写延时也很正常，没有比别的osd高多少，头疼…

 

杀手锏

既然常见的手段排查，都没有发现明显的问题，接下来要用更细致的手段了

使用sudo ceph daemon osd.x dump_historic_ops来打印出这个osd的op处理流程情况

结果为

{
    "description": "osd_op(client.45184774.0:141944 42.42as0 42.ad4aa42a (undecoded) ondisk+write+known_if_redirected e358965)",
    "initiated_at": "2020-07-26 20:15:35.076183",
    "age": 72.268030,
    "duration": 35.587722,
    "type_data": {
        "flag_point": "reached pg",
        "client_info": {
            "client": "client.45184774",
            "client_addr": "10.95.141.7:0/3273188421",
            "tid": 141944
        },
        "events": [
            {
                "time": "2020-07-26 20:15:35.076183",
                "event": "initiated"
            },
            {
                "time": "2020-07-26 20:15:35.076183",
                "event": "header_read"
            },
            {
                "time": "2020-07-26 20:15:35.076188",
                "event": "throttled"
            },
            {
                "time": "2020-07-26 20:15:35.076571",
                "event": "all_read"
            },
            {
                "time": "2020-07-26 20:15:35.076629",
                "event": "dispatched"
            },
            {
                "time": "2020-07-26 20:15:35.076636",
                "event": "queued_for_pg"
            },
            {
                "time": "2020-07-26 20:16:10.663904",
                "event": "reached_pg"
            },
            {
                "time": "2020-07-26 20:16:10.663905",
                "event": "done"
            }
        ]
    }
}

 

可以看到，这个op的duration为35.587722秒，也就是这个处理完这个op历时非常长，接下来看一下它究竟在哪里花了时间

看到queued_for_pg和reached_pg这两个event的时间戳，差值是多少呢？

35.56秒！

这个op处理时间消耗，有99.99%都在这两个状态之间，那这两个状态是怎么回事？看到

https://susedoc.github.io/doc-ses/master/single-html/ses-troubleshooting/

 

具体说明：

queued_for_pg
The op has been put into the queue for processing by its PG.

reached_pg
The PG has started doing the op.

 

噢，这个过程就是op在等待被执行。原来op本身很慢，是在队列等待

那么问题来了，队列为啥会等待呢

osd磁盘队列等待一般思路是3个，一个是磁盘有坏道，这导致某些op处理非常慢，引发后续op无法及时被处理，另外一个是队列本身的处理能力不足，直接体现是队列的线程数不够，最后，可能是pg数过多，使得写入压力增大时，op数量激增

磁盘坏道的可能性基本排除，磁盘读写延时持续正常且没有IO错误信息，那么可能就是软件层面的事了，也就是可能是处理op队列的线程数严重不足

经过调查，13及后续版本，我们调整osd op处理线程数的参数是

osd_op_num_shards 
osd_op_num_threads_per_shard

 

这两个值调多大，要具体看业务场景和配置，取太大会有问题，磁盘容易被大量的线程跑满，所以要具体试试，一般两个值都取4来看结果，不够再加

总结

osd延时如果明显的维持在高位，例如hdd磁盘的osd一直都很慢，几秒甚至十几秒，那最先排查的应该是硬件问题，坏道是比较常见的原因，如果物理盘没事，那么可以开始检查其他地方，本文提供了一个参考的解决路径，希望对读者有些许帮助

 

转自：http://strugglesquirrel.com/2020/10/30/ceph%E8%BF%90%E7%BB%B4%E5%A4%A7%E5%AE%9D%E5%89%91%E4%B9%8Bosd%E5%BB%B6%E6%97%B6%E8%B0%83%E6%9F%A5/