[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]
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才漏掉了这一情况。
相关文章
- 修复ext4 bug一个 - 12 25, 2012
- linux在多核处理器上的负载均衡原理（幻灯片） - 10 22, 2010
- [kernel] 内核缓冲的锁 - 08 11, 2010
分类
0 TrackBacks
Listed below are links to blogs that reference this entry: [kernel] 追踪cfq.
TrackBack URL for this entry: http://www.baidu.com/cgi-bin/blog/mt-tb.cgi/3100
6 Comments
留言：
关于文章
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.
你好，这个问题我们也非常关注，能透露下测试用的内核版本吗？
我们测试的是自己维护的打了部分patch的 2.6.32 内核，不过不要紧，跟upstream的2.6.32差不太多，一样能重现。
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版本的
不好意思，我最近一年才开始学习ext4，对nfs是一窍不通。
我个人猜测，你的这个nfs hang和nfs网络的速度有关，如果速度慢，那么某些nfs的调用就长时间无法完成，看上去就像hang了一样。
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.
唉，你这个报错信息发到回复评论里没法看了，要不你发我邮件吧