OSD故障的深度定位

奋斗的松鼠

于 2024-08-12 09:33:53 发布

阅读量673

点赞数 8

文章标签： ceph

本文链接：https://blog.csdn.net/strugglesquirrel/article/details/141122852

版权

写在前面

喜欢ceph的话欢迎关注奋斗的cepher微信公众号阅读更多好文！
在《ceph实战全指南》和《ceph运维精讲》课程中，松鼠哥专门针对故障场景进行较多的思路讲解和演示，但是毕竟环境所限，没有能够更真实模拟生产环境发生的故障，因此在公众号文章中尽量将实际场景的处理操作和思路再进行细化，有兴趣的同学可以浏览松鼠哥的小店，店铺重新装修完，进去就能领优惠券直接下单支持！买起来！

本篇的场景是，集群的osd发生了down，并且在超时后被mon标记out出集群，这是非常常见的生产场景，不过为了更深入理解ceph的运行机制和原理，积累实操经验，本篇更深入地调查了本次故障。

开始

首先集群侧看，osd已经down并且out出了集群(该osd的reweight为0表示它已经out)

[root@test-mon-001 twj]# ceph osd tree down
ID   CLASS WEIGHT    TYPE NAME               STATUS REWEIGHT PRI-AFF 
-176       900.00000 root test-root-2                                 
 -30        30.00000     host test-node-031                         
 926   hdd   1.00000         osd.926           down        0 1.00000

来到这个节点，查看对应osd的日志，确认是IO 错误

[root@test-node-031 ceph]# more ceph-osd.926.log-20240616
2024-06-15 13:08:15.465 7f9fa5b66b80  0 set uid:gid to 167:167 (ceph:ceph)
2024-06-15 13:08:15.465 7f9fa5b66b80  0 ceph version 14.2.22 (564bdc4ae87418a232fc901524470e1a0f76d641) nautilus (stable), process ceph-osd, pid 2216259
2024-06-15 13:08:15.465 7f9fa5b66b80  0 pidfile_write: ignore empty --pid-file
2024-06-15 13:08:15.486 7f9fa5b66b80 -1 bluetwj(/var/lib/ceph/osd/ceph-926/block) _read_bdev_label failed to read from /var/lib/ceph/osd/ceph-926/block: (5) Input/output error
2024-06-15 13:08:15.486 7f9fa5b66b80 -1  ** ERROR: unable to open OSD superblock on /var/lib/ceph/osd/ceph-926: (2) No such file or directory

再看下dmesg，确认磁盘问题，可以看到，系统的磁盘IO报错时间比osd自己的报错时间要早一些，程序在系统层面进行磁盘IO读写，操作实在不能完成了，异常才会被osd所感知，结合两个日志可以认为：osd磁盘在15号11:27开始报错，osd在13:08:15左右挂掉不再起来

[root@test-node-031 ceph]# dmesg -T
[Sat Jun 15 11:27:37 2024] sd 15:1:0:20: rejecting I/O to offline device
[Sat Jun 15 11:27:37 2024] sd 15:1:0:20: rejecting I/O to offline device
[Sat Jun 15 11:27:37 2024] sd 15:1:0:20: rejecting I/O to offline device
[Sat Jun 15 11:27:37 2024] sd 15:1:0:20: [sdae] FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_TIMEOUT
[Sat Jun 15 11:27:37 2024] sd 15:1:0:20: [sdae] CDB: Write(16) 8a 00 00 00 00 02 9d 2b 47 00 00 00 00 80 00 00
[Sat Jun 15 11:27:37 2024] blk_update_request: I/O error, dev sdae, sector 11226793728

到这里，就可以开始换盘并重建osd了，为了调查更完整，我们继续往下看。

osd发生down之后，要过一段时间才会被mon标记为out，继续看mon的日志，定位到对应时间(默认是down掉10分钟后)

2024-06-15 13:16:58.325 7feba7c75700  0 log_channel(cluster) log [INF] : Marking osd.926 out (has been down for 604 seconds)
2024-06-15 13:16:58.325 7feba7c75700  1 mon.test-mon-001@0(leader).osd e259989 do_prune osdmap full prune enabled

当mon将osd标记为out之后，pg将开始peer并在完成后开始backfill，这个pg状态变化松鼠哥在课程内也讲得很清楚了，backfill完成后pool是正常的

[root@test-node-031 ceph]# ceph osd pool stats test1.pool2.bucket.data
pool test1.pool2.bucket.data id 48
  client io 345 MiB/s wr, 0 op/s rd, 1.96 kop/s wr

这种情况下，我们大可换盘并等待pg的重新回填，但是有同事提出，我们能不能确定这个osd影响的pg是什么时候恢复好的。

这个问题有意义吗？在本例中，所有pg都恢复到了active+clean，调查故障osd引发的pg恢复情况似乎没有太大必要，但是，很多调查过程比调查结果重要，因为调查过程所使用的思路、原理很多时候可以强化我们对ceph机制的认识，并在特殊情况下对我们处理集群致命故障有很大的帮助，因此在这个相对正常的环境我们继续调查pg的情况。

PG的一些调查

这个调查很有意思，真的。

首先，我们要跟踪osd.926故障后它的pg的情况，就必须先要得到它所承载的pg列表，如果osd.926的磁盘仍然可以访问，那么使用ceph-objectstore-tool命令就能够列出它的所有pg，但是在本例中(很多时候也是这样)，osd所使用的磁盘已经损坏，甚至lsblk都无法看到盘符，这就没办法直接从osd磁盘读到pg信息。

此时，因为osd已经out，它上面的pg也完成了backfill，那么ceph pg ls-by-osd 926必然也没办法得到pg信息，而且在osd.926的日志中，也没办法得到完整的pg列表，集群对osd.926的相关pg的信息似乎都没办法搞到了，那么还有办法吗？

这时候就要用到osdmap了，在松鼠哥的课程中重点介绍了osdmap，它是集群最重要的map，我们可以从osdmap中得到非常多的信息：

osdmap是一个时间序列，不仅记录变化，还记录对应的时间
osdmap记录详细的集群变化，其中就包括crush变化，可以从osdmap导出当时的crushmap
osdmap记录详细的osd变化，能够得到当时的osd所有状态信息，当然也可以导出pgmap

从osdmap导出pgmap，来完成对当时的pg分布的调查，这个可行吗？可行，这里直接开搞。

首先，明确当前集群osdmap版本

[root@test-mon-001 ceph]# ceph osd dump|more
epoch 262463

接下来，确定osd.926在故障前后的osdmap版本，我们要取一个它故障前的osdmap版本，才能得到正确的pg分布，记得我们在mon的日志中调查osd.926何时out出集群吗？是的，它附近有osd.926被out时候的版本，就是e259989，简单点，我们取集群的259000版本

[twj@test-mon-001 twj]$ sudo ceph osd getmap 259001 -o osdmap.259000
got osdmap epoch 259000

得到osdmap之后，解析它，得到当时的pgmap，注意一次命令获取一个pool的pgmap，这里指定osd.926所在的存储池，它的id是48

[root@test-mon-001 twj]# osdmaptool --test-map-pgs-dump-all --pool 48 osdmap.259000
osdmaptool: osdmap file 'osdmap.259000'
pool 48 pg_num 8192
48.0 raw ([810,729,900,555,1069,1020,864,882,584,633,625,762], p810) up ([810,729,900,555,1069,1020,864,882,584,633,625,762], p810) acting ([810,729,900,555,1069,1020
,864,882,584,633,625,762], p810)
48.1 raw ([586,775,1052,793,980,1034,958,843,685,634,618,704], p586) up ([586,775,1052,793,980,1034,958,843,685,634,618,704], p586) acting ([586,775,1052,793,980,1034
,958,843,685,634,618,704], p586)
48.2 raw ([587,742,810,637,1019,986,670,937,1021,851,750,704], p587) up ([587,742,810,637,1019,986,670,937,1021,851,750,704], p587) acting ([587,742,810,637,1019,986,
670,937,1021,851,750,704], p587)
......

可以看到，该存储池对应的pgmap完整地得到了，为了验证这个pgmap是不是正确的，我们还可以再随机选一个map一下

[root@test-mon-001 twj]# sudo ceph pg map 48.1e5f
osdmap e262469 pg 48.1e5f (48.1e5f) -> up [1010,939,881,702,751,553,918,848,791,659,828,601] acting [1010,939,881,702,751,553,918,848,791,659,828,601]
[root@test-mon-001 twj]# grep '48.1e5f' result
48.1e5f raw ([1010,939,881,702,751,553,926,848,791,659,828,601], p1010) up ([1010,939,881,702,751,553,926,848,791,659,828,601], p1010) acting ([1010,939,881,702,751,553,926,848,791,659,828,601], p1010)

通过对比，可以看到，48.1e5f这个pg在osd.926故障后，backfill到了osd.918，看一下osd.918的日志，直接搜这个pg，它的最后一个记录为

2024-06-16 08:35:12.330 7f18332da700  1 osd.918 pg_epoch: 260636 pg[48.1e5fs6( v 260630'672104 (260585'670543,260630'672104] local-lis/les=259991/259992 n=44297 ec=252387/252387 lis/c 259991/253057 les/c/f 259992/253107/0 259990/260636/253048) [1010,939,881,702,751,553,918,848,791,659,828,601]p1010(0) r=6 lpr=260636 pi=[253057,260636)/1 luod=0'0 crt=260630'672104 active mbc={}] start_peering_interval up [1010,939,881,702,751,553,918,848,791,659,828,601] -> [1010,939,881,702,751,553,918,848,791,659,828,601], acting [1010,939,881,702,751,553,2147483647,848,791,659,828,601] -> [1010,939,881,702,751,553,918,848,791,659,828,601], acting_primary 1010(0) -> 1010, up_primary 1010(0) -> 1010, role -1 -> 6, features acting 4611087854031667195 upacting 4611087854031667195

这表明在这个时间，pg恢复完了，同时我们还可以query这个pg

[root@test-mon-001 twj]# ceph pg 48.1e5f query
        {
            "peer": "918(6)",
            "pgid": "48.1e5fs6",
            ......
            "stats": {
                "version": "260630'672104",
                "reported_seq": "768967",
                "reported_epoch": "260635",
                "state": "active+undersized+degraded+remapped+backfilling",
                "last_fresh": "2024-06-16 08:35:12.044982",
                "last_change": "2024-06-16 05:55:30.584050",
                "last_active": "2024-06-16 08:35:12.044982",
                "last_peered": "2024-06-16 08:35:12.044982",
                "last_clean": "2024-06-15 13:04:34.864841",
                "last_became_active": "2024-06-15 13:17:02.576905",
                "last_became_peered": "2024-06-15 13:17:02.576905",
                "last_clean": "2024-06-15 13:04:34.864841",
                "last_became_active": "2024-06-15 13:17:02.576905",
                "last_became_peered": "2024-06-15 13:17:02.576905",
                "last_unstale": "2024-06-16 08:35:12.044982",
                "last_undegraded": "2024-06-15 13:17:00.580218",
                "last_fullsized": "2024-06-15 13:17:00.576245",
                ......
        }

从记录来看，last_became_active和last_became_peered记录的时间是准确的osd被out的时间，而last_active和last_peered则是记录了这个pg最后一次完成backfill进入clean的时间(大概确定)，这些信息对于我们处理其他故障可能会很有帮助。

总结

本例是一次常见的osd坏盘，因为是明显的硬件IO错误，所以很快就能够定位到，后续的调查无论是思路还是操作，虽然在本例中并不那么重要，但是对于我们理解原理有很大的帮助，比如以前总是有点纸上谈兵地说，osdmap很重要，但是它有多重要呢？它能用来做什么呢？只有通过实例，才能更好地体会它的设计理念和相关运用，看松鼠哥课程的老铁应该更有体会。
喜欢ceph的话欢迎关注奋斗的cepher微信公众号阅读更多好文！