kvm下的ceph主机启动io请求统计

背景

假如一个主机存储在ceph里面，我们想统计下一次启动过程中的io读取的情况，那么可以通过下面的方法来统计
启动时间也可以通过在宿主机里面去查看，通过日志这边要方便一点，无需登录到虚拟机内部

日志开启

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

[global]
fsid = 4064c56e-c9ad-4b19-bf74-c4e291be5920
mon_initial_members = lab104
mon_host = 192.168.19.104
auth_cluster_required = none
auth_service_required = none
auth_client_required = none

[client]
admin socket = /var/run/ceph/ceph-client/$cluster-$type.$id.$pid.asok
debug rbd = 20
debug client = 20
debug objectcacher = 20
log file = /var/run/ceph/ceph-client/$cluster-$name.log

通过这个可以看到 这个是开启日志的方法

在kvm的主机上面添加上面的日志，这个写到ceph的配置文件即可

日志处理

1
2
3
4
5
6
7
8
9
[root@lab102 kvm]# cat  ceph-client.admin.log |grep ObjectDispatch|grep read|grep ObjectDispatch|grep -v SimpleSchedule|tail -n 10
2025-02-19T14:54:10.524+0800 7f3a48873700 20 librbd::io::ObjectDispatch: 0x564ea4735e50 read: rbd_data.3a5db2d07ea.0000000000000001 3833856~360448
2025-02-19T14:54:10.524+0800 7f3a48873700 20 librbd::io::ObjectDispatch: 0x564ea4735e50 read: rbd_data.3a5db2d07ea.0000000000000002 0~155648
2025-02-19T14:54:10.524+0800 7f3a48873700 20 librbd::io::ObjectDispatch: 0x564ea4735e50 read: rbd_data.3a5db2d07ea.0000000000000002 155648~516096
2025-02-19T14:54:10.524+0800 7f3a48873700 20 librbd::io::ObjectDispatch: 0x564ea4735e50 read: rbd_data.3a5db2d07ea.0000000000000002 671744~516096
2025-02-19T14:54:10.524+0800 7f3a48873700 20 librbd::io::ObjectDispatch: 0x564ea4735e50 read: rbd_data.3a5db2d07ea.0000000000000002 1187840~65536
2025-02-19T14:54:10.527+0800 7f3a48873700 20 librbd::io::ObjectDispatch: 0x564ea4735e50 read: rbd_data.3a5db2d07ea.0000000000000002 1253376~516096
2025-02-19T14:54:10.528+0800 7f3a48873700 20 librbd::io::ObjectDispatch: 0x564ea4735e50 read: rbd_data.3a5db2d07ea.0000000000000002 1769472~516096
2025-02-19T14:54:10.528+0800 7f3a48873700 20 librbd::io::ObjectDispatch: 0x564ea4735e50 read: rbd_data.3a5db2d07ea.0000000000000002 2285568~516096

可以看到请求的时间，请求的对象名称，请求的起点，请求的长度

1
2
3
rados的请求收到了7617次
[root@lab102 kvm]# cat readnew.txt |wc -l
7617

一次启动在ceph这边的rados请求发起了这么多次

下面是一个系统启动的时候读取的总的数据量

1
2
[root@lab102 kvm]# cat  readnew.txt |awk '{print $2}'|awk -F~ '{sum += $2} END{print sum}'
167396352

总的数据读取大小大概在160MB/s左右，主要也就是内核，内核大概也就100M左右，还有其它的一些数据

对象被读取的情况

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
[root@lab102 kvm]# cat new1.txt |sort  -n -k 2|tail -n 15
rbd_data.3a5db2d07ea.00000000000026d5 3117056
rbd_data.3a5db2d07ea.0000000000000019 3407872
rbd_data.3a5db2d07ea.0000000000000dc5 3436544
rbd_data.3a5db2d07ea.0000000000000080 3542528
rbd_data.3a5db2d07ea.0000000000000003 4194304
rbd_data.3a5db2d07ea.0000000000000004 4194304
rbd_data.3a5db2d07ea.0000000000000005 4194304
rbd_data.3a5db2d07ea.000000000000001a 4194304
rbd_data.3a5db2d07ea.000000000000001b 4194304
rbd_data.3a5db2d07ea.000000000000001c 4194304
rbd_data.3a5db2d07ea.000000000000001d 4194304
rbd_data.3a5db2d07ea.0000000000000000 4820992
rbd_data.3a5db2d07ea.0000000000000100 4821504
rbd_data.3a5db2d07ea.0000000000000001 6348800
rbd_data.3a5db2d07ea.0000000000000002 7798784

可以看到有一部分对象还是比较连续的读取的，这个应该是一些操作系统大文件的，比如内核的，这个经过一层文件系统后的有一部分是连续id

如何利用这些日志信息

我们可以看下，在不同的并发下面，这个启动的区别，理论上是越多并发，单个的时间就会越大，开始可能比一个会好一点，会缓存一点其它主机读取的相同的数据，但是这个到了一定的程度就会成为瓶颈了

我们需要根据这个启动分析来得到一个比较合适的并发启动数目

一些命令记录

并发启动虚拟机

1
virsh list --all --name | xargs -P 11 -I {} virsh start  {}

获取虚拟机的ip

1
2
[root@lab102 kvm]# cat check.sh
for vm in $(virsh list --all --name); do     virsh domifaddr  $vm; done|grep ipv|awk '{print $4}'|cut -d / -f 1 > ip.list

查看启动时间

1
for host in `cat ip.list`;do ssh  root@$host  systemd-analyze ;done

启动一个虚拟机的时间

1
2
[root@lab102 kvm]# ssh 192.168.122.48  systemd-analyze
Startup finished in 806ms (kernel) + 1.920s (initrd) + 11.502s (userspace) = 14.229s

并发启动10个虚拟机

1
2
3
4
5
6
7
8
9
10
11
12
[root@lab102 kvm]# for host in `cat ip.list`;do ssh  root@$host  systemd-analyze ;done
Startup finished in 880ms (kernel) + 3.479s (initrd) + 19.364s (userspace) = 23.724s
Startup finished in 883ms (kernel) + 3.404s (initrd) + 17.888s (userspace) = 22.176s
Startup finished in 984ms (kernel) + 3.143s (initrd) + 19.173s (userspace) = 23.302s
Startup finished in 862ms (kernel) + 3.512s (initrd) + 19.606s (userspace) = 23.981s
Startup finished in 868ms (kernel) + 2.628s (initrd) + 17.788s (userspace) = 21.285s
Startup finished in 900ms (kernel) + 2.661s (initrd) + 18.296s (userspace) = 21.859s
Startup finished in 880ms (kernel) + 3.479s (initrd) + 19.364s (userspace) = 23.724s
Startup finished in 870ms (kernel) + 3.442s (initrd) + 19.233s (userspace) = 23.546s
Startup finished in 911ms (kernel) + 3.395s (initrd) + 17.976s (userspace) = 22.283s
Startup finished in 901ms (kernel) + 3.309s (initrd) + 19.488s (userspace) = 23.699s
Startup finished in 901ms (kernel) + 2.597s (initrd) + 18.168s (userspace) = 21.667s

可以看到时间增加了7秒左右，大概是1.5倍，这个时间是11个虚拟机并发启动的情况，如果更多的情况可以继续查看

1
2
3
4
5
6
7
8
3.97k op/s
3.16k op/s
3.75k op/s
3.68k op/s
3.10k op/s
3.52k op/s
1.52k op/s
1.53k op/s

从ceph的日志看，可以看到启动11个时候的高峰期op大概在3k多

kvm下的ceph主机启动io请求统计
https://zphj1987.com/2025/02/19/kvm下的ceph主机启动io请求统计/
作者
zphj1987
发布于
2025年2月19日
许可协议