喜迎
元旦
看懂ceph日志系列之index-osd读流程-下 | 奋斗的松鼠 - Blog

看懂ceph日志系列之index-osd读流程-下

字数统计: 1.7k字   |   阅读时长≈ 8分

看懂ceph日志系列之osd读流程-上的续集

写在前面

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

本篇继续根据日志输出探究流程

前文再续

在看懂ceph日志系列之osd读流程-上中，对slow的ssd osd分析到了op线程使用**method->exec()**函数执行op内的ops，接下来就进入到这些op的执行中

1
2
3
4
2018-12-11 23:45:14.040950 7f3ba076e700 10 osd.178 pg_epoch: 18424 pg[201.28c( v 18424'38174038 (18424'38172500,18424'38174038] local-lis/les=18173/18174 n=53 ec=1977/1977 lis/c 18173/18173 les/c/f 18174/18174/0 18173/18173/6366) [178,169] r=0 lpr=18173 crt=18424'38174038 lcod 18424'38174037 mlcod 18424'38174037 active+clean] do_osd_op 201:3170be39:::.dir.772a65be-4b10-4862-832a-e55d1c05db84.5149179.1.33:head [omap-get-header]
2018-12-11 23:45:14.040965 7f3ba076e700 10 osd.178 pg_epoch: 18424 pg[201.28c( v 18424'38174038 (18424'38172500,18424'38174038] local-lis/les=18173/18174 n=53 ec=1977/1977 lis/c 18173/18173 les/c/f 18174/18174/0 18173/18173/6366) [178,169] r=0 lpr=18173 crt=18424'38174038 lcod 18424'38174037 mlcod 18424'38174037 active+clean] do_osd_op  omap-get-header
2018-12-11 23:45:14.041056 7f3ba076e700 10 osd.178 pg_epoch: 18424 pg[201.28c( v 18424'38174038 (18424'38172500,18424'38174038] local-lis/les=18173/18174 n=53 ec=1977/1977 lis/c 18173/18173 les/c/f 18174/18174/0 18173/18173/6366) [178,169] r=0 lpr=18173 crt=18424'38174038 lcod 18424'38174037 mlcod 18424'38174037 active+clean] do_osd_op 201:3170be39:::.dir.772a65be-4b10-4862-832a-e55d1c05db84.5149179.1.33:head [omap-get-vals]
2018-12-11 23:45:14.041080 7f3ba076e700 10 osd.178 pg_epoch: 18424 pg[201.28c( v 18424'38174038 (18424'38172500,18424'38174038] local-lis/les=18173/18174 n=53 ec=1977/1977 lis/c 18173/18173 les/c/f 18174/18174/0 18173/18173/6366) [178,169] r=0 lpr=18173 crt=18424'38174038 lcod 18424'38174037 mlcod 18424'38174037 active+clean] do_osd_op  omap-get-vals

do_osd_op在此前已经做了交代，它负责实际执行op的ops，这里执行rgw.bucket_list中的omap的相关操作，前文也说到，操作对象**.dir.772a65be-4b10-4862-832a-e55d1c05db84.5149179.1.33**是bucket的一个shard对象，这个ceph环境中有将近33亿个图片对象，因此每个shard中的omap信息是极其多的

1
2
3
4
5
6
2018-12-11 23:45:14.995250 7f3ba076e700 20 osd.178 pg_epoch: 18424 pg[201.28c( v 18424'38174038 (18424'38172500,18424'38174038] local-lis/les=18173/18174 n=53 ec=1977/1977 lis/c 18173/18173 les/c/f 18174/18174/0 18173/18173/6366) [178,169] r=0 lpr=18173 crt=18424'38174038 lcod 18424'38174037 mlcod 18424'38174037 active+clean] Found key 1542422108.59126305580139160156.jpg

... 此处省略大量内容 ...

2018-12-11 23:45:15.003073 7f3ba076e700 20 osd.178 pg_epoch: 18424 pg[201.28c( v 18424'38174038 (18424'38172500,18424'38174038] local-lis/les=18173/18174 n=53 ec=1977/1977 lis/c 18173/18173 les/c/f 18174/18174/0 18173/18173/6366) [178,169] r=0 lpr=18173 crt=18424'38174038 lcod 18424'38174037 mlcod 18424'38174037 active+clean] Found key 1542422207.18930006027221679688.jpg
2018-12-11 23:45:15.012291 7f3ba076e700 10 osd.178 pg_epoch: 18424 pg[201.28c( v 18424'38174038 (18424'38172500,18424'38174038] local-lis/les=18173/18174 n=53 ec=1977/1977 lis/c 18173/18173 les/c/f 18174/18174/0 18173/18173/6366) [178,169] r=0 lpr=18173 crt=18424'38174038 lcod 18424'38174037 mlcod 18424'38174037 active+clean] method called response length=239834

日志到了这里，出现了大量的Found key xxx.jpg，看来是在shard文件中得到了图片文件的key，特别留意一下日志的时间戳，第一个Found key出现在

1
2018-12-11 23:45:14.995250

再看一下这条日志的上一条日志时间戳

1
2018-12-11 23:45:14.041080

时间差是多少呢？ 958ms ！！，看起来omap-get-vals这个操作是导致这个op处理缓慢的直接原因，先继续往下走，看看这个op的过程

1
2018-12-11 23:45:15.012313 7f3ba076e700 10 osd.178 pg_epoch: 18424 pg[201.28c( v 18424'38174038 (18424'38172500,18424'38174038] local-lis/les=18173/18174 n=53 ec=1977/1977 lis/c 18173/18173 les/c/f 18174/18174/0 18173/18173/6366) [178,169] r=0 lpr=18173 crt=18424'38174038 lcod 18424'38174037 mlcod 18424'38174037 active+clean]  dropping ondisk_read_lock

此日志出自PrimaryLogPG.cc:3266，位于execute_ctx函数内部，这里表示进行了判断，发现是read操作，所以释放了ondisk_read_lock，看起来读操作已经全部完成了

1
2018-12-11 23:45:15.012323 7f3ba076e700 15 osd.178 pg_epoch: 18424 pg[201.28c( v 18424'38174038 (18424'38172500,18424'38174038] local-lis/les=18173/18174 n=53 ec=1977/1977 lis/c 18173/18173 les/c/f 18174/18174/0 18173/18173/6366) [178,169] r=0 lpr=18173 crt=18424'38174038 lcod 18424'38174037 mlcod 18424'38174037 active+clean] do_osd_op_effects client.5533156 con 0x7f3be4f28000

do_osd_op_effects函数出自PrimaryLogPG.cc:7386，该函数在PrimaryLogPG.cc:3309被调用，位于execute_ctx函数内部，到这里，线程处理完读操作后，要验证一下op对osd的影响

1
2018-12-11 23:45:15.012336 7f3ba076e700 15 osd.178 pg_epoch: 18424 pg[201.28c( v 18424'38174038 (18424'38172500,18424'38174038] local-lis/les=18173/18174 n=53 ec=1977/1977 lis/c 18173/18173 les/c/f 18174/18174/0 18173/18173/6366) [178,169] r=0 lpr=18173 crt=18424'38174038 lcod 18424'38174037 mlcod 18424'38174037 active+clean] log_op_stats osd_op(client.5533156.0:77009385 201.28c 201:3170be39:::.dir.772a65be-4b10-4862-832a-e55d1c05db84.5149179.1.33:head [call rgw.bucket_list] snapc 0=[] ondisk+read+known_if_redirected e18424) v8 inb 0 outb 239834 lat 6.180145

此日志出自函数complete_read_ctx，位于PrimaryLogPG.cc:7766，在该函数的7787行进行了log_op_stats的调用，检查pglog状态，是否发生了更改等

1
2018-12-11 23:45:15.012351 7f3ba076e700 15 osd.178 pg_epoch: 18424 pg[201.28c( v 18424'38174038 (18424'38172500,18424'38174038] local-lis/les=18173/18174 n=53 ec=1977/1977 lis/c 18173/18173 les/c/f 18174/18174/0 18173/18173/6366) [178,169] r=0 lpr=18173 crt=18424'38174038 lcod 18424'38174037 mlcod 18424'38174037 active+clean] publish_stats_to_osd 18424:38258109

此日志出自函数complete_read_ctx，位于PrimaryLogPG.cc:7766，在该函数的7788行进行了publish_stats_to_osd的调用，公告作出修改后的pg状态

1
2018-12-11 23:45:15.012378 7f3ba076e700 10 osd.178 18424 dequeue_op 0x7f3c182da480 finish

完成op的全部处理，dequeue_op返回

1
2
3
// finish
dout(10) << "dequeue_op " << op << " finish" << dendl;
OID_EVENT_TRACE_WITH_MSG(op->get_req(), "DEQUEUE_OP_END", false);

至此，我们看看这个op花费的时间为

1
2018-12-11 23:45:15.012378 - 2018-12-11 23:45:14.040608 = 1.028230s

其中我们上面提到的omap-get-vals操作就花费了958ms，占整个op处理流程时间的93.19%

总结与分析

这个读op在do_osd_op中使用method->exec调用了op中的rgw.bucket_list，这个调用差不多1s才完成，在此期间，这个shard所在的pg 201.28c 以及这个shard本身进行了read lock，其他线程的write lock肯定是无法成功的，考虑到集群平均40k的ops，1s足以让很多op阻塞在队列中，再考虑其他pg的情况，slow的情况会变得更糟

下一步

这两篇文章里，我们分析了osd的一个读op处理流程的日志，从中发现了slow request的关键点在于某些op操作非常耗时，但是没有对这些op进行更深入的探究，例如这些op是什么操作触发？能否避免？能否减缓它的影响？等等，后续的文章中，会进一步深入探讨

参考资料

赏

谢谢你请我吃糖果

支付宝
微信
  • 本文作者： 奋斗的松鼠
  • 本文链接： http://www.strugglesquirrel.com/2018/12/19/看懂ceph日志系列之index-osd读流程-下/
  • 版权声明： 本博客所有文章除特别声明外，创作版权均为作者个人所有，未经允许禁止转载！

扫一扫，分享到微信

tag:

    缺失模块。
    1、请确保node版本大于6.2
    2、在博客根目录（注意不是yilia-plus根目录）执行以下命令：
    npm i hexo-generator-json-content --save

    3、在根目录_config.yml里添加配置： 

      jsonContent:
    meta: false
    pages: false
    posts:
      title: true
      date: true
      path: true
      text: false
      raw: false
      content: false
      slug: false
      updated: false
      comments: false
      link: false
      permalink: false
      excerpt: false
      categories: false
      tags: true

松鼠哥，存储研发专家
曾就职于深信服北京研发中心，负责存储相关产品的调研测试
在分布式存储领域深耕近十年，实战经验和理论经验功力深厚
累计管理及上线生产集群超过600个，机器超3万台，磁盘总数超过80万块，总容量达到EB级别。