[kernel] 追踪cfq

前一阵子,我在一个SATA硬盘上模拟测试一个应用:
1. 创建十万个文件
2. 启动100个线程,每个线程都是对这十万个文件不停的调用 fgetxattr 和 fsetxattr 
在跑了大概40分钟后,dmesg里出现了一些warning:

May 25 18:50:48 core097002 kernel: [ 4680.778040] INFO: task kjournald:172 blocked for more than 120 seconds.
May 25 18:51:47 core097002 snmpd[2666]: Connection from UDP: [172.23.14.66]:33299
May 25 18:57:45 core097002 kernel: [ 4680.778181] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
May 25 18:57:45 core097002 kernel: [ 4680.778297] kjournald     D 0000000000000000     0   172      2 0x00000000
May 25 18:57:45 core097002 kernel: [ 4680.778304]  ffff880224efdd40 0000000000000046 0000000000000000 0000000000016980
May 25 18:57:45 core097002 kernel: [ 4680.778454]  ffff880224e84738 ffff880224e84240 ffff880224e84180 ffff880226de8240
May 25 18:57:45 core097002 snmpd[2666]: Received SNMP packet(s) from UDP: [172.23.14.66]:33299
May 25 18:57:45 core097002 kernel: [ 4680.778603]  ffff880224e84738 00000001003fda2c 00000000249100e0 0000000000000000
May 25 18:57:45 core097002 kernel: [ 4680.778753] Call Trace:
May 25 18:57:45 core097002 kernel: [ 4680.778818]  [<ffffffffa000a49c>] journal_commit_transaction+0x17c/0x1070 [jbd]
May 25 18:57:45 core097002 kernel: [ 4680.778938]  [<ffffffff81059742>] ? finish_task_switch+0x42/0xe0
May 25 18:57:46 core097002 kernel: [ 4680.779037]  [<ffffffff8108d520>] ? autoremove_wake_function+0x0/0x40
May 25 18:57:46 core097002 kernel: [ 4680.779145]  [<ffffffff810788b9>] ? try_to_del_timer_sync+0x49/0xe0
May 25 18:57:46 core097002 kernel: [ 4680.779255]  [<ffffffffa000e0b2>] kjournald+0xe2/0x250 [jbd]
May 25 18:57:46 core097002 kernel: [ 4680.779353]  [<ffffffff8108d520>] ? autoremove_wake_function+0x0/0x40
May 25 18:57:47 core097002 kernel: [ 4680.779451]  [<ffffffffa000dfd0>] ? kjournald+0x0/0x250 [jbd]
May 25 18:57:49 core097002 kernel: [ 4680.779535]  [<ffffffff8108d3a6>] kthread+0x96/0xa0
May 25 18:57:49 core097002 kernel: [ 4680.779621]  [<ffffffff8101408a>] child_rip+0xa/0x20
May 25 18:57:49 core097002 kernel: [ 4680.779710]  [<ffffffff8108d310>] ? kthread+0x0/0xa0
May 25 18:57:49 core097002 kernel: [ 4680.779797]  [<ffffffff81014080>] ? child_rip+0x0/0x20
May 25 18:57:49 core097002 kernel: [ 4680.779881] INFO: task syslogd:2430 blocked for more than 120 seconds.
May 25 18:57:49 core097002 kernel: [ 4680.779980] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
May 25 18:57:49 core097002 kernel: [ 4680.780105] syslogd       D 0000000000000000     0  2430      1 0x00000004
May 25 18:57:49 core097002 kernel: [ 4680.780110]  ffff880221ae98c8 0000000000000082 0000000000000000 0000000000016980
May 25 18:57:50 core097002 kernel: [ 4680.780260]  ffff88022505ec38 ffff88022505e740 ffff88022505e680 ffff880226e1e340
May 25 18:57:50 core097002 kernel: [ 4680.780408]  ffff88022505ec38 00000001003fd7ce 0000000023d91340 0000000000000000
May 25 18:57:50 core097002 kernel: [ 4680.780557] Call Trace:
May 25 18:57:50 core097002 kernel: [ 4680.780600]  [<ffffffff814ae453>] io_schedule+0x73/0xc0
May 25 18:57:50 core097002 kernel: [ 4680.780685]  [<ffffffff8118f925>] sync_buffer+0x45/0x50
May 25 18:57:50 core097002 kernel: [ 4680.780769]  [<ffffffff814aeb3a>] __wait_on_bit_lock+0x5a/0xb0
May 25 18:57:50 core097002 kernel: [ 4680.780872]  [<ffffffff8118f8e0>] ? sync_buffer+0x0/0x50
May 25 18:57:50 core097002 kernel: [ 4680.780960]  [<ffffffff8118f8e0>] ? sync_buffer+0x0/0x50
May 25 18:57:50 core097002 kernel: [ 4680.781046]  [<ffffffff814aec0d>] out_of_line_wait_on_bit_lock+0x7d/0x90
May 25 18:57:51 core097002 kernel: [ 4680.781161]  [<ffffffff8108d560>] ? wake_bit_function+0x0/0x40
May 25 18:57:51 core097002 kernel: [ 4680.781252]  [<ffffffff8118fb1c>] __lock_buffer+0x2c/0x30
May 25 18:57:51 core097002 kernel: [ 4680.781345]  [<ffffffffa0009c2f>] do_get_write_access+0x3bf/0x480 [jbd]
May 25 18:57:51 core097002 kernel: [ 4680.781449]  [<ffffffff811904ce>] ? __getblk+0x2e/0x240
May 25 18:57:51 core097002 kernel: [ 4680.781535]  [<ffffffffa0009e81>] journal_get_write_access+0x31/0x50 [jbd]
May 25 18:57:51 core097002 kernel: [ 4680.781656]  [<ffffffffa0031cd4>] __ext3_journal_get_write_access+0x34/0x70 [ext3]
May 25 18:57:51 core097002 kernel: [ 4680.781784]  [<ffffffffa0023ab3>] ext3_reserve_inode_write+0x83/0xb0 [ext3]
May 25 18:57:51 core097002 kernel: [ 4680.781904]  [<ffffffffa0023b16>] ext3_mark_inode_dirty+0x36/0x60 [ext3]

直观看起来,好像是jbd在提交事务时迟迟没有返回,那就是jbd的bug喽?于是我们在jbd里插入了很多trace_printk,企图找出问题,最后发现是jbd很久都无法lock_buffer,故而顿在那里。那是谁已经lock住buffer了呢?除了jbd写硬盘,那就只剩write-back了,于是接着trace write_back,发现是submit_bio后长时间没有返回,于是我问马涛“如果硬盘设备真的很慢,是不是会出现120秒IO都无法完成的情况”——马涛说可能性很低,与其怀疑硬盘,不如怀疑io-scheduler,于是我们把io-scheduler从cfq换成deadline,再跑测试,24小时都没有再出现问题了。

于是我得出结论:cfq太讲求公平,所以忽视了IO可能造成的超时,因此对于IO超时要求高的应用,最好用deadline。
但是马涛同学没有善罢甘休,他继续看cfq的实现代码,发现cfq给ASYNC型的IO分配了太低的权限,而write-back的IO都是ASYNC型的,所以被严重耽误了。于是马涛发了个邮件 http://marc.info/?l=linux-kernel&m=130761660610470&w=2 提出了这个问题,并把测试用例也附上了 http://code.taobao.org/trac/dirbench/browser/trunk/meta_test/press/set_vs_get ,vivek回了一个改进cfq的patch,我们打上这一patch后情况有所好转,但是没有根除,接着把cfq的参数slice_idle置为0,测试ok了。
感谢马涛同学穷根究底的精神,很值得我学习。

看来我们这一高频率操作文件系统meta-data的测试用例很特别,也许实际应用中很少有这样的所以cfq才漏掉了这一情况。


相关文章

分类

6 Comments

王宁 said:

你好,这个问题我们也非常关注,能透露下测试用的内核版本吗?

DongHao Author Profile Page said:

我们测试的是自己维护的打了部分patch的 2.6.32 内核,不过不要紧,跟upstream的2.6.32差不太多,一样能重现。

taotao1240 said:

hi,请教个问题,我的一个存储划了一个卷通过nfs共享出去,结果经常出现nfs hang住的情况,dmesg显示如下
INFO: task nfsd:3161 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
nfsd D 0000000000000000 0 3161 2
ffff81005ec2b9c8 0000000000000046 0000000000000000 0000004200000001
ffff81007e394900 ffffffff80850400 ffff81007f000000 ffff81007f000000
ffff81007d527330 ffffffff8078c350 ffff81007d527580 0000000000000000
Call Trace:
[] __qdisc_run+0xee/0x1c7
[] local_bh_enable+0x6b/0x87
[] dev_queue_xmit+0x292/0x2bf
[] __mutex_lock_slowpath+0x6f/0xaa
[] mutex_lock+0xa/0xb
[] xfs_write+0x1c2/0x6e8
[] _spin_unlock+0x10/0x2a
[] _spin_unlock_irq+0x11/0x2b
[] __down_read+0x34/0xa5
[] xfs_file_aio_write+0x0/0x4f
[] do_sync_readv_writev+0xc0/0x107
[] _spin_unlock_irqrestore+0x12/0x2d
[] autoremove_wake_function+0x0/0x2e
[] nfsd_acceptable+0x0/0xd2
[] rw_copy_check_uvector+0x6c/0xdd
[] do_readv_writev+0xb2/0x18b
[] nfsd_setuser+0x13f/0x1c1
[] nfsd_setuser_and_check_port+0x52/0x57
[] nfsd_vfs_write+0xea/0x2ea
[] xfs_file_open+0x26/0x2b
[] __dentry_open+0x186/0x26f
[] nfsd_write+0xc5/0xe2
[] nfsd3_proc_write+0xe1/0x100
[] nfsd_dispatch+0xee/0x1ca
[] svc_process+0x3e6/0x70e
[] _spin_unlock_irq+0x11/0x2b
[] __down_read+0x34/0xa5
[] nfsd+0x0/0x2b3
[] nfsd+0x1a3/0x2b3
[] child_rip+0xa/0x12
[] nfsd+0x0/0x2b3
[] nfsd+0x0/0x2b3
[] child_rip+0x0/0x12
google了下,没找到什么好的方法,只能手动重启机器,在ssh端reboot也不行。请问有没有什么方法解决

ps:2.6.26.2内核,nfs是V3版本的

DongHao Author Profile Page said:

不好意思,我最近一年才开始学习ext4,对nfs是一窍不通。
我个人猜测,你的这个nfs hang和nfs网络的速度有关,如果速度慢,那么某些nfs的调用就长时间无法完成,看上去就像hang了一样。

王文和 said:

hi,我这有个35T的存储,在做文件备份使用,使用rsync同步时有这些错误
本想该I/O调度方式试试,可存储太大,一改就卡主,同样的一台ext3的文件系统就没这个错误,所以想请你帮忙判断下。谢谢

Aug 6 17:14:19 zhuanma11 kernel: hpsa 0000:07:00.0: resetting device 0:0:0:1
Aug 6 17:14:20 zhuanma11 kernel: hpsa 0000:07:00.0: device is ready.
Aug 6 17:14:51 zhuanma11 kernel: hpsa 0000:07:00.0: resetting device 0:0:0:1
Aug 6 17:17:08 zhuanma11 kernel: INFO: task scsi_eh_0:314 blocked for more than 120 seconds.
Aug 6 17:17:08 zhuanma11 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 6 17:17:08 zhuanma11 kernel: scsi_eh_0 D 0000000000000000 0 314 2 0x00000000
Aug 6 17:17:08 zhuanma11 kernel: ffff880234c49bb0 0000000000000046 ffff880234c49b40 0000000000000000
Aug 6 17:17:08 zhuanma11 kernel: 0000000000000001 ffff88000002bb00 ffff88023571eac0 0000000000008024
Aug 6 17:17:08 zhuanma11 kernel: ffff88023571f078 ffff880234c49fd8 000000000000f4e8 ffff88023571f078
Aug 6 17:17:08 zhuanma11 kernel: Call Trace:
Aug 6 17:17:08 zhuanma11 kernel: [] schedule_timeout+0x215/0x2e0
Aug 6 17:17:08 zhuanma11 kernel: [] ? release_console_sem+0x1cf/0x220
Aug 6 17:17:08 zhuanma11 kernel: [] wait_for_common+0x123/0x180
Aug 6 17:17:08 zhuanma11 kernel: [] ? default_wake_function+0x0/0x20
Aug 6 17:17:08 zhuanma11 kernel: [] ? enqueue_cmd_and_start_io+0x11b/0x180 [hpsa]
Aug 6 17:17:08 zhuanma11 kernel: [] wait_for_completion+0x1d/0x20
Aug 6 17:17:08 zhuanma11 kernel: [] hpsa_eh_device_reset_handler+0x116/0x3c0 [hpsa]
Aug 6 17:17:08 zhuanma11 kernel: [] scsi_eh_ready_devs+0x231/0x850
Aug 6 17:17:08 zhuanma11 kernel: [] scsi_error_handler+0x483/0x660
Aug 6 17:17:08 zhuanma11 kernel: [] ? scsi_error_handler+0x0/0x660
Aug 6 17:17:08 zhuanma11 kernel: [] kthread+0x96/0xa0
Aug 6 17:17:08 zhuanma11 kernel: [] child_rip+0xa/0x20
Aug 6 17:17:08 zhuanma11 kernel: [] ? kthread+0x0/0xa0
Aug 6 17:17:08 zhuanma11 kernel: [] ? child_rip+0x0/0x20
Aug 6 17:17:08 zhuanma11 kernel: INFO: task jbd2/sda5-8:1421 blocked for more than 120 seconds.
Aug 6 17:17:08 zhuanma11 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 6 17:17:08 zhuanma11 kernel: jbd2/sda5-8 D 0000000000000002 0 1421 2 0x00000000
Aug 6 17:17:08 zhuanma11 kernel: ffff88022d4dfb30 0000000000000046 0000000000000000 ffff88015e1ac200
Aug 6 17:17:08 zhuanma11 kernel: ffff88022d4dfaa0 ffffffff81012b59 ffff88022d4dfae0 ffffffff8109b809
Aug 6 17:17:08 zhuanma11 kernel: ffff88022ecdb0f8 ffff88022d4dffd8 000000000000f4e8 ffff88022ecdb0f8
Aug 6 17:17:08 zhuanma11 kernel: Call Trace:
Aug 6 17:17:08 zhuanma11 kernel: [] ? read_tsc+0x9/0x20
Aug 6 17:17:08 zhuanma11 kernel: [] ? ktime_get_ts+0xa9/0xe0
Aug 6 17:17:08 zhuanma11 kernel: [] ? sync_page+0x0/0x50
Aug 6 17:17:08 zhuanma11 kernel: [] io_schedule+0x73/0xc0
Aug 6 17:17:08 zhuanma11 kernel: [] sync_page+0x3d/0x50
Aug 6 17:17:08 zhuanma11 kernel: [] __wait_on_bit+0x5f/0x90
Aug 6 17:17:08 zhuanma11 kernel: [] wait_on_page_bit+0x73/0x80
Aug 6 17:17:08 zhuanma11 kernel: [] ? wake_bit_function+0x0/0x50
Aug 6 17:17:08 zhuanma11 kernel: [] ? pagevec_lookup_tag+0x25/0x40
Aug 6 17:17:08 zhuanma11 kernel: [] wait_on_page_writeback_range+0xfb/0x190
Aug 6 17:17:08 zhuanma11 kernel: [] filemap_fdatawait+0x2f/0x40
Aug 6 17:17:08 zhuanma11 kernel: [] jbd2_journal_commit_transaction+0x7e9/0x14b0 [jbd2]
Aug 6 17:17:08 zhuanma11 kernel: [] ? __switch_to+0xd0/0x320
Aug 6 17:17:08 zhuanma11 kernel: [] ? try_to_del_timer_sync+0x7b/0xe0
Aug 6 17:17:08 zhuanma11 kernel: [] kjournald2+0xb8/0x220 [jbd2]
Aug 6 17:17:08 zhuanma11 kernel: [] ? autoremove_wake_function+0x0/0x40
Aug 6 17:17:08 zhuanma11 kernel: [] ? kjournald2+0x0/0x220 [jbd2]
Aug 6 17:17:08 zhuanma11 kernel: [] kthread+0x96/0xa0
Aug 6 17:17:08 zhuanma11 kernel: [] child_rip+0xa/0x20
Aug 6 17:17:08 zhuanma11 kernel: [] ? kthread+0x0/0xa0
Aug 6 17:17:08 zhuanma11 kernel: [] ? child_rip+0x0/0x20
Aug 6 17:17:08 zhuanma11 kernel: INFO: task flush-8:0:5770 blocked for more than 120 seconds.
Aug 6 17:17:08 zhuanma11 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

DongHao Author Profile Page said:

唉,你这个报错信息发到回复评论里没法看了,要不你发我邮件吧

留言:

关于文章

This page contains a single entry by DongHao published on 06 21, 2011 11:07 AM.

北戴河后记 was the previous entry in this blog.

ext2/ext3/ext4简介(PPT) is the next entry in this blog.

Find recent content on the main index or look in the 存档 to find all content.