磁盘故障是个很麻烦的问题,影响有:磁盘性能大幅下降、IO hung、磁盘损坏数据丢失。严重的批量磁盘故障,影响的服务器规模少则几十台,多则上千台甚至更多!目前已遇到多起疑难批量磁盘故障,都是新 case,厂商搜集日志没有任何发现,但经过我们的排查最终都查清楚了根本原因,并提供了根治或规避方法。
本文主要记录一下这些疑难磁盘故障的排查总结、开发的工具、经验教训等,相信阅读本文的同学能获得不少有用的知识。
iostat 在磁盘故障排查中的使用
这是 sata 盘16k随机读 iostat 截图:IOPS 只有200,IO 流量只有3M,IO 使用率100%。
sata 盘虽然随机读写性能很差,但是这台机器性能太差,判定大概率磁盘有问题。
这是 nvme 盘,业务 IO 读写时 iostat 截图:IOPS 只有3000,IO 流量只有20M,IO 使用率70%。正常情况,nvme 盘在 4K 随机读写情况下,IOPS 能达到百万,IO 流量 GB/S 级别。但是这台机器 IOPS 只有3000,IO 流量20M/s,但 IO 使用率竟然达到70%,这个太异常了,判定大概率是磁盘有问题。
blktrace 在磁盘故障排查中的使用
有了这些预备知识,就可以用起来 blktrace 了,使用方法可以简化成:
blktrace -d /dev/sda -o - | blkparse -i -
sda是 IO 使用率很高但 IO hung 或者 IOPS 很低的磁盘。该命令采样 sda 盘每个 IO 请求在 IO 传输过程各个环节的耗时并打印出来。
blktrace 打印的演示数据如下:
“Sequeue Number” 那一列是序列号,“Time Stamp” 那一列是时间戳,“PID” 那一列是抓取当时IO数据时的进程 PID,“Event” 那一列是 IO 传输事件(就是前文提到的I、D、C),“Start block+ number of blocks” 那一列是IO传输的起始扇区号(查证不是起始物理块号)+扇区数。Start block+ number of blocks” 这一列的数据标识了 IO 的唯一性,简单说用来区分不同的 IO。
blktrace 更详细的用法见 http://linuxperf.com/?p=161。
下图是使用该方法抓到的某款 ssd 磁盘的 IO 传输过程的数据:
我们重点关注的是3列数据,时间戳(第4列)、IO 事件 IDC 等(第6列)、IO 请求读写的起始扇区地址+传输扇区数(第8列)。起始扇区地址是7223836744 的这个 IO 请求,IO 请求派发给磁盘驱动(D)的时间点是44.007497905,IO 请求传输完成(C)的时间点是44.012554366,这两个时间点一相减就是该 IO 请求在磁盘驱动层的传输耗时,这两个时间差达到5ms,正常情况是 us 级别。同时,iostat 看到的 IOPS 并不高。基于以上测试数据,判定 IO 请求在磁盘驱动层的传输耗时偏长,大概率就是磁盘有问题了。
systemtap 在磁盘故障排查中的使用
ebpf 编程限制太多,systemtap 相对更简单。如下是我用 systemtap 针对该问题编写的一个脚本,命名为 blktrace-systemtap.stp。
global id_buf;
global dc_buf;
global id_buf_name;
global dc_buf_name;
//IO请求插入IO队列,记录时间点
probe kernel.trace("block_rq_insert")
{
if($rq != 0 && kernel_string($rq->rq_disk->disk_name) == "sda"){//抓抓取sda盘的IO数据
id_buf[$rq] = gettimeofday_ms();
id_buf_name[$rq] = execname();
}
}
//IO请求从IO队列剔除并派发给磁盘驱动,记录时间点
probe kernel.trace("block_rq_issue")
{
if(id_buf[$rq] != 0){
dc_buf[$rq] = gettimeofday_ms();
dc_buf_name[$rq] = execname();
}
}
//IO请求传输完成,计算与IO请求插入IO队列的时间点的时间差,如果时间差太大就打印IO请求在传输过程各阶段的耗时
probe kernel.trace("block_rq_complete")
{
if($rq!= 0 && id_buf[$rq]!=0 && dc_buf[$rq] != 0){
dx = gettimeofday_ms() - id_buf[$rq];
if(dx > 10)//大于10ms则打印IO各阶段的耗时
{
printf("%s I-D:%dms %s D-C:%dms %s\n",kernel_string($rq->rq_disk->disk_name),dc_buf[$rq]-id_buf[$rq],id_buf_name[$rq],gettimeofday_ms()-dc_buf[$rq],dc_buf_name[$rq]);
}
}
if(dc_buf[$rq]){
delete dc_buf[$rq];
delete dc_buf_name[$rq];
}
if(id_buf[$rq]){
delete id_buf[$rq];
delete id_buf_name[$rq];
}
}
该脚本的作用是:如果要是某个 IO 请求“从 IO 请求插入 IO 队列到 IO 请求传输完成”耗时大于10ms,则打印 IO 请求在 IO 队列和 IO 请求在磁盘驱动层的耗时。if(dx > 10) 里的10可以按照实际情况增大或减小。打印情况如下:
sda I-D:0ms kworker/u898:0 D-C:100ms kworker/u898:0
案例一:sata 盘每21分钟 IO hung 7s
这个批量磁盘故障出现概率很高,每21分钟出现一次,isotat 看到的现场是这样:
[<ffffffff99d69f19>] schedule+0x29/0x70
[<ffffffff99d67a21>] schedule_timeout+0x221/0x2d0
[<ffffffff99d695ed>] io_schedule_timeout+0xad/0x130
[<ffffffff99d69688>] io_schedule+0x18/0x20
[<ffffffff99d68071>] bit_wait_io+0x11/0x50
[<ffffffff99d67b97>] __wait_on_bit+0x67/0x90
[<ffffffff997b6b81>] wait_on_page_bit+0x81/0xa0
[<ffffffff997b6cb1>] __filemap_fdatawait_range+0x111/0x190
[<ffffffff997b6d44>] filemap_fdatawait_range+0x14/0x30
[<ffffffff997b91a6>] filemap_write_and_wait_range+0x56/0x90
[<ffffffffc067e5aa>] ext4_sync_file+0xba/0x320 [ext4]
[<ffffffff99877367>] do_fsync+0x67/0xb0
[<ffffffff99877650>] SyS_fsync+0x10/0x20
这是 ext4 文件系统 write 后等待传输完成,进程保持这种状态7s后,恢复正常。会不会是卡在内核某处导致的?这个文件系统 write 过程,大体可以分配两个流程:
SyS_fsync->do_fsync->ext4_sync_file->filemap_write_and_wait_range->__filemap_fdatawrite_range->__filemap_fdatawrite_range->do_writepages->ext4_writepages->ext4_io_submit->submit_bio 把 IO 请求派发给 block 层。然后回到 filemap_write_and_wait_range 函数,执行__filemap_fdatawait_range->wait_on_page_writeback->wait_on_page_bit 休眠等待 IO 请求传输完成。
而执行 submit_bio 派发 IO 到 block 层也是一个关键,因为正是这里把 IO 派发给磁盘驱动。派发给磁盘驱动的函数流程是:
submit_bio->generic_make_request->blk_queue_bio->__blk_run_queue->__blk_run_queue_uncond->scsi_request_fn
或者 ext4_writepages->blk_finish_plug->blk_flush_plug_list->queue_unplugged->__blk_run_queue->__blk_run_queue_uncond->scsi_request_fn,最终都调用 scsi_request_fn 函数。
等 IO 请求传输完成,执行中断回调函数handle_irq->......__handle_irq_event_percpu->megasas_isr_fusion->complete_cmd_fusion->scsi_done->blk_complete_request,
然后在 blk_complete_request 函数往后流程会触发软中断,执行 do_softirq->...->blk_done_softirq->scsi_softirq_done->.....bio_endio->ext4_end_bio->ext4_finish_bio->end_page_writeback 唤醒之前在wait_on_page_bit 休眠的进程。
这基本就是 IO 传输的整个流程了,用 systemtap 捕捉关键函数,打印进程名字、进程 PID、时间戳、IO 传输有关的 page 等信息,然后看到底 IO hung 的7s是卡在哪里?我选择的函数有:IO 传输传输发起函数 submit_bio,发起磁盘数据传输函数 scsi_request_fn,发送 SCSI 命令给磁盘控制器函数scsi_dispatch_cmd,进程发送 IO 请求后休眠函数wait_on_page_bit,磁盘数据传输完成后执行的中断回调函数blk_complete_request,唤醒等待文件数据传输完成的进程的 end_page_writeback 函数。添加的调试信息演示如下:
probe kernel.function("wait_on_page_bit")
{
printf("wait_on_page_bit %s pid:%d page:%p bit_nr:%d cpu:%d\n",execname(),tid(),$page,$bit_nr,cpu())}
}
[10:08:50]submit_bio net_agent pid:298171 bio:0xffff9777cd34e600 queue:0xffff9770019d9330 cpu:10
[10:08:50]scsi_request_fn net_agent pid:298171 rq queue:0xffff9770019d9330 cpu:10
[10:08:50]scsi_dispatch_cmd net_agent pid:298171 return:0 cpu:10
[10:08:50]wait_on_page_bit net_agent pid:298171 page:0xfffff2f917d96700 bit_nr:13 cpu:10
...................
[10:08:57] blk_complete_request swapper/25 pid:0 req->q:0xffff9770019d9330 req:0xffff977713793900 cpu:25
[10:08:57] end_page_writeback swapper/10 pid:0 page:0xfffff2f917d96700 cpu:10
案例二:sata 盘每周六11点 IO hung
//io请求传输完成,统计IO流量执行到
b.attach_kprobe(event="blk_account_io_completion",fn_name="trace_blk_account_io_completion")
//io请求传输完成最后,统计IO使用率执行到
b.attach_kprobe(event="blk_account_io_done",fn_name="trace_blk_account_io_done")
//io请求加入队列时执行
b.attach_kprobe(event="blk_account_io_start",fn_name="trace_blk_account_io_start")
//统计IO使用率执行到
b.attach_kprobe(event="part_round_stats",fn_name="trace_part_round_stats")
//发生IO请求合并时执行到
b.attach_kprobe(event="elv_merge_requests",fn_name="trace_elv_merge_requests")
//把io请求加入IO队列时令iflight加1
b.attach_kprobe(event="part_dec_in_flight",fn_name="trace_part_dec_in_flight")
//io请求传输完成时令iflight减1
b.attach_kprobe(event="part_inc_in_flight",fn_name="trace_part_inc_in_flight")
案例三:使用 perccli 采集阵列卡信息导致 IO hung 几秒
发生 IO hung 的服务器都是同一个型号,这是个很重要的信息。有了前两次批量磁盘故障经验,再加上是同一个型号的机器,理所应当怀疑是磁盘或者阵列卡硬件有问题。但搜集了大概5台服务器的磁盘和阵列卡等日志,厂商没有任何发现。并且厂商反馈这个型号的服务器只有我们遇到了 IO hung 问题!难道与我们业务模型有关?
由于该问题触发概率很低,一直没有抓到现场,并且厂商还怀疑 IO hung 与内核有关系,不一定是 IO 卡在磁盘驱动导致的!本来可以依靠监控,但是物理机的监控做不到秒级,而这个 IO hung 也就持续几秒,很可能抓不到完整数据!
没办法,找了几台发生过 IO hung 的服务器,一直执行 iostat -dmx 1 每1s抓一次 IO 数据,期待运气好能抓到一次现场。iostat 打印的 await、r_await、w_await 可以反映 IO 平均延迟,如果抓到了问题现场,这3个参数应该会很大。但这些延迟数据包含了 IO 请求在 IO 队列的时间 +IO 请求在磁盘驱动的时间,如果厂商判定是 IO 请求在 IO 队列卡主了导致 IO hung,是内核导致的 IO hung,则有必要证明 IO hung 发生在磁盘驱动,以便帮助厂家定位问题原因!
在这种情况下,可以用 blktrace 一直抓取磁盘日志,但是日志量太大,因为没人能预料下次啥时间发生。如果一个星期后发生,blktrace 采集的日志量估计有上百G,难以分析。能否做一个类似 blktrace 的工具,但是只在 IO 请求在 IO 队列+磁盘驱动花费时间过长时再打印出 IO 耗时数据呢?可以的,于是就用 systemtap 编写了前文提到的脚本 blktrace-systemtap.stp:
global id_buf;
global dc_buf;
global id_buf_name;
global dc_buf_name;
//IO请求插入IO队列,记录时间点
probe kernel.trace("block_rq_insert")
{
if($rq != 0 && kernel_string($rq->rq_disk->disk_name) == "sda"){//抓抓取sda盘的IO数据
id_buf[$rq] = gettimeofday_ms();
id_buf_name[$rq] = execname();
}
}
//IO请求从IO队列剔除并派发给磁盘驱动,记录时间点
probe kernel.trace("block_rq_issue")
{
if(id_buf[$rq] != 0){
dc_buf[$rq] = gettimeofday_ms();
dc_buf_name[$rq] = execname();
}
}
//IO请求传输完成,计算与IO请求插入IO队列的时间点的时间差,如果时间差太大就打印IO请求在传输过程各阶段的耗时
probe kernel.trace("block_rq_complete")
{
if($rq!= 0 && id_buf[$rq]!=0 && dc_buf[$rq] != 0){
dx = gettimeofday_ms() - id_buf[$rq];
if(dx > 10)//大于10ms则打印IO各阶段的耗时
{
printf("%s I-D:%dms %s D-C:%dms %s\n",kernel_string($rq->rq_disk->disk_name),dc_buf[$rq]-id_buf[$rq],id_buf_name[$rq],gettimeofday_ms()-dc_buf[$rq],dc_buf_name[$rq]);
}
}
if(dc_buf[$rq]){
delete dc_buf[$rq];
delete dc_buf_name[$rq];
}
if(id_buf[$rq]){
delete id_buf[$rq];
delete id_buf_name[$rq];
}
}
global softirq_name;
probe begin{
softirq_name[0] = "tasklet_hi_action"
softirq_name[1] = "run_timer_softirq"
softirq_name[2] = "net_tx_action"
softirq_name[3] = "net_rx_action"
softirq_name[4] = "blk_done_softirq"
softirq_name[5] = "irq_poll_softirq"
softirq_name[6] = "tasklet_action"
softirq_name[7] = "run_rebalance_domains"
softirq_name[8] = "HRTIMER_SOFTIRQ"
softirq_name[9] = "rcu_process_callbacks"
softirq_name[10] = "rcu_process_callbacks"
}
probe kernel.trace("softirq_entry"){
softirq_time[cpu()] = gettimeofday_us();//每个cpu都有自己的软中断,所以要按照cpu分开
}
probe kernel.trace("softirq_exit"){
if(softirq_time[cpu()]){
dx = gettimeofday_us() - softirq_time[cpu()];
if(dx > 5*1000){//单次软中断耗时大于5ms则打印
printf("%s %s dx:%dms cpu:%d\n",ppfunc(),softirq_name[$vec_nr],dx,cpu())
}
cpu_softirq_time[cpu()] += dx;
}
delete softirq_time[cpu()]
}
//定时1s打印一次每个软中断的总耗时
probe timer.sec(1){
foreach (i in cpu_softirq_time){
if(cpu_softirq_time[i] > 5*1000)
printf("cpu:%d %dms\n",i,cpu_softirq_time[i]/1000);
}
delete cpu_softirq_time
}
大概1~2周后,终于在两台机器上凌晨1点抓到一次 IO hung 现场:
案例四:长时间磁盘读写后 ssd 盘性能下降明显
这个问题是编译业务发现的,编译进行一段时间后,就会出现IO性能明显下降问题,磁盘是 ssd,带了阵列卡,性能很不错。
正常情况 fio 压测 isotat 看到的如下:
出现性能问题的机器,fio 压测 iostat 看到的如下:
可以发现,性能下跌的非常严重。使用 blktrace 或 blktrace-systemtap 等工具很快定位到 IO 性能差的原因是 IO 传输过程的 D-C 环节耗时长(DC耗时大概几百ms),就是因为在磁盘驱动耗时长导致的IO性能差!按照经验,这种问题大概率就是磁盘或者阵列卡硬件有问题!
但是收集磁盘和阵列卡日志后,厂家也是排查不出问题原因,其他客户没遇到类似问题。但神奇的是重启服务器后就能恢复正常,难道又与我们的业务有关系?在排查了很长时间后依然找不到原因。
此时有个想法,前文抓到 DC 耗时几百 ms,一定能说明这个时间是消耗在磁盘或者阵列卡硬件吗?不能!看下如下示意图,把 IO 请求在磁盘驱动层的处理进行细化:
IO 请求在磁盘驱动层的耗时又可以细化为 IO 请求在驱动的耗时+IO 请求在磁盘硬件的处理耗时。本次的磁盘故障 DC 耗时长是哪个环节呢?此时就需要在 blktrace-systemtap.stp 的基础上,再捕捉 IO 请求派发给磁盘驱动的函数,然后就可以计算 IO 请求在驱动的耗时 和 IO 请求在磁盘硬件的处理耗时。于是编写如下脚本:
global queue_buf;
global dispatch_buf;
global queue_buf_name;
global dispatch_buf_name;
global driver_buf;
//IO请求插入IO队列,记录时间点
probe kernel.trace("block_rq_insert")
{
if($rq && $rq->rq_disk){
queue_buf[$rq] = gettimeofday_ms();
queue_buf_name[$rq] = execname();
}
}
/*
//用 scsi_dispatch_cmd代替block_rq_issue trace函数计算IO请求在IO队列的耗时
probe kernel.trace("block_rq_issue")
{
if(queue_buf[$rq] != 0){
dispatch_buf[$rq] = gettimeofday_ms();
dispatch_buf_name[$rq] = execname();
}
}*/
//SCSI 驱动是执行 scsi_dispatch_cmd函数把IO请求派发给磁盘驱动
probe kernel.function("scsi_dispatch_cmd")//执行scsi_dispatch_cmd函数返回记录时间点
{
if(queue_buf[$cmd->request] != 0){
dispatch_buf[$cmd->request] = gettimeofday_ms();
dispatch_buf_name[$cmd->request] = execname();
}
}
probe kernel.function("scsi_dispatch_cmd").return//从scsi_dispatch_cmd函数计返回记录时间点
{
if(dispatch_buf[$cmd->request] != 0){
driver_buf[$cmd->request] = gettimeofday_ms();
}
}
//IO请求传输完成,计算与IO请求插入IO队列的时间点的时间差,如果时间差太大就打印IO请求在传输过程各阶段的耗时
probe kernel.trace("block_rq_complete")
{
if($rq!= 0 && (queue_buf[$rq]!=0) && (dispatch_buf[$rq] != 0) && (driver_buf[$rq] !=0)){
dx = gettimeofday_ms() - queue_buf[$rq];
//DC耗时大于2ms则打印IO信息
if(dx >= 2){
printf("%s io all:%dms in-queue:%dms %s in-driver:%d in-disk:%dms %s\n",kernel_string($rq->rq_disk->disk_name),dx,dispatch_buf[$rq]-queue_buf[$rq],queue_buf_name[$rq],driver_buf[$rq]-dispatch_buf[$rq],gettimeofday_ms()-driver_buf[$rq],dispatch_buf_name[$rq]);
}
}
if(dispatch_buf[$rq])
delete dispatch_buf[$rq];
if(queue_buf[$rq])
delete queue_buf[$rq];
if(driver_buf[$rq])
delete driver_buf[$rq];
if(queue_buf_name[$rq] != "")
delete queue_buf_name[$rq];
if(dispatch_buf_name[$rq] != "")
delete dispatch_buf_name[$rq];
}
sdb io all:2ms in-queue:0ms fio in-driver:2ms in-disk:1ms
这是在IO派发,最后是执行scsi_dma_map->intel_alloc_iova->alloc_iova_fast->alloc_iova 建立 DMA 映射、分配 iommu 需要的 iova 虚拟地址。入口函数正好有 scsi_dispatch_cmd!于是在前文的脚本中添加如下代码,用于计算在 alloc_iova 函数的耗时。
global dma_dx;
probe kernel.function("alloc_iova"){
dma_dx[tid()] = gettimeofday_us();
}
probe kernel.function("alloc_iova").return{
if(dma_dx[tid()] != 0){
dx = gettimeofday_us() - dma_dx[tid()];
if(dx > 1000){//阀值500打印太頻繁
printf("%s %d size:%d dx:%dus\n",execname(),tid(),$size,dx);
//print_backtrace();
}
delete dma_dx[tid()];
}
}
fio 36553 size:64 dx:1292us
sdb io all:2ms in-queue:0ms fio in-driver:2ms in-disk:1ms
static int __alloc_and_insert_iova_range(struct iova_domain *iovad,
unsigned long size, unsigned long limit_pfn,
struct iova *new, bool size_aligned)
{
struct rb_node *prev, *curr = NULL;
unsigned long flags;
unsigned long saved_pfn;
unsigned int pad_size = 0;
spin_lock_irqsave(&iovad->iova_rbtree_lock, flags);
saved_pfn = limit_pfn;
//获取iovad->rbroot红黑树中的一个rb_node节点
curr = __get_cached_rbnode(iovad, &limit_pfn);
prev = curr;
//查找一片连续的iova地址空间,耗时长就是在这里
while (curr) {
struct iova *curr_iova = container_of(curr, struct iova, node);
if (limit_pfn <= curr_iova->pfn_lo) {
goto move_left;
} else if (limit_pfn > curr_iova->pfn_hi) {
if (size_aligned)
pad_size = iova_get_pad_size(size, limit_pfn);
if ((curr_iova->pfn_hi + size + pad_size) < limit_pfn)
break; /* found a free slot */
}
limit_pfn = curr_iova->pfn_lo;
move_left:
prev = curr;
//在这里耗时长
curr = rb_prev(curr);
}
..................
//这里给 new->pfn_lo 和 new->pfn_hi 赋值
new->pfn_lo = limit_pfn - (size + pad_size);
new->pfn_hi = new->pfn_lo + size - 1;
..............
}
案例五:使用 sas3ircu 采集阵列卡信息概率性导致磁盘数据损坏、服务器宕机
dumpe2fs 1.42.9 (28-Dec-2013)
dumpe2fs: Bad magic number in super-block while trying to open /dev/sda3
并且这前 8K 的数据大部分不是0,正常情况 ext4 文件系统的前 8K 数据大部分是0,如下是正常的 ext4 文件系统前8K数据,0xEF53 是 ext4 文件系统的 magic。
probe kernel.function("generic_make_request"){
if(($bio->bi_bdev->bd_dev == 0x800003 || $bio->bi_bdev->bd_dev == 0x800000 || $bio->bi_bdev->bd_dev == 0x800001|| ($bio->bi_bdev->bd_dev==0x800002 && ($bio->bi_sector * 512 + $bio->bi_size > 0xC60000000))))
{
printf("%s %s_%d %s_%d %s sector:0x%x size:%d dev:0x%x rw:0x%x ",ctime(),execname(),tid(),kernel_string(task_current()->parent->comm),task_current()->parent->pid,kernel_string($bio->bi_bdev->bd_disk->disk_name),$bio->bi_sector,$bio->bi_size,$bio->bi_bdev->bd_dev,$bio->bi_rw);
//jbd2/sda3-8进程传输IO时,$bio->bi_io_vec[0]->bv_page->mapping->host->i_dentry->first 是NULL,kworker/u896:1 有时也会这样
if($bio->bi_io_vec && $bio->bi_io_vec[0]->bv_page && $bio->bi_io_vec[0]->bv_page->mapping && (($bio->bi_io_vec[0]->bv_page->mapping & 0x1) == 0)){
if($bio->bi_io_vec[0]->bv_page->mapping->host && $bio->bi_io_vec[0]->bv_page->mapping->host->i_dentry->first && $bio->bi_io_vec[0]->bv_page->mapping->host->i_dentry->first < 0xffffffffffffff00){
printf("filename:%s\n",kernel_string(@cast($bio->bi_io_vec[0]->bv_page->mapping->host->i_dentry->first-0xb0,"struct dentry")->d_iname))
}else
{
printf("*\n")
}
}
else
{
printf(" #\n")
}
}
}
cat /sys/block/sda/sda1/start
2048
cat /sys/block/sda/sda1/size
2048
cat /sys/block/sda/sda2/start
4096
cat /sys/block/sda/sda2/size
104857600
cat /sys/block/sda/sda3/start
104861696
cat /sys/block/sda/sda3/size
832839680
1:这个脚本监控了 sda 盘所有分区的写操作,如果是有进程写 sda2 分区的数据,越界到了 sda3 分区,就可以抓到。因为 sda2 分区是跟文件系统,空闲时都有很多进程读写文件,为了过滤掉干扰打印,加了个 if($bio->bi_bdev->bd_dev==0x800002 && ($bio->bi_sector * 512 + $bio->bi_size > 0xC60000000) 判断。这个判断是如果有进程写 sda2 分区结束地址,再把改进程信息打印出来。$bio->bi_sector 是本次写操作的起始扇区地址(相对当前磁盘分区的起始地址,如果从磁盘分区起始地址开始写,$bio->bi_sector就是0),以512字节为单位,$bio->bi_size 是本次写操作的大小,二者相加就是本次写操作的结束扇区地址。sda2 分区50G,16进制是 0xC80000000,如果有 sda2 分区的写操作的磁盘地址大于 0xC60000000,那就很接近 0xC80000000,有可能该写操作越界到了 sda3 分区。
2:打印出写操作的文件名字,原理是基于 pagecache 的命名空间,找到它映射的文件 inode、dentry。需要注意的时,内核 jbd2 线程的写操作,是无法解析出它写的哪个文件。因为它是直接在 ext4 的 jbd2 分区写操作,并不是针对某个文件。
3:如果是 direct IO 形式的文件读写,基于 pagecache 原理解析不出它写的哪个文件。此时需要加上 if($bio->bi_io_vec[0]->bv_page->mapping & 0x1) == 0) 判断,如果 bit0 是1,说明是非 pagecache 的写操作。
运行后的效果如下:
Fri Jul 15 07:33:51 2022 kworker/u896:2_207799 kthreadd_2 sda sector:0x88ac8 size:4096 dev:0x800003 rw:0x1 filename:cli.log
Fri Jul 15 07:33:54 2022 jbd2/sda3-8_1629 kthreadd_2 sda sector:0x18c44128 size:4096 dev:0x800003 rw:0x411 *
案例六:nvme 盘因磁盘起始分区未 4K 对齐导致性能下降一半
blktrace -d /dev/nvme0n1
blkparse -i nvme0n1 -d nvme0n1.blktrace.bin >/dev/null
btt -i nvme0n1.blktrace.bin
--- a/drivers/block/nvme-core.c 2017-05-15 13:07:28.440514564 -0600
+++ b/drivers/block/nvme-core.c 2017-05-15 13:07:49.437515189 -0600
@@ -2336,7 +2336,9 @@
if (ctrl->mdts)
dev->max_hw_sectors = 1 << (ctrl->mdts + shift - 9);
if ((pdev->vendor == PCI_VENDOR_ID_INTEL) &&
- (pdev->device == 0x0953) && ctrl->vs[3]) {
+ ((pdev->device == 0x0953) ||
+ (pdev->device == 0x0a53) ||
+ (pdev->device == 0x0a54)) && ctrl->vs[3]) {
unsigned int max_hw_sectors;
dev->stripe_size = 1 << (ctrl->vs[3] + shift);
此时用如下命令观察有性能问题的盘每次传输的IO请求的起始扇区地址和数据量:
stap --all-modules -ve 'probe kernel.function("blk_mq_make_request") {if(execname()=="fio") {printf("start addr:%d size:%d\n",$bio->bi_sector*512,$bio->bi_size)}}'
发现一个很奇怪的问题,每次传输的 IO 请求的起始扇区地址除以 4K 后,余数都是0.25。
start addr:6361336923136 size:131072
//start addr除以4096后为 1553191012.25
start addr:6361870386176 size:131072
start addr:6361856361472 size:131072
start addr:6363297104896 size:131072
start addr:6363166819328 size:131072
start addr:6361150145536 size:131072
start addr:6362798507008 size:131072
//start addr除以4096后为 1553254948.25
start addr:6362132268032 size:131072
而在性能正常的 nvme 盘上,每次传输的 IO 请求的起始扇区地址处于4K,没余数,整除。
start addr:14315814912 size:131072
start addr:13303021568 size:131072
start addr:13914865664 size:131072
start addr:14319091712 size:131072
start addr:14378598400 size:131072
start addr:15401353216 size:131072
start addr:14310440960 size:131072
start addr:14828961792 size:131072
start addr:14549123072 size:131072
为什么有问题的 nvme 盘,每次传输的 IO 请求的起始扇区地址除以4K,余数都是0.25呢?这是 lvm 导致的?还是 ext4 文件系统有关?还有哪些地方会影响到 IO 请求的起始扇区地址?这个因素肯定是很原始的,与 ext4 或者 lvm 关系不大!此时服务器厂家做了一个测试,强制令 nvme 盘的 part 起始分区地址不 4K 对齐,就能复现 nvme 盘性能差问题。据此我们对比性能正常的和异常的 nvme 盘,有了发现。执行 fdisk -lu /dev/nvme0n1 查看 nvme 盘 part 分区信息:
性能异常的 nvme 盘
1:parted -s /dev/nvme0n1 mkpart primary 0 100%
Error: /dev/nvme0n1: unrecognised disk label
2:parted /dev/nvme0n1//需要重新创建分区
GNU Parted 3.1
Using /dev/nvme0n1
Welcome to GNU Parted! Type 'help' to view a list of commands.
(parted) mklabel
New disk label type? y
parted: invalid token: y
New disk label type? gpt
(parted) q
Information: You may need to update /etc/fstab.
3:parted -s /dev/nvme0n1 mkpart primary 0 100%
pvcreate /dev/nvme0n1p1
vgcreate docker-test /dev/nvme0n1p1
lvcreate -n test1 -L 20G docker-test
mkfs.ext4 /dev/mapper/docker--test-test1
mount /dev/mapper/docker--test-test1 /home/test1
最后启动 fio 压测,nvme 盘性能果然变差,iops 数据跟发生 nvme 性能差的盘一样。
怎么令这块盘性能恢复正常呢?按照如下命令
umount /home/test1
lvremove /dev/mapper/docker--test-test1
vgremove docker-test
pvremove /dev/nvme0n1p1
parted -s /dev/nvme0n1 rm 1
parted -s /dev/nvme0n1 mkpart primary 1 100%
总结
这6例批量磁盘故障,排查过程都很艰辛。但最终都查出了根本原因,不然影响很严重。我的感想是,要能灵活使用各种工具抓取问题现场。除此之外,还要有丰富 linux 内核、磁盘和阵列卡硬件等相关知识储备,尤其是 linux 内核。更重要的,排查问题的思路要灵活,一个思路走不通就要换个思路试试。不要放过任何一个细节,因为可能就是查出根因的关键。
Hujun Peng
云服务中心高级后端工程师
主要负责线上疑难内核问题解决、基于 systemtap 和 ebpf 开发内核级调试工具,擅长内核 block 层和内存管理。
OPPO 安第斯智能云(AndesBrain)是服务个人、家庭与开发者的泛终端智能云,致力于“让终端更智能”。作为 OPPO 三大核心技术之一,安第斯智能云提供端云协同的数据存储与智能计算服务,是万物互融的“数智大脑”。
本文分享自微信公众号 - 安第斯智能云(OPPO_tech)。
如有侵权,请联系 support@oschina.cn 删除。
本文参与“OSC源创计划”,欢迎正在阅读的你也加入,一起分享。