写在前面
喜欢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微信公众号阅读更多好文!