kvm下的ceph主机启动io请求统计
背景
假如一个主机存储在ceph里面，我们想统计下一次启动过程中的io读取的情况，那么可以通过下面的方法来统计
启动时间也可以通过在宿主机里面去查看，通过日志这边要方便一点，无需登录到虚拟机内部
日志开启
[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的配置文件即可
日志处理
[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
可以看到请求的时间，请求的对象名称，请求的起点，请求的长度
rados的请求收到了7617次
[root@lab102 kvm]# cat readnew.txt |wc -l
7617
一次启动在ceph这边的rados请求发起了这么多次
下面是一个系统启动的时候读取的总的数据量
[root@lab102 kvm]# cat readnew.txt |awk '{print $2}'|awk -F~ '{sum += $2} END{print sum}'
167396352
总的数据读取大小大概在160MB/s左右，主要也就是内核，内核大概也就100M左右，还有其它的一些数据
对象被读取的情况
[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
如何利用这些日志信息
我们可以看下，在不同的并发下面，这个启动的区别，理论上是越多并发，单个的时间就会越大，开始可能比一个会好一点，会缓存一点其它主机读取的相同的数据，但是这个到了一定的程度就会成为瓶颈了
我们需要根据这个启动分析来得到一个比较合适的并发启动数目
一些命令记录
并发启动虚拟机
virsh list --all --name | xargs -P 11 -I {} virsh start {}
获取虚拟机的ip
[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
查看启动时间
for host in `cat ip.list`;do ssh root@$host systemd-analyze ;done
启动一个虚拟机的时间
[root@lab102 kvm]# ssh 192.168.122.48 systemd-analyze
Startup finished in 806ms (kernel) + 1.920s (initrd) + 11.502s (userspace) = 14.229s
并发启动10个虚拟机
[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个虚拟机并发启动的情况，如果更多的情况可以继续查看
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多