<p>Hi All,</p><div>I encountered a hang on XFS during unplug.<br><strong>Test Case:</strong><br>#!/bin/sh<br>index=0<br>while [ "$?" == 0 ]<br>do<br> index=$(($index+1))<br> sync<br> cp /mnt/1KB.txt /tmp/"$index".test<br>
done</div><div>Where /mnt - mount point for vfat and /tmp mount point for XFS, both can be XFS also.</div><p>During this operation, unplug the USB. I am getting HANG almost everytime I unplug.</p><p><strong>Kernel Version:</strong> 2.6.35.13 (extremely sorry, I know next question will be why am I not using TOT kernel - I tried but my PC does not boot up with the latest one)</p>
<p><strong>Target=ARM</strong></p><div><strong>Logs Using Kernel Hung Task Feature</strong></div><div># sh test.sh <br>usb 2-1: USB disconnect, address 2<br>sd 0:0:0:0: [sda] Unhandled error code<br>sd 0:0:0:0: [sda] Result: hostbyte=0x01 driverbyte=0x00<br>
sd 0:0:0:0: [sda] CDB: cdb[0]=0x2a: 2a 00 00 40 08 01 00 00 02 00<br>end_request: I/O error, dev sda, sector 4196353<br>sd 0:0:0:0: [sda] Unhandled error code<br>sd 0:0:0:0: [sda] Result: hostbyte=0x01 driverbyte=0x00<br>
sd 0:0:0:0: [sda] CDB: cdb[0]=0x2a: 2a 00 00 40 08 08 00 00 18 00<br>end_request: I/O error, dev sda, sector 4196360<br>end_request: I/O error, dev sda, sector 6293645<br>Device sda3, XFS metadata write error block 0x1 in sda3<br>
xfs_force_shutdown(sda3,0x1) called from line 1031 of file fs/xfs/xfs_buf_item.c. Return address = 0xc0507b1c</div><p><strong>INFO: task khubd:</strong>33 blocked for more than 120 seconds.<br>"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.<br>
khubd D c06c261c 0 33 2 0x00000000<br>Backtrace: <br>[<c06c2210>] (schedule+0x0/0x500) from [<c0523f4c>] (_xfs_log_force+0x230/0x284)<br>[<c0523d1c>] (_xfs_log_force+0x0/0x284) from [<c0524194>] (xfs_log_force+0x18/0x38)<br>
[<c052417c>] (xfs_log_force+0x0/0x38) from [<c0544edc>] (xfs_sync_data+0x48/0x58)<br> r4:00000001 r3:00000005<br>[<c0544e94>] (xfs_sync_data+0x0/0x58) from [<c0544f44>] (xfs_quiesce_data+0x24/0x80)<br>
r6:dbd0dd08 r5:00000001 r4:db46e000<br>[<c0544f20>] (xfs_quiesce_data+0x0/0x80) from [<c0542208>] (xfs_fs_sync_fs+0x24/0xe0)<br> r6:dbd0dd08 r5:00000001 r4:db46e000 r3:c05421e4<br>[<c05421e4>] (xfs_fs_sync_fs+0x0/0xe0) from [<c048faf8>] (__sync_filesystem+0x84/0xa0)<br>
r8:0000001f r7:db46eae0 r6:dbd0dd08 r5:00000001 r4:db470200<br>[<c048fa74>] (__sync_filesystem+0x0/0xa0) from [<c048fbe0>] (sync_filesystem+0x58/0x60)<br> r5:db470200 r4:db470200<br>[<c048fb88>] (sync_filesystem+0x0/0x60) from [<c0499124>] (fsync_bdev+0x20/0x44)<br>
r4:db89e0a0 r3:00000006<br>[<c0499104>] (fsync_bdev+0x0/0x44) from [<c056c6a0>] (invalidate_partition+0x20/0x3c)<br> r5:dbdc1a00 r4:db89e0a0<br>[<c056c680>] (invalidate_partition+0x0/0x3c) from [<c04b8914>] (del_gendisk+0x34/0x140)<br>
r5:dbdc1a00 r4:db470e00<br>[<c04b88e0>] (del_gendisk+0x0/0x140) from [<c05c78e8>] (sd_remove+0x48/0x84)<br> r6:db44a5e8 r5:c07e8fc4 r4:db46e4c0<br>[<c05c78a0>] (sd_remove+0x0/0x84) from [<c05b2860>] (__device_release_driver+0x6c/0xac)<br>
r6:60000013 r5:c07e901c r4:db46e4c0 r3:c05c78a0<br>[<c05b27f4>] (__device_release_driver+0x0/0xac) from [<c05b2978>] (device_release_driver+0x24/0x30)<br> r5:db46e4c0 r4:db46e4f4<br>[<c05b2954>] (device_release_driver+0x0/0x30) from [<c05b1e58>] (bus_remove_device+0x7c/0x8c)<br>
r5:dad9d018 r4:db46e4c0<br>[<c05b1ddc>] (bus_remove_device+0x0/0x8c) from [<c05b03f0>] (device_del+0x118/0x170)<br> r4:db46e4c0 r3:00000000<br>[<c05b02d8>] (device_del+0x0/0x170) from [<c05c4da4>] (__scsi_remove_device+0x48/0x90)<br>
r6:60000013 r5:db46e4c0 r4:db46e400 r3:c07e8760<br>[<c05c4d5c>] (__scsi_remove_device+0x0/0x90) from [<c05c2404>] (scsi_forget_host+0x48/0x6c)<br> r5:db46e400 r4:db46e800<br>[<c05c23bc>] (scsi_forget_host+0x0/0x6c) from [<c05bc408>] (scsi_remove_host+0x7c/0x104)<br>
r5:db46e838 r4:db46e800<br>[<c05bc38c>] (scsi_remove_host+0x0/0x104) from [<c0612ffc>] (quiesce_and_remove_host+0x68/0x9c)<br> r6:db46ebb4 r5:db46e800 r4:db46eab8 r3:00000000<br>[<c0612f94>] (quiesce_and_remove_host+0x0/0x9c) from [<c06130d0>] (usb_stor_disconnect+0x1c/0x28)<br>
r7:c07eb2f4 r6:db46ec00 r5:db49a200 r4:db46eab8<br>[<c06130b4>] (usb_stor_disconnect+0x0/0x28) from [<c0601668>] (usb_unbind_interface+0x54/0xdc)<br> r4:db49a220 r3:c06130b4<br>[<c0601614>] (usb_unbind_interface+0x0/0xdc) from [<c05b2860>] (__device_release_driver+0x6c/0xac)<br>
r7:00000000 r6:db49a200 r5:c07eb2f4 r4:db49a220<br>[<c05b27f4>] (__device_release_driver+0x0/0xac) from [<c05b2978>] (device_release_driver+0x24/0x30)<br> r5:db49a220 r4:db49a254<br>[<c05b2954>] (device_release_driver+0x0/0x30) from [<c05b1e58>] (bus_remove_device+0x7c/0x8c)<br>
r5:db46ec68 r4:db49a220<br>[<c05b1ddc>] (bus_remove_device+0x0/0x8c) from [<c05b03f0>] (device_del+0x118/0x170)<br> r4:db49a220 r3:00000000<br>[<c05b02d8>] (device_del+0x0/0x170) from [<c05ff0c4>] (usb_disable_device+0x58/0xf8)<br>
r6:db49a200 r5:00000000 r4:db46ec00 r3:00000005<br>[<c05ff06c>] (usb_disable_device+0x0/0xf8) from [<c05fa978>] (usb_disconnect+0x98/0xf4)<br> r7:dbd70200 r6:db46ec68 r5:db46ec9c r4:db46ec00<br>[<c05fa8e0>] (usb_disconnect+0x0/0xf4) from [<c05fafbc>] (hub_thread+0x3e4/0xd78)<br>
[<c05fabd8>] (hub_thread+0x0/0xd78) from [<c041e6a0>] (kthread+0x84/0x8c)<br>[<c041e61c>] (kthread+0x0/0x8c) from [<c040c04c>] (do_exit+0x0/0x61c)<br> r7:00000013 r6:c040c04c r5:c041e61c r4:dbc2df24<br>
<strong>INFO: task xfslogd/1</strong>:40 blocked for more than 120 seconds.<br>"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.<br>xfslogd/1 D c06c261c 0 40 2 0x00000000<br>
Backtrace: <br>[<c06c2210>] (schedule+0x0/0x500) from [<c0523f4c>] (_xfs_log_force+0x230/0x284)<br>[<c0523d1c>] (_xfs_log_force+0x0/0x284) from [<c0524148>] (xfs_log_force_umount+0x1a8/0x1dc)<br>[<c0523fa0>] (xfs_log_force_umount+0x0/0x1dc) from [<c053753c>] (xfs_do_force_shutdown+0x70/0x164)<br>
[<c05374cc>] (xfs_do_force_shutdown+0x0/0x164) from [<c0507b1c>] (xfs_buf_iodone_callbacks+0x14c/0x184)<br> r7:db469f20 r6:db46e000 r5:daf58968 r4:db445ec0<br>[<c05079d0>] (xfs_buf_iodone_callbacks+0x0/0x184) from [<c053b8e0>] (xfs_buf_iodone_work+0x58/0x7c)<br>
r7:c0bed1d0 r6:c053b888 r5:db468000 r4:db445ec0<br>[<c053b888>] (xfs_buf_iodone_work+0x0/0x7c) from [<c041a8bc>] (worker_thread+0x154/0x1e4)<br> r4:c0bed1c0 r3:00000001<br>[<c041a768>] (worker_thread+0x0/0x1e4) from [<c041e6a0>] (kthread+0x84/0x8c)<br>
[<c041e61c>] (kthread+0x0/0x8c) from [<c040c04c>] (do_exit+0x0/0x61c)<br> r7:00000013 r6:c040c04c r5:c041e61c r4:dbc2decc<br><strong>INFO: task sync:</strong>164 blocked for more than 120 seconds.<br>"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.<br>
sync D c06c261c 0 164 136 0x00000000<br>Backtrace: <br>[<c06c2210>] (schedule+0x0/0x500) from [<c06c297c>] (schedule_timeout+0x20/0x200)<br>[<c06c295c>] (schedule_timeout+0x0/0x200) from [<c06c20d0>] (wait_for_common+0xd0/0x164)<br>
r7:db44534c r6:daed4000 r5:7fffffff r4:db445348<br>[<c06c2000>] (wait_for_common+0x0/0x164) from [<c06c220c>] (wait_for_completion+0x18/0x1c)<br>[<c06c21f4>] (wait_for_completion+0x0/0x1c) from [<c053a74c>] (xfs_buf_iowait+0x54/0x5c)<br>
[<c053a6f8>] (xfs_buf_iowait+0x0/0x5c) from [<c053bb9c>] (xfs_flush_buftarg+0x14c/0x180)<br> r4:db4452c0 r3:db4452ec<br>[<c053ba50>] (xfs_flush_buftarg+0x0/0x180) from [<c0544f5c>] (xfs_quiesce_data+0x3c/0x80)<br>
r7:c048fb14 r6:00000000 r5:00000001 r4:db46e000<br>[<c0544f20>] (xfs_quiesce_data+0x0/0x80) from [<c0542208>] (xfs_fs_sync_fs+0x24/0xe0)<br> r6:daed5f84 r5:00000001 r4:db46e000 r3:c05421e4<br>[<c05421e4>] (xfs_fs_sync_fs+0x0/0xe0) from [<c048faf8>] (__sync_filesystem+0x84/0xa0)<br>
r8:c0394264 r7:c048fb14 r6:daed5f84 r5:00000001 r4:db470200<br>[<c048fa74>] (__sync_filesystem+0x0/0xa0) from [<c048fb40>] (sync_one_sb+0x2c/0x30)<br> r5:db470240 r4:db470200<br>[<c048fb14>] (sync_one_sb+0x0/0x30) from [<c0470ca0>] (iterate_supers+0x74/0xb8)<br>
[<c0470c2c>] (iterate_supers+0x0/0xb8) from [<c048fa30>] (sync_filesystems+0x20/0x2c)<br> r7:00000024 r6:bef48db4 r5:00000001 r4:000f78be<br>[<c048fa10>] (sync_filesystems+0x0/0x2c) from [<c048fb68>] (sys_sync+0x24/0x44)<br>
[<c048fb44>] (sys_sync+0x0/0x44) from [<c03940e0>] (ret_fast_syscall+0x0/0x30)</p><div><strong>On Analysis:</strong></div><div>I found that both the <strong>"khubd"</strong> and <strong>"xfslogd"</strong> are waiting for signal (sv_wait() (xfs_log.c - _xfs_log_force()))<br>
<strong>In normal case:</strong><br>I found that xfslogd does the callback and signal that through xlog_state_do_callback() ( sv_broadcast(&iclog->ic_force_wait) - xfs_log.c);<br>But during hang, xfslogd itself is waiting. So who does the callback in this case?<br>
Is xfslogd supposed to wait(sv_wait(&iclog->ic_force_wait, PINOD, &log->l_icloglock, s);) ?</div><p>Please let me know in case of any issues also update if my analysis is right or wrong. I do not expect a solution but please guide me in my findings.</p>
<p>Thanks & Regards,<br>Amit Sahrawat<br></p>