Linux-next: very slow disk write speed: WARNING: CPU: 4 PID: 12891 at fs/inode.c:390 ihold+0x30/0x40()
With the recent linux-next tree (e.g., next-20150909), I can easily get the below callstack (see the end of the mail) when I run some heavy I/O workloads, like building a kernel with "make -j16". After the callstack happens, "dd if=/dev/zero of=zero.bin bs=1M" shows the disk write speed goes down to a value far less than 1MB/s (I get the speed by iostat or iotop), while the normal write speed should be 100MB/s. However, at this time, "cat a_big_file > /dev/null" shows the disk read speed is still normal, e.g., >100MB/s. Though I found the issue in Hyper-V VM, I don't think it's caused by a change in the Linux Hyper-V drivers, because I don't see any change in the Linux Hyper-V drivers can cause this issue. NOTE: only the linux-next tree (maybe since some Aug version or even July version?) has the issue. The latest Linus's tree and Greg's char-misc.git tree don't have the issue. With respect to the Linux Hyper-V drivers, I'm sure there is no real difference between linux-next and Greg's char-misc.git. Any idea? Thanks! -- Dexuan The callstack is: [ 1799.156370] ld (36538) used greatest stack depth: 12344 bytes left [ 1860.388015] [ cut here ] [ 1860.388015] WARNING: CPU: 4 PID: 12891 at fs/inode.c:390 ihold+0x30/0x40() [ 1860.388015] Modules linked in: xt_tcpudp iptable_filter ip_tables x_tables i2c_piix4 i2c_core serio_raw evdev hid_generic hid_hyperv hid hyperv_keyboard autofs4 hv_netvsc hv_utils hv_storvsc psmouse hyperv_fb atkbd hv_vmbus [ 1860.389888] CPU: 4 PID: 12891 Comm: kworker/u130:3 Not tainted 4.2.0-next-20150909 #1 [ 1860.389888] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS 090006 05/23/2012 [ 1860.389888] Workqueue: writeback wb_workfn (flush-8:16) [ 1860.389888] 8c808fa0 880368253a60 8c30d002 [ 1860.389888] 880368253a98 8c056396 880291eb0870 880291eb08f0 [ 1860.389888] 88044e142120 0001 0641 880368253aa8 [ 1860.389888] Call Trace: [ 1860.389888] [] dump_stack+0x44/0x62 [ 1860.389888] [] warn_slowpath_common+0x86/0xc0 [ 1860.389888] [] warn_slowpath_null+0x1a/0x20 [ 1860.389888] [] ihold+0x30/0x40 [ 1860.389888] [] inode_switch_wbs+0x1b6/0x270 [ 1860.389888] [] ? inode_switch_wbs+0x72/0x270 [ 1860.389888] [] wbc_detach_inode+0x1a1/0x1d0 [ 1860.389888] [] writeback_sb_inodes+0x27e/0x480 [ 1860.389888] [] __writeback_inodes_wb+0x89/0xc0 [ 1860.389888] [] wb_writeback+0x207/0x280 [ 1860.389888] [] wb_workfn+0x299/0x3d0 [ 1860.389888] [] process_one_work+0x1b8/0x4b0 [ 1860.389888] [] ? process_one_work+0x14f/0x4b0 [ 1860.389888] [] worker_thread+0x4b/0x440 [ 1860.389888] [] ? rescuer_thread+0x2d0/0x2d0 [ 1860.389888] [] ? rescuer_thread+0x2d0/0x2d0 [ 1860.389888] [] kthread+0xf3/0x110 [ 1860.389888] [] ? kthread_create_on_node+0x230/0x230 [ 1860.389888] [] ret_from_fork+0x3f/0x70 [ 1860.389888] [] ? kthread_create_on_node+0x230/0x230 [ 1860.389888] ---[ end trace b4922878dcd2b65d ]--- [ 1865.692016] kworker/dying (163) used greatest stack depth: 11976 bytes left [ 1943.756018] [ cut here ] [ 1943.756018] WARNING: CPU: 3 PID: 339 at fs/inode.c:390 ihold+0x30/0x40() [ 1943.756018] Modules linked in: xt_tcpudp iptable_filter ip_tables x_tables i2c_piix4 i2c_core serio_raw evdev hid_generic hid_hyperv hid hyperv_keyboard autofs4 hv_netvsc hv_utils hv_storvsc psmouse hyperv_fb atkbd hv_vmbus [ 1943.756018] CPU: 3 PID: 339 Comm: kworker/u129:1 Tainted: GW 4.2.0-next-20150909 #1 [ 1943.764006] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS 090006 05/23/2012 [ 1943.764006] Workqueue: writeback wb_workfn (flush-8:16) [ 1943.764006] 8c808fa0 8802967f7a60 8c30d002 [ 1943.764006] 8802967f7a98 8c056396 880295417170 8802954171f0 [ 1943.764006] 880294864000 0001 0757 8802967f7aa8 [ 1943.764006] Call Trace: [ 1943.764006] [] dump_stack+0x44/0x62 [ 1943.764006] [] warn_slowpath_common+0x86/0xc0 [ 1943.764006] [] warn_slowpath_null+0x1a/0x20 [ 1943.764006] [] ihold+0x30/0x40 [ 1943.764006] [] inode_switch_wbs+0x1b6/0x270 [ 1943.764006] [] ? inode_switch_wbs+0x72/0x270 [ 1943.764793] [] wbc_detach_inode+0x1a1/0x1d0 [ 1943.764793] [] writeback_sb_inodes+0x27e/0x480 [ 1943.768142] [] __writeback_inodes_wb+0x89/0xc0 [ 1943.768142] [] wb_writeback+0x207/0x280 [ 1943.772350] [] wb_workfn+0x299/0x3d0 [ 1943.772656] [] process_one_work+0x1b8/0x4b0 [ 1943.780012] [] ? process_one_work+0x14f/0x4b0 [ 1943.780012] [] worker_thread+0x4b/0x440 [ 1943.780012] [] ? rescuer_thread+0x2d0/0x2d0 [ 1943.780614] [] ? rescuer_thread+0x2d0/0x2d0 [ 1943.780614] [] kthread+0xf3/0x110 [ 1943.784614] [] ? kthread_create_on_node+0x230/0x230 [ 1943.784614] [] ret_from_fork+0x3f/0x70 [ 1943.784614] [] ? kthread_create_on_node+0x230/0x230 [ 1943.788386] ---[ end trace
Linux-next: very slow disk write speed: WARNING: CPU: 4 PID: 12891 at fs/inode.c:390 ihold+0x30/0x40()
With the recent linux-next tree (e.g., next-20150909), I can easily get the below callstack (see the end of the mail) when I run some heavy I/O workloads, like building a kernel with "make -j16". After the callstack happens, "dd if=/dev/zero of=zero.bin bs=1M" shows the disk write speed goes down to a value far less than 1MB/s (I get the speed by iostat or iotop), while the normal write speed should be 100MB/s. However, at this time, "cat a_big_file > /dev/null" shows the disk read speed is still normal, e.g., >100MB/s. Though I found the issue in Hyper-V VM, I don't think it's caused by a change in the Linux Hyper-V drivers, because I don't see any change in the Linux Hyper-V drivers can cause this issue. NOTE: only the linux-next tree (maybe since some Aug version or even July version?) has the issue. The latest Linus's tree and Greg's char-misc.git tree don't have the issue. With respect to the Linux Hyper-V drivers, I'm sure there is no real difference between linux-next and Greg's char-misc.git. Any idea? Thanks! -- Dexuan The callstack is: [ 1799.156370] ld (36538) used greatest stack depth: 12344 bytes left [ 1860.388015] [ cut here ] [ 1860.388015] WARNING: CPU: 4 PID: 12891 at fs/inode.c:390 ihold+0x30/0x40() [ 1860.388015] Modules linked in: xt_tcpudp iptable_filter ip_tables x_tables i2c_piix4 i2c_core serio_raw evdev hid_generic hid_hyperv hid hyperv_keyboard autofs4 hv_netvsc hv_utils hv_storvsc psmouse hyperv_fb atkbd hv_vmbus [ 1860.389888] CPU: 4 PID: 12891 Comm: kworker/u130:3 Not tainted 4.2.0-next-20150909 #1 [ 1860.389888] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS 090006 05/23/2012 [ 1860.389888] Workqueue: writeback wb_workfn (flush-8:16) [ 1860.389888] 8c808fa0 880368253a60 8c30d002 [ 1860.389888] 880368253a98 8c056396 880291eb0870 880291eb08f0 [ 1860.389888] 88044e142120 0001 0641 880368253aa8 [ 1860.389888] Call Trace: [ 1860.389888] [] dump_stack+0x44/0x62 [ 1860.389888] [] warn_slowpath_common+0x86/0xc0 [ 1860.389888] [] warn_slowpath_null+0x1a/0x20 [ 1860.389888] [] ihold+0x30/0x40 [ 1860.389888] [] inode_switch_wbs+0x1b6/0x270 [ 1860.389888] [] ? inode_switch_wbs+0x72/0x270 [ 1860.389888] [] wbc_detach_inode+0x1a1/0x1d0 [ 1860.389888] [] writeback_sb_inodes+0x27e/0x480 [ 1860.389888] [] __writeback_inodes_wb+0x89/0xc0 [ 1860.389888] [] wb_writeback+0x207/0x280 [ 1860.389888] [] wb_workfn+0x299/0x3d0 [ 1860.389888] [] process_one_work+0x1b8/0x4b0 [ 1860.389888] [] ? process_one_work+0x14f/0x4b0 [ 1860.389888] [] worker_thread+0x4b/0x440 [ 1860.389888] [] ? rescuer_thread+0x2d0/0x2d0 [ 1860.389888] [] ? rescuer_thread+0x2d0/0x2d0 [ 1860.389888] [] kthread+0xf3/0x110 [ 1860.389888] [] ? kthread_create_on_node+0x230/0x230 [ 1860.389888] [] ret_from_fork+0x3f/0x70 [ 1860.389888] [] ? kthread_create_on_node+0x230/0x230 [ 1860.389888] ---[ end trace b4922878dcd2b65d ]--- [ 1865.692016] kworker/dying (163) used greatest stack depth: 11976 bytes left [ 1943.756018] [ cut here ] [ 1943.756018] WARNING: CPU: 3 PID: 339 at fs/inode.c:390 ihold+0x30/0x40() [ 1943.756018] Modules linked in: xt_tcpudp iptable_filter ip_tables x_tables i2c_piix4 i2c_core serio_raw evdev hid_generic hid_hyperv hid hyperv_keyboard autofs4 hv_netvsc hv_utils hv_storvsc psmouse hyperv_fb atkbd hv_vmbus [ 1943.756018] CPU: 3 PID: 339 Comm: kworker/u129:1 Tainted: GW 4.2.0-next-20150909 #1 [ 1943.764006] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS 090006 05/23/2012 [ 1943.764006] Workqueue: writeback wb_workfn (flush-8:16) [ 1943.764006] 8c808fa0 8802967f7a60 8c30d002 [ 1943.764006] 8802967f7a98 8c056396 880295417170 8802954171f0 [ 1943.764006] 880294864000 0001 0757 8802967f7aa8 [ 1943.764006] Call Trace: [ 1943.764006] [] dump_stack+0x44/0x62 [ 1943.764006] [] warn_slowpath_common+0x86/0xc0 [ 1943.764006] [] warn_slowpath_null+0x1a/0x20 [ 1943.764006] [] ihold+0x30/0x40 [ 1943.764006] [] inode_switch_wbs+0x1b6/0x270 [ 1943.764006] [] ? inode_switch_wbs+0x72/0x270 [ 1943.764793] [] wbc_detach_inode+0x1a1/0x1d0 [ 1943.764793] [] writeback_sb_inodes+0x27e/0x480 [ 1943.768142] [] __writeback_inodes_wb+0x89/0xc0 [ 1943.768142] [] wb_writeback+0x207/0x280 [ 1943.772350] [] wb_workfn+0x299/0x3d0 [ 1943.772656] [] process_one_work+0x1b8/0x4b0 [ 1943.780012] [] ? process_one_work+0x14f/0x4b0 [ 1943.780012] [] worker_thread+0x4b/0x440 [ 1943.780012] [] ? rescuer_thread+0x2d0/0x2d0 [ 1943.780614] [] ? rescuer_thread+0x2d0/0x2d0 [ 1943.780614] [] kthread+0xf3/0x110 [ 1943.784614] [] ? kthread_create_on_node+0x230/0x230 [ 1943.784614] [] ret_from_fork+0x3f/0x70 [ 1943.784614] [] ? kthread_create_on_node+0x230/0x230 [ 1943.788386] ---[ end trace
