简介

一、查ceph自带的统计

1 命令格式

2 dump 命令输出结果

二、自己添加统计

三、分析案例

io耗时初分析

继续分析

进一步分析

代码修改和验证

四、报错记录

五、附录

1、代码修改和验证

作者:bandaoyu 本文持续更新,源地址：https://blog.csdn.net/bandaoyu/article/details/120913194

即看即用

查看

ceph daemon osd.10 perf dump

输出osd.N的统计信息: ceph daemon osd.N perf dump

重置osd.N的统计信息:ceph daemon osd.N perf reset all

增加统计项

#include "common/perf_counters.h"enum {l_os_first = 84000,l_os_jq_max_ops,...l_os_queue_lat,l_os_nc_used_bytes, // add by skdkjzz l_os_last,
};PerfCountersBuilder my_plb(cct, "myStatName", l_os_first , l_os_last);#加入项目标记add_u64_counter：计数的，add_time_avg：求平均时间的my_plb.add_u64_counter(l_os_jq_max_ops, "test_count");my_plb.add_time_avg(l_os_queue_lat, "latency", "after dequeue latency",   "wadl", perf_prio);perf_logger = my_plb.create_perf_counter();#计数统计，在需要增加或者减少 l_os_jq_max_ops的地方调用函数 inc or decperf_logger ->inc(l_os_jq_max_ops,num); #inc为增加,增加num
perf_logger ->dec(l_os_jq_max_ops,num);#dec为减少,减少num#求平均值，起始一个begin，后面累加tinc
perf_logger ->begin_inc(l_os_queue_lat);
perf_logger ->tinc(l_os_queue_lat,dur_t);

Perf具体的计算函数，包括set()、tset()、inc()、tinc()、dec()

这些函数都有一个参数: int idx, 就是前面我们定义的enum类型的具体指标。函数首字母是’t’的是关于time的处理。
set()/tset()：设置一个值。
inc()/tinc(): 增加，如果给定了增加多少，就增加具体的值；如果没有指定增加多少，+1.
dec(): 减少，如果给定了减少的值，就减少多少；如果没有指定，-1

32：将test_perfcounter子模块中的所有指标都清0

34-35：在perf counter集合的层面上清空，其实内部最后还是调用的PerfCounter::reset(), 也就是32行的调用函数

PerfCounterCollection::reset(string name)函数中的参数如果是”all”的话，perf集合会遍历所有的perf counter，依次调用reset();
参数可以是具体的perf counter子模块名，就只清空该模块，比如reset(“test_perfcounter”)
————————————————
版权声明：本文为CSDN博主「bandaoyu」的原创文章，遵循CC 4.0 BY-SA版权协议，转载请附上原文出处链接及本声明。
原文链接：https://blog.csdn.net/bandaoyu/article/details/120913194

简介

Ceph 性能计数器（ performance counters ）是内部模块指标的收集统计器。它采集到的数据可以通过各种工具收集、聚合和绘图，可用于性能分析。

Ceph mon和 OSD 等进程的性能计数器有专门的socket接口供其他工具连接和交互。默认情况下，每个进程的套接字文件位于 /var/run/ceph 下。性能计数器被组合到集合名称中。这些集合名称代表一个子系统或子系统的一个实例。
以下是监视器、OSD 和 RADOS 网关集合名称类别的完整列表，以及每个类别的简要说明：

https://access.redhat.com/documentation/en-us/red_hat_ceph_storage/1.3/html/administration_guide/performance_counters

一、查ceph自带的统计

1 命令格式

perf dump命令将输出 ceph中 PERF COUNTERS 的统计信息

ceph daemon xxx.id perf dump 命令

如:

ceph daemon osd.10 perf dump

ceph 提供了许多非常的工具，今天简单介绍一下获取OSD统计信息的工具。通过该命令可以让我们更直观的看到OSD的一些信息。

输出osd.N的统计信息: ceph daemon osd.N perf dump

重置osd.N的统计信息:ceph daemon osd.N perf reset all

2 dump 命令输出结果

该命令会输出一个json格式的结果，通过对结果的分析，我们可以很好的得到osd的运行状态,比如读写操作的延时、操作队列的长度，数据恢复，操作计数等信息，部分统计字段如下：
(字段含义见后面章节)

{"WBThrottle": {"bytes_dirtied": 0,"bytes_wb": 17505569440,"ios_dirtied": 0,"ios_wb": 12112,"inodes_dirtied": 0,"inodes_wb": 12112},"filestore": {"journal_queue_max_ops": 50000,"journal_queue_ops": 0,"journal_ops": 57187,"journal_queue_max_bytes": 33554432,"journal_queue_bytes": 0,"journal_bytes": 22842879961,"journal_latency": {"avgcount": 57187,"sum": 322.201043018},"journal_wr": 52269,"journal_wr_bytes": {"avgcount": 52269,"sum": 23029956608},"journal_full": 0,"committing": 0,"commitcycle": 346,"commitcycle_interval": {"avgcount": 346,"sum": 5199.707915189},"commitcycle_latency": {"avgcount": 346,"sum": 7.791222630},"op_queue_max_ops": 25000,"op_queue_ops": 0,"ops": 57187,"op_queue_max_bytes": 10485760,"op_queue_bytes": 0,"bytes": 22842079343,"apply_latency": {"avgcount": 57187,"sum": 2242.084968391},"queue_transaction_latency_avg": {"avgcount": 57187,"sum": 70.085438088}},"leveldb": {"leveldb_get": 37522,"leveldb_transaction": 159445,..."leveldb_compact_queue_len": 0},"objecter": {...},"osd": {..."op_latency": {"avgcount": 25670,"sum": 1126.046253167      },"subop_push": 0,"subop_push_in_bytes": 0,"subop_push_latency": {"avgcount": 0,"sum": 0.000000000},"pull": 0,..."copyfrom": 6478,...}
}

Ceph daemon osd perf dump 命令：https://blog.csdn.net/c744402859/article/details/53223412

二、添加统计项目

PerfCounters添加步骤，以FileStore，统计增减最终结果为例：

1、在需要使用的cc文件中添加头文件：
#include "common/perf_counters.h"

2、添加统计项目的enum

ObjectStore中有enum枚举，注意枚举中的第一个元素与最后一个元素，这是给PerfCountersBuilder使用的（如：PerfCountersBuilder my_plb(cct, "myStatName", l_os_first , l_os_last);）

我们自己添加自己想要的元素需要注意必须在l_os_first 与 l_os_last之间添加！

enum {l_os_first = 84000,l_os_jq_max_ops,...l_os_queue_lat,l_os_nc_used_bytes, // add by skdkjzz l_os_last,
};

3、

#创建一个自己的counter build：my_plb并加入项目

PerfCountersBuilder my_plb(cct, "myStatName", l_os_first , l_os_last);

#加入项目标记add_u64_counter：计数的，add_time_avg：求平均时间的

my_plb.add_u64_counter(l_os_jq_max_ops, "test_count");

my_plb.add_time_avg(l_os_queue_lat, "latency", "after dequeue latency", "wadl", perf_prio);

#创建counter

perf_logger = my_plb.create_perf_counter();

#在需要增加或者减少 l_os_jq_max_ops的地方调用函数 inc or dec

perf_logger ->inc(l_os_jq_max_ops,num); #inc为增加,增加num
perf_logger ->dec(l_os_jq_max_ops,num);#dec为减少,减少num

#求平均值，起始一个begin，后面累加tinc
perf_logger ->begin_inc(l_os_queue_lat);
perf_logger ->tinc(l_os_queue_lat,dur_t);

至此，完成添加！

原文链接：https://blog.csdn.net/skdkjzz/article/details/52106585

例子2：Ceph内建辅助工具实践：http://aspirer.wang/?p=1456

例子3：打点统计均值

1、在Engine.h定义计数的变量的id：l_row_flush_op_lat

enum {
l_engine_first = 100000,

……

l_row_flush_op_lat,
……

l_engine_last,
};

2、创建变量并和id绑定，创建create_perf_counters

add_u64_counter：计数的

add_time_avg：求平均时间的
void EngineService::engine_create_logger()
{
dout(2) << "engine_create_logger" << dendl;

PerfCountersBuilder engine_plb(ecct, "engine", l_engine_first, l_engine_last);

engine_plb.set_prio_default(PerfCountersBuilder::PRIO_USEFUL);
engine_plb.add_u64_counter(
l_engine_op, "op",
"Client operations",
"ops", PerfCountersBuilder::PRIO_CRITICAL);

engine_plb.add_time_avg(
l_engine_op_lat, "engine_op_latency",
"Latency of client operations (including queue time)",
"l", 9);

……

engine_plb.add_time_avg(
l_row_obj_write_lock_hold_lat, "row_obj_write_lock_hold_lat",
"Latency of row_obj_write_lock_hold_lat operation (including queue time)");

// 优先级为调试级别的时延点添加在本行代码后面
engine_plb.set_prio_default(PerfCountersBuilder::PRIO_DEBUGONLY);

logger = engine_plb.create_perf_counters();
ecct->get_perfcounters_collection()->add(logger);
}

{

#做某事前调用begin_inc

eng->logger->begin_inc(l_row_flush_op_lat);----->begin_count++;

（做某事）
#做某事后调用tinc
eng->logger->tinc(l_row_flush_op_lat, ceph_clock_now() - start);--->表示把第二个参数的值累加到l_row_flush_op_lat绑定的value上，avgcount++,第3个参数=1，表示算均值
}

重复执行上面多次，最终会累加值value/次数avgcount = 均值。

void PerfCounters::begin_inc(int idx)
{if (!m_cct->_conf->perf)return;assert(idx > m_lower_bound);assert(idx < m_upper_bound);perf_counter_data_any_d& data(m_data[idx - m_lower_bound -1]);if (!(data.type & PERFCOUNTER_TIME))return;if (data.type & PERFCOUNTER_LONGRUNAVG) {data.begin_count++;}
}void PerfCounters::tinc(int idx, ceph::timespan amt, uint32_t avgcount)
{if (!m_cct->_conf->perf)return;assert(idx > m_lower_bound);assert(idx < m_upper_bound);perf_counter_data_any_d& data(m_data[idx - m_lower_bound - 1]);if (!(data.type & PERFCOUNTER_TIME))return;if (data.type & PERFCOUNTER_LONGRUNAVG) {data.avgcount++;data.u64 += amt.count();data.avgcount2++;if (data.max_time < amt.count() / 1000) {data.max_time = amt.count() / 1000;}if(0 != ratio_switch){map<uint64_t, uint64_t>::iterator iter;for(iter = data.latency_ratio.begin(); iter != data.latency_ratio.end(); ++iter){if(amt.count() / 1000 <= iter->first){iter->second++;break;}}}} else {data.u64 += amt.count();}
}

ceph perf counter 源码分析及使用
示例


enum {
t_perfcounter_first = 200,
test_perfcounter_count,
test_perfcounter_time,
test_perfcounter_sum,
test_perfcounter_last,
};PerfCountersCollection *coll = g_ceph_context->get_perfcounters_collection();PerfCountersBuilder test_plb(g_ceph_context, "test_perfcounter", test_perfcounter_first, test_perfcounter_last);test_plb.add_u64_counter(test_perfcounter_count, "test_count");
test_plb.add_time(test_perfcounter_time, "test_time", "Time of system service");
test_plb.add_u64(test_perfcounter_sum, "test_sum", "Sum of variable", "wr_bytes_sum");test_logger = test_plb.create_perf_counters();coll->add(test_plb);test_logger->set(test_perfcounter_count, 1);
test_logger->tset(test_perfcounter_time, utime_t(0, 1));
test_logger->set(test_perfcounter_sum, 1);test_logger->inc(test_perfcounter_count);
test_logger->tinc(test_perfcounter_time, utime_t());
test_logger->inc(test_percounter_sum, 10);test_logger->dec(test_perfcounter_count);
test_logger->dec(test_perfcounter_sum, 5);test_logger->reset();coll->reset(string("test_perfcounter"));
coll->reset(string("all"));
coll->remove(test_logger);
coll->clear();

分析
1-7：定义一个枚举型

enum {
t_perfcounter_first = 200,
test_perfcounter_count,
test_perfcounter_time,
test_perfcounter_sum,
test_perfcounter_last,
};

定义一个枚举型，在使用perf counter的时候，每一个couter会有一个data size，也就是有多少个perf counter对象，所以都会定义一个enum，enum的第一个和最后一个元素是必须要有的（也就是first和last），然后我们要计算perf的指标都定义在这两个enum元素之间就OK。

9：定义了一个PerfCounterCollection对象，该类中有perf_counters_set_t m_loggers成员变量，该类是多个PerfCounter子模块的集合，所有的Perf counter模块都在这个集合中。

11：定义了一个PerfCountersBuilder对象，该类中有PerfCounters *m_perf_counters成员变量。

m_perf_counters变量在实例化类的时候，通过类的构造函数初始化了，初始化：new PerfCounters(cct, name, first, last)，实例化一个PerfCounters对象。

PerfCounters类中有perf_counter_data_vec_t m_data及int m_lower_bound, int m_upper_bound, string m_name;

PerfCounters类的构造函数：PerfCounters::PerfCounters(CephContext *cct, const std::string &name, int lower_bound, int upper_bound)，构造函数的参数中的name是计算perf子模块的名称, 在这里就是”test_perfcounter”, lower_bound和high_bound是我们要跟踪计算perf的子模块的上下界限，主要是为了调整m_data(是一个vector)的长度。

13-15：将具体的跟踪指标(test_perfcounter_count等)加入到跟踪子模块（test_perfcounter）中。

根据不同的指标的类型不同，调用的函数也不同，也是根据不同的类型来区分的。这些函数最后还是调用同样的函数：add_impl(idx, name, description, nick, PERFCOUNTER_U64);只是最后这个type参数不同。目前根据time、普通数值、计量值来区分，分别有add_time()、add_u64()、add_u64_counter().

add_impl(…)函数如下：

   PerfCounters::perf_counter_data_vec_t &vec(m_perf_counters->m_data);PerfCounters::perf_counter_data_any_d&data(vec[idx - m_perf_counters->m_lower_bound - 1]);assert(data.type == PERFCOUNTER_NONE);data.name = name;data.description = description;data.nick = nick;data.type = (enum perfcounter_type_d)ty;

0: 取m_data的值
1-2：取m_data中的和具体的跟踪指标对应index的值
4-7：给m_data对应的index位置赋值，从上层传下来的关于这个指标的信息，主要是index、指标名称、指标描述信息、指标的别名、指标类型

17：返回一个完整perf counter的PerfCounter类型的m_perf_counters；上面关于perf指标的操作都是为了创建一个完整的PerfCounter对象。

 PerfCounters *PerfCountersBuilder::create_perf_counters(){PerfCounters::perf_counter_data_vec_t::const_iterator d = m_perf_counters->m_data.begin();PerfCounters::perf_counter_data_vec_t::const_iterator d_end = m_perf_counters->m_data.end();for (; d != d_end; ++d) {if (d->type == PERFCOUNTER_NONE) {assert(d->type != PERFCOUNTER_NONE);}}PerfCounters *ret = m_perf_counters;m_perf_counters = NULL;return ret;}

19：将新的Perf Counter字模块加入Perf Counters集合中。

21-30： Perf具体的计算函数，包括set()、tset()、inc()、tinc()、dec()

32：将test_perfcounter子模块中的所有指标都清0

34-35：在perf counter集合的层面上清空，其实内部最后还是调用的PerfCounter::reset(), 也就是32行的调用函数

36: 从perf counter集合中删除某个子perf counter模块

37: 从perf counter集合中删除所有的perf counter模块

参考
ceph源代码: test/perf_counters.cc

原文链接：https://blog.csdn.net/ygtlovezf/article/details/76260251

三、分析案例

原文：Ceph性能瓶颈分析与优化(rbd篇) - 知乎

希望通过对ceph的性能瓶颈点进行分析，从而找到io路径主要性能瓶颈点，进而对ceph的性能做相应的优化。

ceph的性能瓶颈分析与优化一直是一个难点，因为优化性能这个事情本身是没有一成不变的可供参考的例子，比如一些朋友提供了ceph配置优化的建议，但是这种优化是基于特定硬件以及特定环境的，是不可复制的。我个人理解的是如果期望对性能瓶颈进行分析并进行优化，最好的办法便是通过ceph的io日志或者是各个阶段的延迟的监控指标，进而找到耗时比较长的点，然后针对此做出优化(当然，做这个事情的前提便是需要对ceph的io路径比较熟悉，同时由于ceph相关日志与指标项可能不是很全，必要时需要自己添加)。

io耗时初分析

这里是利用fio来测试，fio测试主要是有几个阶段的耗时：

fio工具发起请求到librbd接收到请求的耗时；
librbd️接收到请求到向osd发送出请求的耗时；
osd处理io的耗时；
osd发送reply给client；client接收到的耗时；
client给应用(fio)回复的耗时

所以这里我们期望通过ceph提供的延时阶段来大概看到哪个阶段是主要耗时点：

// fio命令-- fio整个IO耗时是（均值）15ms左右(lat (msec): min=1, max=47, avg=15.08)

// fio命令-- fio整个耗时是15ms左右
username@hostname:/#  fio -filename=/dev/nbd0 -direct=1 -iodepth=128 -rw=randwrite -ioengine=libaio -bs=4k -time_based -numjobs=1 -name="test" -runtime=3
test: (g=0): rw=randwrite, bs=4K-4K/4K-4K/4K-4K, ioengine=libaio, iodepth=128
fio-2.16
Starting 1 process
Jobs: 1 (f=1): [w(1)] [-.-% done] [0KB/34116KB/0KB /s] [0/8529/0 iops] [eta 00m:00s]
test: (groupid=0, jobs=1): err= 0: pid=1173687: Thu Sep 17 14:10:08 2020write: io=102280KB, bw=33935KB/s, iops=8483, runt=  3014msecslat (usec): min=1, max=2238, avg= 9.73, stdev=19.80clat (msec): min=1, max=47, avg=15.07, stdev= 2.25lat (msec): min=1, max=47, avg=15.08, stdev= 2.25

// librbd耗时

sudo ceph daemon /var/run/ceph/ceph-client.828073.asok perf dump #（**.asok 可以在/var/run/ceph下面查到）
// wr_latency是librbd收到fio的请求到发送给osd，再到收到回复并准备返回给应用io完成的整个耗时
// 可以看到fio的延时与如下wr_latency延时（ "avgtime": 0.014859839）基本相当，都是十几毫秒。这也就证明了fio应用与rbd交互本身耗时很短

（主要耗时在<librbd--请求-->IO操作--回复-->librbd>）

username@hostname:/# sudo ceph daemon /var/run/ceph/ceph-client.828073.asok  perf dump
"librbd-16bdd26b8b4567-rbd-volume-nbd": {"wr": 25570,"wr_bytes": 104734720,"wr_latency": {"avgcount": 25570,"sum": 379.966093228,"avgtime": 0.014859839},

// 所以一个想法便是既然写延时这么高，那么这个延时是发生在osd侧么？
// 所以测试前清空osd的perf，然后fio完查看vim

#1、清空osd的perf统计

username@hostname# for i in {0,3,4,5,6};do sudo ceph daemon osd.${i} perf reset all ;done

#2、执行fio

username@hostname# fio fio_w.conf

#3、读出新的统计
username@hostname# for i in {0,3,4,5,6};do sudo ceph daemon osd.${i} perf dump ;done > io_perf_osd ; cat io_perf_osd | grep -A 3 op_latency ; cat io_perf_osd | grep -A 3 op_w_process

// op_latency即是osd收到io到整个io完成的整个时间段
"op_latency": {
"avgcount": 1834,
"sum": 2.175986444,
"avgtime": 0.001186470
--
// subop_latency是本osd处理副本op的耗时
"subop_latency": {
"avgcount": 3005,
"sum": 1.671269352,
"avgtime": 0.000556162
……

脚本：

for i in {2,8,14,22}
do
ceph daemon osd.${i} perf reset all
done

for i in {2,14,22,8}
do
ceph daemon osd.${i}  perf dump
done  > io_perf_osd
cat io_perf_osd | grep -A 3 op_latency
cat io_perf_osd | grep -A 3 op_w_proces

从上面数据可知，op_latency的时延在一两毫秒，所以这也就表明了延时不在osd侧

继续分析

由于耗时主要不是在osd端，这里首先想到的便是网络繁忙等导致的网络延时或者是客户端回调(finish线程是单线程的)会耗时比较高。所以想到的是获取到op开始准备好发送给osd(_session_op_assign函数)到收到返回并处理完成的时间(_session_op_remove)，那么通过打印出这两个函数的日志，然后看他们的间隔就知道这个阶段的耗时了，如下：

// 如果要查看以下日志，需要把debug_objecter设置为15
username@hostname:/# cat ceph-client.828073.log   | egrep "_session_op_assign|_session_op_remove" |sort -k 8  2020-09-17 10:38:50.549806 7f639d009040 15 client.1500594.objecter _session_op_assign 8 1(每个io有一个唯一的tid)
2020-09-17 10:38:50.550629 7f638de72700 15 client.1500594.objecter _session_op_remove 8 1
......
......
2020-09-17 10:39:27.235067 7f63777fe700 15 client.1500594.objecter _session_op_assign 7 9998(每个io有一个唯一的tid)
2020-09-17 10:39:27.237152 7f638de72700 15 client.1500594.objecter _session_op_remove 7 9998
2020-09-17 10:39:27.235110 7f63777fe700 15 client.1500594.objecter _session_op_assign 1 9999
2020-09-17 10:39:27.237156 7f638ce70700 15 client.1500594.objecter _session_op_remove 1 9999

从上面日志片段可以看出，这两个函数相隔的时间也都不算多，跟后端osd处理时间差不太多，所以肯定是rbd从收到op到发送给osd之前这个阶段耗时比较长。

其实如果单纯想看是不是finish回调比较慢，可以通过perf dump里面提供的finish的信息便可以知道，但是finishi队列排队个数以及平均完成时间均很小，所以显然finish回调耗时不长

"finisher-radosclient": {"queue_len": 2,  // finishi队列排队个数"complete_latency": {"avgcount": 9942995,"sum": 80.688346845,"avgtime": 0.000008115 // 平均完成时间}},

进一步分析

如果期望做进一步分析，需要对io流程有一个初步的梳理，如下：

Image::write
->ImageRequestWQ<I>::write-> ImageRequestWQ<I>::aio_write-> ImageRequest<I>::aio_write-> queue() // 把io丢到队列io_work_queue// 工作线程从io_work_queue队列取出io后调用ImageRequest<I>::send()
工作线程（io_work_queue = new io::ImageRequestWQ<>）：ImageRequestWQ<I>::processImageRequest<I>::send()
->AbstractImageWriteRequest<I>::send_request()->AbstractImageWriteRequest<I>::send_object_requests--> journal开启--> journal未开启AbstractObjectWriteRequest<I>::send()--> AbstractObjectWriteRequest<I>::pre_write_object_map_update()--> AbstractObjectWriteRequest<I>::write_object--> image_ctx->data_ctx.aio_operate--> librados::IoCtx::aio_operate--> librados::IoCtxImpl::aio_operate--> Objecter::op_submit // 向主osd发送io// 收到主osd的io回复
Objecter::ms_dispatch(Message *m)
-> Objecter::handle_osd_op_reply-> onfinish->complete(rc) // 丢finish队列，finish处理回调

从上面的io路径发现一个关键点，也就是io会先丢到队列io_work_queue的，然后工作线程再从队列里面取出io进行处理。这里因为经过队列以及线程的转换，往往可能是瓶颈所在，所以期望查看io丢队列前到工作线程拿到io准备处理这个阶段的耗时。正好他们分别对应着函数ImageRequestWQ::aio_write以及ImageRequest::send()，所以希望从日志里面找到这两个时间点的间隔

// 这个对应着ImageRequestWQ<I>::aio_write的调用次数
username@hostname:/# sudo cat  /var/log/ceph/ceph-client.828073.log  |egrep 'aio_write' |grep -v send    | wc -l
25644// 这个对应着ImageRequest<I>::send()次数
username@hostname:/# sudo cat  /var/log/ceph/ceph-client.828073.log  |egrep 'send: aio_write'    | wc -l
25644

ImageRequestWQ::aio_write函数会调用ImageRequest::send()函数，所以他们的调用次数是一样的。这没问题，但是细细分析我们发现，日志里很多时候多个aio_write函数后才会有send()函数，本来一个aio_write函数后会跟着一个send，这说明了io在aio_write到send之间发生了等待以及阻塞

void ImageRequestWQ<I>::aio_write(AioCompletion *c, uint64_t off, uint64_t len,bufferlist &&bl, int op_flags,bool native_async)
{c->init_time(util::get_image_ctx(&m_image_ctx), AIO_TYPE_WRITE);// 关键日志的打印ldout(cct, 20) << "ictx=" << &m_image_ctx << ", "<< "completion=" << c << ", off=" << off << ", "<< "len=" << len << ", flags=" << op_flags << dendl;RWLock::RLocker owner_locker(m_image_ctx.owner_lock);if (m_image_ctx.non_blocking_aio || writes_blocked()) {queue(ImageRequest<I>::create_write_request(m_image_ctx, c, {{off, len}}, std::move(bl), op_flags, trace));} else{c->start_op();ImageRequest<I>::aio_write(&m_image_ctx, c, {{off, len}},std::move(bl), op_flags, trace);finish_in_flight_io();}
}// queue丢队列，然后在工作线程里面调用下面的send函数void ImageRequest<I>::send()
{I &image_ctx = this->m_image_ctx;AioCompletion *aio_comp = this->m_aio_comp;// 关键日志的打印ldout(cct, 20) << get_request_type() << ": ictx=" << &image_ctx << ", "<< "completion=" << aio_comp << dendl;if (m_bypass_image_cache || m_image_ctx.image_cache == nullptr){send_request();} else{send_image_cache_request();}
}

继续细看代码的日志输出，发现对于同一个请求，这两个函数打印出来的completion是一样的，于是便可以通过这两条日志查看这两个函数的运行时间，如下：

username@hostname:/#  sudo cat  /var/log/ceph/ceph-client.828073.log  |egrep aio_write |grep send  |awk '{print $10}' |sort |uniq -c    |less3 completion=0x7f63600008c03 completion=0x7f6360000b207 completion=0x7f6360000c603 completion=0x7f6360000d603 completion=0x7f6360000d803 completion=0x7f6360000da020 completion=0x7f6360000e302 completion=0x7f636011c4f0...... // 还有很多username@hostname:/#  sudo cat  /var/log/ceph/ceph-client.828073.log  | grep  "completion=0x7f63600008c0"// 可以看到这两个函数对应的日志输出间隔时间有十几毫秒，大头基本就在这里了
2020-09-17 10:39:26.153953 7f63757fa700 20 librbd::io::ImageRequestWQ: 0x55983bb2d980 aio_write: ictx=0x55983bb2e7a0, completion=0x7f63600008c0, off=17863884800, len=4096, flags=0
2020-09-17 10:39:26.164749 7f63777fe700 20 librbd::io::ImageRequest: 0x7f6360035810 send: aio_write: ictx=0x55983bb2e7a0, completion=0x7f63600008c02020-09-17 10:39:26.167203 7f63757fa700 20 librbd::io::ImageRequestWQ: 0x55983bb2d980 aio_write: ictx=0x55983bb2e7a0, completion=0x7f63600008c0, off=81776902144, len=4096, flags=0
2020-09-17 10:39:26.180059 7f63777fe700 20 librbd::io::ImageRequest: 0x7f63600b8fd0 send: aio_write: ictx=0x55983bb2e7a0, completion=0x7f63600008c02020-09-17 10:39:26.183942 7f63757fa700 20 librbd::io::ImageRequestWQ: 0x55983bb2d980 aio_write: ictx=0x55983bb2e7a0, completion=0x7f63600008c0, off=18960003072, len=4096, flags=0
2020-09-17 10:39:26.194718 7f63777fe700 20 librbd::io::ImageRequest: 0x7f6360054710 send: aio_write: ictx=0x55983bb2e7a0, completion=0x7f63600008c0// 选择另外一个查看也是这样
username@hostname:/#  sudo cat  /var/log/ceph/ceph-client.828073.log  | grep  "completion=0x7f636011c4f0"                                      2020-09-17 10:39:26.112072 7f63757fa700 20 librbd::io::ImageRequestWQ: 0x55983bb2d980 aio_write: ictx=0x55983bb2e7a0, completion=0x7f636011c4f0, off=8828133376, len=4096, flags=0
2020-09-17 10:39:26.124578 7f63777fe700 20 librbd::io::ImageRequest: 0x7f63600215c0 send: aio_write: ictx=0x55983bb2e7a0, completion=0x7f636011c4f0
2020-09-17 10:39:26.127175 7f63757fa700 20 librbd::io::ImageRequestWQ: 0x55983bb2d980 aio_write: ictx=0x55983bb2e7a0, completion=0x7f636011c4f0, off=70778023936, len=4096, flags=0
2020-09-17 10:39:26.138301 7f63777fe700 20 librbd::io::ImageRequest: 0x7f636003bb10 send: aio_write: ictx=0x55983bb2e7a0, completion=0x7f636011c4f0

到这里基本就怀疑是丢队列后线程来不及处理引起的。因为往队列里丢和取了以后进行处理都是一个线程，但是取的线程因为还要调用send函数所以相对会慢很多，进而导致队列堆积

代码修改和验证

见附录1。

结论

做了如上代码修改后，并把rbd_op_thread配置项设为4，fio的随机4k iops可以从三万左右提升到6万以上(三节点，每节点19个sata ssd盘)。

限于本人知识水平以及文笔有限，文中可能有疏漏甚至是错误的地方，希望大家批评指证，谢谢。

技术分享预告：网易数帆 Curve 核心开发团队将带来精心准备的新一代开源分布式存储 - Curve 技术系列公开课（直播+回放），每周五晚19:00为大家揭开 Curve 技术的奥妙及 Curve 社区的规划，本周五为 ChunkServer 数据节点的主题，敬请点击收看（https://link.zhihu.com/?target=https%3A//live.bilibili.com/22585337），更多信息见：【系列公开课】Curve核心团队深度解读：如何打造新一代超高性能分布式存储系统https://zhuanlan.zhihu.com/p/269472143

四、报错记录

1、Can't get admin socket path: unable to get conf option admin_socket for {mon.id}: warning: line 13: '{duplicate_parameter_name}' in section '{section_name}' redefined

可能配置文件有重复的配置项

1190451 – A duplicate line in the ceph.conf file causes the ceph daemon command to fail

五、附录

1、代码修改和验证

如上，可以看到可能是工作线城处理不过来，通过查看发现工作线程是写死的单线程的，所以试图把工作线程变为可配置的。另外，为了实时查看到工作队列里面积压的请求个数，可以加个perf dump信息，具体代码修改如下：

diff --git a/src/librbd/ImageCtx.cc b/src/librbd/ImageCtx.cc
index 8f52c9609d..284993eb04 100644
--- a/src/librbd/ImageCtx.cc
+++ b/src/librbd/ImageCtx.cc
@@ -58,7 +58,7 @@ public:ContextWQ *op_work_queue;explicit ThreadPoolSingleton(CephContext *cct)
-    : ThreadPool(cct, "librbd::thread_pool", "tp_librbd", 1,
+    : ThreadPool(cct, "librbd::thread_pool", "tp_librbd", cct->_conf->get_val<int64_t>("rbd_op_threads"),"rbd_op_threads"),op_work_queue(new ContextWQ("librbd::op_work_queue",cct->_conf->get_val<int64_t>("rbd_op_thread_timeout"),
@@ -275,6 +275,7 @@ struct C_InvalidateCache : public Context {trace_endpoint.copy_name(pname);perf_start(pname);if (cache) {Mutex::Locker l(cache_lock);ldout(cct, 20) << "enabling caching..." << dendl;
@@ -381,6 +382,14 @@ struct C_InvalidateCache : public Context {"wb", perf_prio, unit_t(BYTES));plb.add_time_avg(l_librbd_wr_latency, "wr_latency", "Write latency","wl", perf_prio);
+    plb.add_time_avg(l_librbd_wr_before_queue_op_lat, "wr_before_queue_latency", "before queue latency",
+                     "wbql", perf_prio);
+    plb.add_time_avg(l_librbd_wr_after_dequeue_op_lat, "wr_after_dequeue_latency", "after dequeue latency",
+                     "wadl", perf_prio);
+    plb.add_time_avg(l_librbd_wr_send_lat, "wr_send_latency", "send latency",
+                     "send", perf_prio);
+    //plb.add_u64_counter(l_librbd_wr_queue, "queue", "queue");
+    plb.add_u64(l_librbd_wr_queue, "queue", "q", "q", PerfCountersBuilder::PRIO_USEFUL);plb.add_u64_counter(l_librbd_discard, "discard", "Discards");diff --git a/src/librbd/Types.h b/src/librbd/Types.h
index 007e0f3da0..027b26c433 100644
--- a/src/librbd/Types.h
+++ b/src/librbd/Types.h
@@ -20,6 +20,10 @@ enum {l_librbd_wr,l_librbd_wr_bytes,l_librbd_wr_latency,
+  l_librbd_wr_before_queue_op_lat,
+  l_librbd_wr_after_dequeue_op_lat,
+  l_librbd_wr_send_lat,
+  l_librbd_wr_queue,diff --git a/src/librbd/io/ImageRequest.h b/src/librbd/io/ImageRequest.h
index 24239d3e5b..fb5f18962e 100644
--- a/src/librbd/io/ImageRequest.h
+++ b/src/librbd/io/ImageRequest.h
@@ -95,6 +95,10 @@ public:m_bypass_image_cache = true;}+  AioCompletion* get_completion() {
+    return m_aio_comp;
+  }
+diff --git a/src/librbd/io/ImageRequestWQ.cc b/src/librbd/io/ImageRequestWQ.cc
index fe2a39bd7f..db144897e8 100644
--- a/src/librbd/io/ImageRequestWQ.cc
+++ b/src/librbd/io/ImageRequestWQ.cc
@@ -262,7 +262,10 @@ void ImageRequestWQ<I>::aio_write(AioCompletion *c, uint64_t off, uint64_t len,RWLock::RLocker owner_locker(m_image_ctx.owner_lock);if (m_image_ctx.non_blocking_aio || writes_blocked()) {
-    queue(ImageRequest<I>::create_write_request(
+      utime_t elapsed;
+      elapsed = ceph_clock_now() - c->start_time;
+      m_image_ctx.perfcounter->tinc(l_librbd_wr_before_queue_op_lat, elapsed);
+      queue(ImageRequest<I>::create_write_request(m_image_ctx, c, {{off, len}}, std::move(bl), op_flags, trace));} else {c->start_op();
@@ -609,8 +612,17 @@ void ImageRequestWQ<I>::process(ImageRequest<I> *req) {ldout(cct, 20) << "ictx=" << &m_image_ctx << ", "<< "req=" << req << dendl;+
+  utime_t elapsed;
+  elapsed = ceph_clock_now() - req->get_completion()->start_time;
+  m_image_ctx.perfcounter->tinc(l_librbd_wr_after_dequeue_op_lat, elapsed);
+
+  utime_t before_send = ceph_clock_now();req->send();+  utime_t send_time;
+  send_time = ceph_clock_now() - before_send;
+  m_image_ctx.perfcounter->tinc(l_librbd_wr_send_lat, send_time);finish_queued_io(req);if (req->is_write_op()) {finish_in_flight_write();@@ -705,15 +719,19 @@ void ImageRequestWQ<I>::queue(ImageRequest<I> *req) {assert(m_image_ctx.owner_lock.is_locked());CephContext *cct = m_image_ctx.cct;if (req->is_write_op()) {m_queued_writes++;} else {m_queued_reads++;}
+  m_image_ctx.perfcounter->set(l_librbd_wr_queue, m_queued_writes);diff --git a/src/test/librbd/io/test_mock_ImageRequestWQ.cc b/src/test/librbd/io/test_mock_ImageRequestWQ.cc
index 7a731db23a..1119abb437 100644
--- a/src/test/librbd/io/test_mock_ImageRequestWQ.cc
+++ b/src/test/librbd/io/test_mock_ImageRequestWQ.cc
@@ -40,6 +40,10 @@ struct ImageRequest<librbd::MockTestImageCtx> {}+  AioCompletion* get_completion() {
+      return aio_comp;
+  }
+

代码修改后验证

rbd_op_thread =1

[global]
ioengine=rbd
pool=rbd
rbdname=volume-nbd02
invalidate=0
rw=randwrite
bs=4k
runtime=300[rbd_iodepth32]
iodepth=1024

当rbd_op_thread为1时，此时fio只有不到两万八九，此时查看后端，queue中均有上千个排队。

username@hostname:/#  i=`sudo ls /var/run/ceph | grep client` ; sudo ceph daemon /var/run/ceph/${i} perf dump  |grep queue   |grep -v queue_len |grep -v laten"queue": 951,
username@hostname:/home/hzwuhongsong#
username@hostname:/home/hzwuhongsong#
username@hostname:/home/hzwuhongsong#  i=`sudo ls /var/run/ceph | grep client` ; sudo ceph daemon /var/run/ceph/${i} perf dump  |grep queue   |grep -v queue_len |grep -v laten"queue": 941,
username@hostname:/home/hzwuhongsong#  i=`sudo ls /var/run/ceph | grep client` ; sudo ceph daemon /var/run/ceph/${i} perf dump  |grep queue   |grep -v queue_len |grep -v laten"queue": 927,

查看平均延时，如下，可以看出wr_latency延时基本耗在wr_after_dequeue_latency，也即wr_before_queue_latency到wr_after_dequeue_latency之间，即也是在队列里面的时间

username@hostname:#  i=`sudo ls /var/run/ceph | grep client` ; sudo ceph daemon /var/run/ceph/${i} perf dump > txt ;cat txt | grep -A3  wr_lat ; cat txt | grep -A3 wr_before_queue_latency ; cat txt  |grep -A3 wr_after_dequeue_latency ;"wr_latency": {"avgcount": 61510,"sum": 2191.520516783,"avgtime": 0.035628686"wr_before_queue_latency": {"avgcount": 62534,"sum": 0.040011280,"avgtime": 0.000000639"wr_after_dequeue_latency": {"avgcount": 61606,"sum": 2033.996583350,"avgtime": 0.033016209
username@hostname:#  i=`sudo ls /var/run/ceph | grep client` ; sudo ceph daemon /var/run/ceph/${i} perf dump > txt ;cat txt | grep -A3  wr_lat ; cat txt | grep -A3 wr_before_queue_latency ; cat txt  |grep -A3 wr_after_dequeue_latency ;"wr_latency": {"avgcount": 116908,"sum": 4189.363698823,"avgtime": 0.035834705"wr_before_queue_latency": {"avgcount": 117932,"sum": 0.076435187,"avgtime": 0.000000648"wr_after_dequeue_latency": {"avgcount": 116989,"sum": 3877.598762186,"avgtime": 0.033144985

rbd_op_thread = 4

换成4后，iops可以到6万左右，这时候发现队列中排队的仅为个位数、

username@hostname:#  i=`sudo ls /var/run/ceph | grep client` ; sudo ceph daemon /var/run/ceph/${i} perf dump  |grep queue   |grep -v queue_len |grep -v laten"queue": 3,
username@hostname:#  i=`sudo ls /var/run/ceph | grep client` ; sudo ceph daemon /var/run/ceph/${i} perf dump  |grep queue   |grep -v queue_len |grep -v laten"queue": 2,
username@hostname:#  i=`sudo ls /var/run/ceph | grep client` ; sudo ceph daemon /var/run/ceph/${i} perf dump > txt ;cat txt | grep -A3  wr_lat ; cat txt | grep -A3 wr_before_queue_latency ; cat txt  |grep -A3 wr_after_dequeue_latency ;"wr_latency": {"avgcount": 2270672,"sum": 37963.386444893,"avgtime": 0.016719009 // 这个延时基本就是后端延时"wr_before_queue_latency": {"avgcount": 2271695,"sum": 1.605575268,"avgtime": 0.000000706"wr_after_dequeue_latency": {"avgcount": 2271687,"sum": 60.918221533,"avgtime": 0.000026816
username@hostname:#  i=`sudo ls /var/run/ceph | grep client` ; sudo ceph daemon /var/run/ceph/${i} perf dump > txt ;cat txt | grep -A3  wr_lat ; cat txt | grep -A3 wr_before_queue_latency ; cat txt  |grep -A3 wr_after_dequeue_latency ;"wr_latency": {"avgcount": 2439428,"sum": 40801.854420279,"avgtime": 0.016725992"wr_before_queue_latency": {"avgcount": 2440451,"sum": 1.724664580,"avgtime": 0.000000706"wr_after_dequeue_latency": {"avgcount": 2440451,"sum": 65.108590681,"avgtime": 0.000026678// 后端延时
username@hostname:/# for i in {0,3,4,5,6};do sudo  ceph daemon osd.${i}  perf dump  ;done  >    io_perf_osd ;  cat io_perf_osd | grep -A 3 op_w_process                 "op_w_process_latency": {"avgcount": 25845,"sum": 382.087422960,"avgtime": 0.014783804
--"op_w_process_latency": {"avgcount": 46384,"sum": 695.850786001,"avgtime": 0.015001957

查看社区代码修改记录及讨论，可以看到在比较老的版本（比如h版本）时，rbd_op_thread是可以配置的，但是在我测试的L版本中，rbd_op_thread是写死为1的(高版本也依然是这样)，配置写死的原因貌似是高版本引入了rbd cache以及mirror，如果多线程，在极端情况可能导致不一致，所以如果不使用这两项特性，应该是可以把rbd_op_thread的个数做到可配置的。

结论

做了如上代码修改后，并把rbd_op_thread配置项设为4，fio的随机4k iops可以从三万左右提升到6万以上(三节点，每节点19个sata ssd盘)。

限于本人知识水平以及文笔有限，文中可能有疏漏甚至是错误的地方，希望大家批评指证，谢谢。

【ceph】ceph性能分析工具之perf dump代码打点调试统计PerfCounters相关推荐

【ceph】ceph性能分析工具之perf dump代码打点调试统计
目录简介一.查ceph自带的统计 1 命令格式 2 dump 命令输出结果二.自己添加统计三.分析案例 io耗时初分析继续分析进一步分析代码修改和验证四.报错记录五.附录 1.代码修 ...
linux性能分析工具：perf入门一页纸
软件开发中程序运行一段时间出现2类问题最头疼: 1.突然崩溃(调试问题) Windows:可以用WinDbg分析core dump文件,使用应用程序验证器(appverif.exe)对程序进行全面检查 ...
C++ 性能分析工具调研
文章目录 0. 前言 1. gprof 3. valgrind 4. gperftools 5. perf 0. 前言目标:性能分析(profile)包含的内容特别多,但目前我只关注运行时间. 详细 ...
系统级性能分析工具perf的介绍与使用
测试环境:Ubuntu16.04 + Kernel:4.4.0-31 apt-get install linux-source cd /usr/src/tools/perf make &&am ...
linux 解析pdf下载工具,Linux高级系统级性能分析工具-perf.pdf
Linux高级系统级性能分析工具-perf Linux 的系统级性能剖析工具‐perf (二) 承刚 TAOBAO Kernel Team chenggang.qin@ 第三章 Perf top ...
系统级性能分析工具 — Perf
从2.6.31内核开始,linux内核自带了一个性能分析工具perf,能够进行函数级与指令级的热点查找. perf Performance analysis tools for Linux. Perf ...
java dump分析工具_Java 性能分析工具（2）：Java 内置监控工具
引言本文为 Java 性能分析工具系列文章第二篇,第一篇:操作系统工具.在本文中将介绍如何使用 Java 内置监控工具更加深入的了解 Java 应用程序和 JVM 本身.在 JDK 中有许多内置的工 ...
Linux性能分析工具perf基础使用介绍
perf是Linux内核内置的性能分析工具.从内核版本2.6.31开始出现该工具,如果没有安装,可以使用以下命令进行安装 yum -y install perf.x86_64 这里我们主要介绍一下如何 ...
linux 系统级性能分析工具 perf 的介绍与使用
目录 1. 背景知识 1.1 tracepoints 1.2 硬件特性之cache 2. 主要关注点 3. perf的使用 3.0 perf引入的overhead 3.1 perf list 3.2 ...

【ceph】ceph性能分析工具之perf dump代码打点调试统计PerfCounters

即看即用

查看

增加统计项

简介

一、查ceph自带的统计

1 命令格式

2 dump 命令输出结果

二、添加统计项目

三、分析案例

io耗时初分析

继续分析

进一步分析

代码修改和验证

四、报错记录

五、附录

1、代码修改和验证

【ceph】ceph性能分析工具之perf dump代码打点调试统计PerfCounters相关推荐

最新文章

热门文章