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

2018-12-18

字数统计: 4.9k字 | 阅读时长≈ 23分

针对一些实际场景问题，采用生产环境的日志进行分析

写在前面

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

ceph是一个很复杂的系统，想要用好它，对它的脾性就要有很好的理解，才能在合适的时机做合适的事

作为ceph的开发、运维技术人员，应对ceph的各种日常事务，尤其是异常处理过程，都高度依赖ceph的日志，从日志中得到最直接有用的信息，从另外一方面来看，ceph的日志也为我们学习它提供了非常直观的资料，本系列打算以全部看懂ceph日志为目的主线，延伸到它原理的方方面面

怎么开始

笔者习惯是从问题出发，使用自顶向下，首先对对象有个宏观认识，再深入、延伸它的细枝末节

从slow request说起

近期，线上的ceph集群间歇性地出现slow request，严重的时候有超过5K个slow request，导致很多数据丢失，是比较严重的事件，借此，很有必要深入分析、探究slow request的原理

环境说明：

0、版本为luminous 12.2.7
1、184个osd，其中ssd-osd有16个，用作rgw的index等
2、集群已经使用了1211 TiB，全部都是100KiB-2MiB的小图片，总数为3197M objects
3、集群一天24小时都有图片写入，平均：31216 kB/s rd, 338 MB/s wr, 26284 op/s rd, 37211 op/s wr
4、集群每天都在删除30天前的数据，根据bucket的创建时间来删除
5、只使用了对象存储
6、分析对象为ssd osd，负责index等存储池
7、分析debug_osd 20/20的日志

有了上述背景交代，后续说明问题的时候也许就更容易理解一些

我们的场景总结为：持续高速写入，海量小文件存储，同时伴有高速旧文件删除，稍微熟悉存储的人都知道，海量文件存储一直是比较头疼的问题，况且一边疯狂写入一边疯狂删除，还要保证集群稳定，对存储本身提出了很高的要求

现场日志分析

出现slow request后，使用ceph health detail和ceph osd find x马上定位到slow的osd，发现slow都是ssd-osd，起初以为是rocksdb在进行compaction，导致写入阻塞，但是iostat -x 1看到，磁盘并不忙碌，开始分析对应osd的日志

使用ceph tell 'osd.178' injectargs '--debug_osd 20/20'打开对应osd的日志，得到下面的日志，通过跟踪其中一个线程的op处理过程，我们得以窥视ceph处理op的细枝末节

1	2018-12-11 23:45:14.040588 7f3ba076e700 20 osd.178 op_wq(4) _process 201.28c item PGQueueable(0x7f3c182da480 prio 63 cost 43 e18424) pg 0x7f3bf53f1000

这行日志出自OSD.cc:10531，格式为

1	dout(20) << __func__ << " " << item.first << " item " << *qi << " pg " << pg << dendl;

根据代码，此时osd线程从op队列获取到一个op，并开始处理这个op，但是在处理前，会进行pg lock操作：

// [lookup +] lock pg (if we have it)
if (!pg) {
  pg = osd->_lookup_lock_pg(item.first);
} else {
  pg->lock();
}

线程获得pg锁，才能进行对应的op，这里锁的粒度为pg，主要是为了保证pg的强一致性，在此op结束后回释放这个lock，然后再通过对比pg所有副本间的pglog来确定所有副本是不是一致的

2018-12-11 23:45:14.040608 7f3ba076e700 10 osd.178 18424 dequeue_op 0x7f3c182da480 prio 63 cost 43 latency 5.208418 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 pg 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]

dequeue_op函数出自OSD.cc:9800，日志格式为

dout(10) << "dequeue_op " << op << " prio " << op->get_req()->get_priority()
          << " cost " << op->get_req()->get_cost()
         << " latency " << latency
         << " " << *(op->get_req())
         << " pg " << *pg << dendl;

根据代码，线程成功获得pg lock并从queue中拿到了op，打印了op的基本信息，其中我们最关注的是latency，它的取值是latency = now - op->get_req()->get_recv_stamp()，也就是这个op等待了多久才开始被执行，这里，这个op等待时间为5.208418s，是一个非常大的值，而一个op默认超过32s就会被标记为slow request

另外，这里特别提一下操作对象.dir.772a65be-4b10-4862-832a-e55d1c05db84.5149179.1.33，它是rgw的index中的一个object，它就是bucket的所谓的shard文件，这次的slow request它肯定脱不了干系

2018-12-11 23:45:14.040648 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] _handle_message: 0x7f3c182da480

这里_handle_message表示op开始进入解析处理流程，没有深究

2018-12-11 23:45:14.040666 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] do_op: op 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

do_op函数出自PrimaryLogPG.cc:1855，在这里op会被初步检查，例如op的名称是否过长、对象是否正常、op是不是在黑名单等等，注意，这条日志的出处是位于主pg的文件中，另外还有一个副pg的代码文件ReplicatedBackend.cc，它们都是pg，但是主副pg的处理流程和职能有很大不同，因此分放在不同的代码文件中

2018-12-11 23:45:14.040697 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] op_has_sufficient_caps session=0x7f3bd87bd600 pool=201 (tupu-201-zone1.rgw.buckets.index ) owner=0 need_read_cap=0 need_write_cap=0 classes=[class rgw rd 1 wr 0 wl 1] -> yes

op_has_sufficient_caps函数出自PG.cc：1859，这条日志是op_has_sufficient_caps函数在do_op函数的1931行被调用，其作用是检查op是否有足够的权限对目标object进行操作，可以看到结果是yes

2018-12-11 23:45:14.040719 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_op 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 may_read -> read-ordered flags ondisk+read+known_if_redirected

这条日志出自PrimaryLogPG.cc:2033，这里线程判断op的具体操作类型，根据代码，操作类型有下面几种定义：

dout(10) << "do_op " << *m
     << (op->may_write() ? " may_write" : "")
     << (op->may_read() ? " may_read" : "")
     << (op->may_cache() ? " may_cache" : "")
     << " -> " << (write_ordered ? "write-ordered" : "read-ordered")
     << " flags " << ceph_osd_flag_string(m->get_flags())
     << dendl;

从日志看来，这个op是may_read的，也就是进行读操作，并且有read-ordered的flags

2018-12-11 23:45:14.040752 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] get_object_context: found obc in cache: 0x7f3bff9782c0

get_object_context函数出自PrimaryLogPG.cc:9903，这个函数查找给定对象的上下文objectcontext，用于确定这个对象是不是可以操作，同时，obc必须在内存中，也就是已经cache，如果不是，则需要从磁盘上先刷到内存中才行

objectcontext是一个对象的上下文，简单理解就是对象的实时情况表，它记录了对象当前的各种状态信息，例如现在是否正在处理其他请求，是否上锁等等，它的定义在osd_internal_types.sh:42有详细的说明

关于objectcontext，这篇文章讲得非常好

2018-12-11 23:45:14.040766 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] get_object_context: 0x7f3bff9782c0 201:3170be39:::.dir.772a65be-4b10-4862-832a-e55d1c05db84.5149179.1.33:head rwstate(none n=0 w=0) oi: 201:3170be39:::.dir.772a65be-4b10-4862-832a-e55d1c05db84.5149179.1.33:head(18424'38174038 client.5558163.0:173766639 dirty|omap s 0 uv 38174038 alloc_hint [0 0 0]) exists: 1 ssc: 0x7f3bd75fd320 snapset: 0=[]:{}

这条日志在get_object_context函数中打印，确定给定的object是存在的，并且得到这个object的上下文了，这里有个值得注意的地方，是**rwstate(none n=0 w=0)**，它显示了对象上下文中记录的状态，日志的格式为

inline ostream& operator<<(ostream& out, const ObjectContext::RWState& rw)
{
  return out << "rwstate(" << rw.get_state_name()
         << " n=" << rw.count
         << " w=" << rw.waiters.size()
         << ")";
}

inline ostream& operator<<(ostream& out, const ObjectContext& obc)
{
  return out << "obc(" << obc.obs << " " << obc.rwstate << ")";
}

可以看到，n表示的是获取了rw lock的数量，而w表示正在等待获取rw lock的数量

在osd_internal_types.sh:62有详细的说明关于rwstat的类型，这里再延伸一下：

struct RWState {
  enum State {
    RWNONE,
    RWREAD,
    RWWRITE,
    RWEXCL,
  };
  static const char *get_state_name(State s) {
    switch (s) {
    case RWNONE: return "none";
    case RWREAD: return "read";
    case RWWRITE: return "write";
    case RWEXCL: return "excl";
    default: return "???";
    }
  }
  ...
// do simple synchronous mutual exclusion, for now.  no waitqueues or anything fancy.
void ondisk_write_lock() {
  lock.Lock();
  writers_waiting++;
  while (readers_waiting || readers)
    cond.Wait(lock);
  writers_waiting--;
  unstable_writes++;
  lock.Unlock();
}
void ondisk_write_unlock() {
  lock.Lock();
  assert(unstable_writes > 0);
  unstable_writes--;
  if (!unstable_writes && readers_waiting)
    cond.Signal();
  lock.Unlock();
}
void ondisk_read_lock() {
  lock.Lock();
  readers_waiting++;
  while (unstable_writes)
    cond.Wait(lock);
  readers_waiting--;
  readers++;
  lock.Unlock();
}
void ondisk_read_unlock() {
  lock.Lock();
  assert(readers > 0);
  readers--;
  if (!readers && writers_waiting)
    cond.Signal();
  lock.Unlock();
}

根据代码，object的上下文提供了对这个object的访问控制，定义了lock的类型和不同锁获取的算法，从中可以看到，读读和写写是可以并发的，而读写混合是不支持并发的，关于object的锁机制，这里的文章讲得非常好，本文就不扯远了，专注读懂日志

2018-12-11 23:45:14.040796 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] find_object_context 201:3170be39:::.dir.772a65be-4b10-4862-832a-e55d1c05db84.5149179.1.33:head @head oi=201:3170be39:::.dir.772a65be-4b10-4862-832a-e55d1c05db84.5149179.1.33:head(18424'38174038 client.5558163.0:173766639 dirty|omap s 0 uv 38174038 alloc_hint [0 0 0])

find_object_context函数出自PrimaryLogPG.cc:10035，该函数在do_op函数的2152行被调用，目的是获取到对象的objectcontext

2018-12-11 23:45:14.040833 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] do_op obc obc(201:3170be39:::.dir.772a65be-4b10-4862-832a-e55d1c05db84.5149179.1.33:head rwstate(read n=1 w=0))

这条日志出自PrimaryLogPG.cc:2305，根据代码，到这里，说明已经得到了rw lock或者不需要lock：

if (m->has_flag(CEPH_OSD_FLAG_SKIPRWLOCKS)) {
  dout(20) << __func__ << ": skipping rw locks" << dendl;
} else if (m->get_flags() & CEPH_OSD_FLAG_FLUSH) {
  dout(20) << __func__ << ": part of flush, will ignore write lock" << dendl;

  // verify there is in fact a flush in progress
  // FIXME: we could make this a stronger test.
  map<hobject_t,FlushOpRef>::iterator p = flush_ops.find(obc->obs.oi.soid);
  if (p == flush_ops.end()) {
    dout(10) << __func__ << " no flush in progress, aborting" << dendl;
    reply_ctx(ctx, -EINVAL);
    return;
  }
} else if (!get_rw_locks(write_ordered, ctx)) {
  dout(20) << __func__ << " waiting for rw locks " << dendl;
  op->mark_delayed("waiting for rw locks");
  close_op_ctx(ctx);
  return;
}
dout(20) << __func__ << " obc " << *obc << dendl;

如果这里检查到对象的rwstat不符合要求，这个op就会立即进入delay队列，延迟处理，后续会看到，大量slow request的op会在这里进行这个处理，日志显示**”waiting for rw locks”，使得op的latency变得更长，这里的rwstate(read n=1 w=0))**，可以看到n=1了，对比上两条日志，也说明对象的rw lock已经成功

2018-12-11 23:45:14.040852 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] execute_ctx 0x7f3c2549fc00

execute_ctx函数出自PrimaryLogPG.cc:3187，execute_ctx函数在do_op的2347行被调用，这是do_op的核心处理函数，此前所有的检查和预处理，都是为了这个函数的执行作铺垫，跟着日志再进去看看

2018-12-11 23:45:14.040867 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] execute_ctx 201:3170be39:::.dir.772a65be-4b10-4862-832a-e55d1c05db84.5149179.1.33:head [call rgw.bucket_list] ov 18424'38174038

这条日志出自PrimaryLogPG.cc:3227，位于execute_ctx函数内部，这里表示op不是写或者cache操作

2018-12-11 23:45:14.040886 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]  taking ondisk_read_lock

此日志出自PrimaryLogPG.cc:3243，位于execute_ctx函数内部，这里表示进行了判断，发现是read操作，这里的ondisk_read_lock就是前面看到的objectcontext中的其中一个方法，它在获取object的rw lock后，再获得磁盘的read lock

根据代码，在execute_ctx函数的3255行调用了prepare_transaction，然后prepare_transaction函数中被调用了do_osd_op函数，prepare_transaction函数出自PrimaryLogPG.cc:7496

2018-12-11 23:45:14.040898 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 [call rgw.bucket_list]

do_osd_op函数出自PrimaryLogPG.cc:5065，do_osd_op函数是prepare_transaction的核心，负责处理主要任务，这条日志的格式为

1	dout(10) << "do_osd_op " << soid << " " << ops << dendl;

进入do_osd_op表示一切准备就绪，op的操作即将进行

2018-12-11 23:45:14.040914 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  call rgw.bucket_list

这条日志出自do_osd_op函数内部，位于PrimaryLogPG.cc:5098，打印即将进行的op调用，接下来会开始op的执行

2018-12-11 23:45:14.040935 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] call method rgw.bucket_list

日志出自do_osd_op函数内部，位于PrimaryLogPG.cc:5272，对op的实际执行就是在这里进行的

...
int flags = method->get_flags();
if (flags & CLS_METHOD_WR)
  ctx->user_modify = true;

bufferlist outdata;
dout(10) << "call method " << cname << "." << mname << dendl;
int prev_rd = ctx->num_read;
int prev_wr = ctx->num_write;
result = method->exec((cls_method_context_t)&ctx, indata, outdata);
...
dout(10) << "method called response length=" << outdata.length() << dendl;
op.extent.length = outdata.length();
osd_op.outdata.claim_append(outdata);
dout(30) << "out dump: ";
osd_op.outdata.hexdump(*_dout);
*_dout << dendl;

对于op中的操作，这里看到是使用method对象的exec方法来实际执行函数的，参数为indata，将输出结果存放在outdata中，并在后续处理中看到，会输出处理结果的长度等信息

分析到这里，处理流程开始进入执行op执行函数的环节，是一个明显的阶段，先做个小结，再往下继续

阶段性总结

首先，op到达osd后，会进入op的队列，这个队列由下面的相关参数控制：

1 2	osd_op_num_shards:Number of queues to requests osd_op_num_threads_per_shard:Threads number for each queue

然后，osd的op线程从队列中取出一个op，在取出的同时，会对操作的目标pg加锁，防止其他op线程对这个pg进行并发操作，日志关键字为**_process pgid item PGQueueable**，它是op开始的第一条日志

接下来进入dequeue_op函数，此时op被正式开始处理，我们比较关注latency字段，它表示op等了多久才被处理，通常几个ms被处理是正常的，被操作对象和操作的op函数有时候也能提供很有用的信息，日志关键字为dequeue_op

接下来，op线程会对op的各项指标进行检测，包括op的名称长度、操作权限、操作类型等，都符合要求就会往下走，日志关键字为_handle_message、do_op: op osd_op、op_has_sufficient_caps

接下来，op线程会判断op的操作类型，因为操作类型决定了操作对象的锁的类型，在操作前需要获取对应的锁，日志关键字为may_read、may_write等

接下来，op线程检查、获取被操作对象的上下文，如果这个上下文已经cache，也就是内存中，就可以直接获取到，如果不在，则需要等待上下文从磁盘中获取，日志关键字为get_object_context、find_object_context，通过检查对象的上下文，op线程得知对象的rwstat，进而判断这个op操作与对象现在的状态是否互斥，互斥的话，就将op放入delay队列，暂不处理

对于不互斥的操作，例如读读，则会进一步执行op，日志关键字为execute_ctx，在这个函数内部进行操作锁的获取，关键字为taking ondisk_read_lock

接下来，得到锁之后，会执行op的ops，其执行是在do_osd_op中执行的

接下来，在do_osd_op中，调用了**method->exec()**对op中的字符串类型的函数进行转换并执行，进入op操作函数的执行范围

到这里，我们第一部分的日志分析完了，上述osd.178的日志中可以看到，这一阶段的开始时间为

1	2018-12-11 23:45:14.040588

而执行op调用的时间为

1	2018-12-11 23:45:14.040935

总共耗时0.347ms，操作可以说很快了，初步判断这部分流程不是造成slow的原因

参考资料

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