xfs
[Top] [All Lists]

XFS and USB Hang on 2.6.35.13

To: xfs@xxxxxxxxxxx, Dave Chinner <david@xxxxxxxxxxxxx>
Subject: XFS and USB Hang on 2.6.35.13
From: Amit Sahrawat <amit.sahrawat83@xxxxxxxxx>
Date: Thu, 30 Jun 2011 16:57:42 +0530
Dkim-signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=mime-version:date:message-id:subject:from:to:content-type; bh=niD+7c7Y1GCyBAirgicChvCvlA0yhW/prMJWCUIbuTI=; b=sBtTkYxHeXeZzTaZ1T6qX75JVB6YUU1K1RmY7vGxsTjzNGEBVDxYLXYjObKTU6+zyW B4w9noet8olz00fQ6+9MDojtnd7FgFp9OVSGcst5xGcC3cvdzUBm3/APVPtRa1O2wkMt IHO9QvvELB8s0Dxu8d0jntWjTMg45Imr6bPtQ=

Hi All,

I encountered a hang on XFS during unplug.
Test Case:
#!/bin/sh
index=0
while [ "$?" == 0 ]
do
        index=$(($index+1))
        sync
        cp /mnt/1KB.txt /tmp/"$index".test
done
Where /mnt - mount point for vfat and /tmp mount point for XFS, both can be XFS also.

During this operation, unplug the USB. I am getting HANG almost everytime I unplug.

Kernel Version: 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)

Target=ARM

Logs Using Kernel Hung Task Feature
# sh test.sh
usb 2-1: USB disconnect, address 2
sd 0:0:0:0: [sda] Unhandled error code
sd 0:0:0:0: [sda] Result: hostbyte=0x01 driverbyte=0x00
sd 0:0:0:0: [sda] CDB: cdb[0]=0x2a: 2a 00 00 40 08 01 00 00 02 00
end_request: I/O error, dev sda, sector 4196353
sd 0:0:0:0: [sda] Unhandled error code
sd 0:0:0:0: [sda] Result: hostbyte=0x01 driverbyte=0x00
sd 0:0:0:0: [sda] CDB: cdb[0]=0x2a: 2a 00 00 40 08 08 00 00 18 00
end_request: I/O error, dev sda, sector 4196360
end_request: I/O error, dev sda, sector 6293645
Device sda3, XFS metadata write error block 0x1 in sda3
xfs_force_shutdown(sda3,0x1) called from line 1031 of file fs/xfs/xfs_buf_item.c.  Return address = 0xc0507b1c

INFO: task khubd:33 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
khubd         D c06c261c     0    33      2 0x00000000
Backtrace:
[<c06c2210>] (schedule+0x0/0x500) from [<c0523f4c>] (_xfs_log_force+0x230/0x284)
[<c0523d1c>] (_xfs_log_force+0x0/0x284) from [<c0524194>] (xfs_log_force+0x18/0x38)
[<c052417c>] (xfs_log_force+0x0/0x38) from [<c0544edc>] (xfs_sync_data+0x48/0x58)
 r4:00000001 r3:00000005
[<c0544e94>] (xfs_sync_data+0x0/0x58) from [<c0544f44>] (xfs_quiesce_data+0x24/0x80)
 r6:dbd0dd08 r5:00000001 r4:db46e000
[<c0544f20>] (xfs_quiesce_data+0x0/0x80) from [<c0542208>] (xfs_fs_sync_fs+0x24/0xe0)
 r6:dbd0dd08 r5:00000001 r4:db46e000 r3:c05421e4
[<c05421e4>] (xfs_fs_sync_fs+0x0/0xe0) from [<c048faf8>] (__sync_filesystem+0x84/0xa0)
 r8:0000001f r7:db46eae0 r6:dbd0dd08 r5:00000001 r4:db470200
[<c048fa74>] (__sync_filesystem+0x0/0xa0) from [<c048fbe0>] (sync_filesystem+0x58/0x60)
 r5:db470200 r4:db470200
[<c048fb88>] (sync_filesystem+0x0/0x60) from [<c0499124>] (fsync_bdev+0x20/0x44)
 r4:db89e0a0 r3:00000006
[<c0499104>] (fsync_bdev+0x0/0x44) from [<c056c6a0>] (invalidate_partition+0x20/0x3c)
 r5:dbdc1a00 r4:db89e0a0
[<c056c680>] (invalidate_partition+0x0/0x3c) from [<c04b8914>] (del_gendisk+0x34/0x140)
 r5:dbdc1a00 r4:db470e00
[<c04b88e0>] (del_gendisk+0x0/0x140) from [<c05c78e8>] (sd_remove+0x48/0x84)
 r6:db44a5e8 r5:c07e8fc4 r4:db46e4c0
[<c05c78a0>] (sd_remove+0x0/0x84) from [<c05b2860>] (__device_release_driver+0x6c/0xac)
 r6:60000013 r5:c07e901c r4:db46e4c0 r3:c05c78a0
[<c05b27f4>] (__device_release_driver+0x0/0xac) from [<c05b2978>] (device_release_driver+0x24/0x30)
 r5:db46e4c0 r4:db46e4f4
[<c05b2954>] (device_release_driver+0x0/0x30) from [<c05b1e58>] (bus_remove_device+0x7c/0x8c)
 r5:dad9d018 r4:db46e4c0
[<c05b1ddc>] (bus_remove_device+0x0/0x8c) from [<c05b03f0>] (device_del+0x118/0x170)
 r4:db46e4c0 r3:00000000
[<c05b02d8>] (device_del+0x0/0x170) from [<c05c4da4>] (__scsi_remove_device+0x48/0x90)
 r6:60000013 r5:db46e4c0 r4:db46e400 r3:c07e8760
[<c05c4d5c>] (__scsi_remove_device+0x0/0x90) from [<c05c2404>] (scsi_forget_host+0x48/0x6c)
 r5:db46e400 r4:db46e800
[<c05c23bc>] (scsi_forget_host+0x0/0x6c) from [<c05bc408>] (scsi_remove_host+0x7c/0x104)
 r5:db46e838 r4:db46e800
[<c05bc38c>] (scsi_remove_host+0x0/0x104) from [<c0612ffc>] (quiesce_and_remove_host+0x68/0x9c)
 r6:db46ebb4 r5:db46e800 r4:db46eab8 r3:00000000
[<c0612f94>] (quiesce_and_remove_host+0x0/0x9c) from [<c06130d0>] (usb_stor_disconnect+0x1c/0x28)
 r7:c07eb2f4 r6:db46ec00 r5:db49a200 r4:db46eab8
[<c06130b4>] (usb_stor_disconnect+0x0/0x28) from [<c0601668>] (usb_unbind_interface+0x54/0xdc)
 r4:db49a220 r3:c06130b4
[<c0601614>] (usb_unbind_interface+0x0/0xdc) from [<c05b2860>] (__device_release_driver+0x6c/0xac)
 r7:00000000 r6:db49a200 r5:c07eb2f4 r4:db49a220
[<c05b27f4>] (__device_release_driver+0x0/0xac) from [<c05b2978>] (device_release_driver+0x24/0x30)
 r5:db49a220 r4:db49a254
[<c05b2954>] (device_release_driver+0x0/0x30) from [<c05b1e58>] (bus_remove_device+0x7c/0x8c)
 r5:db46ec68 r4:db49a220
[<c05b1ddc>] (bus_remove_device+0x0/0x8c) from [<c05b03f0>] (device_del+0x118/0x170)
 r4:db49a220 r3:00000000
[<c05b02d8>] (device_del+0x0/0x170) from [<c05ff0c4>] (usb_disable_device+0x58/0xf8)
 r6:db49a200 r5:00000000 r4:db46ec00 r3:00000005
[<c05ff06c>] (usb_disable_device+0x0/0xf8) from [<c05fa978>] (usb_disconnect+0x98/0xf4)
 r7:dbd70200 r6:db46ec68 r5:db46ec9c r4:db46ec00
[<c05fa8e0>] (usb_disconnect+0x0/0xf4) from [<c05fafbc>] (hub_thread+0x3e4/0xd78)
[<c05fabd8>] (hub_thread+0x0/0xd78) from [<c041e6a0>] (kthread+0x84/0x8c)
[<c041e61c>] (kthread+0x0/0x8c) from [<c040c04c>] (do_exit+0x0/0x61c)
 r7:00000013 r6:c040c04c r5:c041e61c r4:dbc2df24
INFO: task xfslogd/1:40 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
xfslogd/1     D c06c261c     0    40      2 0x00000000
Backtrace:
[<c06c2210>] (schedule+0x0/0x500) from [<c0523f4c>] (_xfs_log_force+0x230/0x284)
[<c0523d1c>] (_xfs_log_force+0x0/0x284) from [<c0524148>] (xfs_log_force_umount+0x1a8/0x1dc)
[<c0523fa0>] (xfs_log_force_umount+0x0/0x1dc) from [<c053753c>] (xfs_do_force_shutdown+0x70/0x164)
[<c05374cc>] (xfs_do_force_shutdown+0x0/0x164) from [<c0507b1c>] (xfs_buf_iodone_callbacks+0x14c/0x184)
 r7:db469f20 r6:db46e000 r5:daf58968 r4:db445ec0
[<c05079d0>] (xfs_buf_iodone_callbacks+0x0/0x184) from [<c053b8e0>] (xfs_buf_iodone_work+0x58/0x7c)
 r7:c0bed1d0 r6:c053b888 r5:db468000 r4:db445ec0
[<c053b888>] (xfs_buf_iodone_work+0x0/0x7c) from [<c041a8bc>] (worker_thread+0x154/0x1e4)
 r4:c0bed1c0 r3:00000001
[<c041a768>] (worker_thread+0x0/0x1e4) from [<c041e6a0>] (kthread+0x84/0x8c)
[<c041e61c>] (kthread+0x0/0x8c) from [<c040c04c>] (do_exit+0x0/0x61c)
 r7:00000013 r6:c040c04c r5:c041e61c r4:dbc2decc
INFO: task sync:164 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
sync          D c06c261c     0   164    136 0x00000000
Backtrace:
[<c06c2210>] (schedule+0x0/0x500) from [<c06c297c>] (schedule_timeout+0x20/0x200)
[<c06c295c>] (schedule_timeout+0x0/0x200) from [<c06c20d0>] (wait_for_common+0xd0/0x164)
 r7:db44534c r6:daed4000 r5:7fffffff r4:db445348
[<c06c2000>] (wait_for_common+0x0/0x164) from [<c06c220c>] (wait_for_completion+0x18/0x1c)
[<c06c21f4>] (wait_for_completion+0x0/0x1c) from [<c053a74c>] (xfs_buf_iowait+0x54/0x5c)
[<c053a6f8>] (xfs_buf_iowait+0x0/0x5c) from [<c053bb9c>] (xfs_flush_buftarg+0x14c/0x180)
 r4:db4452c0 r3:db4452ec
[<c053ba50>] (xfs_flush_buftarg+0x0/0x180) from [<c0544f5c>] (xfs_quiesce_data+0x3c/0x80)
 r7:c048fb14 r6:00000000 r5:00000001 r4:db46e000
[<c0544f20>] (xfs_quiesce_data+0x0/0x80) from [<c0542208>] (xfs_fs_sync_fs+0x24/0xe0)
 r6:daed5f84 r5:00000001 r4:db46e000 r3:c05421e4
[<c05421e4>] (xfs_fs_sync_fs+0x0/0xe0) from [<c048faf8>] (__sync_filesystem+0x84/0xa0)
 r8:c0394264 r7:c048fb14 r6:daed5f84 r5:00000001 r4:db470200
[<c048fa74>] (__sync_filesystem+0x0/0xa0) from [<c048fb40>] (sync_one_sb+0x2c/0x30)
 r5:db470240 r4:db470200
[<c048fb14>] (sync_one_sb+0x0/0x30) from [<c0470ca0>] (iterate_supers+0x74/0xb8)
[<c0470c2c>] (iterate_supers+0x0/0xb8) from [<c048fa30>] (sync_filesystems+0x20/0x2c)
 r7:00000024 r6:bef48db4 r5:00000001 r4:000f78be
[<c048fa10>] (sync_filesystems+0x0/0x2c) from [<c048fb68>] (sys_sync+0x24/0x44)
[<c048fb44>] (sys_sync+0x0/0x44) from [<c03940e0>] (ret_fast_syscall+0x0/0x30)

On Analysis:
I found that both the "khubd" and "xfslogd" are waiting for signal (sv_wait() (xfs_log.c - _xfs_log_force()))
In normal case:
I found that xfslogd does the callback and signal that through xlog_state_do_callback() ( sv_broadcast(&iclog->ic_force_wait) - xfs_log.c);
But during hang, xfslogd itself is waiting. So who does the callback in this case?
Is xfslogd supposed to wait(sv_wait(&iclog->ic_force_wait, PINOD, &log->l_icloglock, s);) ?

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.

Thanks & Regards,
Amit Sahrawat

<Prev in Thread] Current Thread [Next in Thread>