xfs task blocked for more than 120 seconds

Sami Liedes
2012-01-30T00:20:35Z

Hi!

Following the LWN coverage of LCA talk on XFS, I decided to give XFS a
try again. So I decided to try XFS on my backup partition.

My setup is as follows:

* The relevant disk, containing both the ext4 partition
(/media/backup) and the xfs partition (/media/xfstest) are on the
same 2 TB disk, which is a Western Digital Caviar Green SATA3 drive
(SMART reports the device model to be WDC WD20EARX-00PASB0). The
spindle speed of the model is reported to be "closer to 5400 than
7200 rpm".

* The ext4 partition is roughly 1 TB in size and the xfs partition
roughly 800 GB

* I'm using LVM; the logical volumes are /dev/rootvg/backup and
/dev/rootvg/xfstest

* These LVs are both LUKS (dm-crypt) partitions, encrypted with
cbc-essiv:sha256

* The computer is a Core i7 2600 3.4 GHz with 4 cores and HT
(therefore shows as 8 cores) with 8 GiB main memory. AES-NI
instructions are supported and disk crypto generally (with ext4)
works at transparent speeds.

* I'm running Debian unstable amd64 with vanilla (non-Debian) 3.2.2
kernel

* I believe both the disk and the main memory are in good health;
particularly with ext4 there hasn't been any problems

* The backup data is generated by BackupPC. It generally consists of a
large pool of files named by sha-1 hashes (~105 GB of files), plus
lots of trees of hardlinks to these in a structure not unlike
typical home directories and / and /usr trees. I *think* the hard
links may be a red herring and I suspect the problem has something
to do with xfs--dm-crypt interaction, but I'm not sure.

So, to copy the contents of the backup partition -- BackupPC data --
to the XFS drive, I did the following (the tar line is from shell
history, the lines before it are from my memory and might be slightly
wrong):

# cryptsetup luksFormat /dev/rootvg/xfstest
# cryptsetup luksOpen /dev/rootvg/xfstest rootvg-xfstest_crypt
# mkfs.xfs /dev/mapper/rootvg-xfstest_crypt
# mount /dev/mapper/rootvg-xfstest_crypt /media/xfstest
# cd /media/backup
# tar cf - backuppc/ | (cd ../xfstest && tar xf -)

During this operation, I got the following two warning messages in
dmesg:

------------------------------------------------------------
[ 0.000000] Linux version 3.2.2 (sliedes@lh) (gcc version 4.6.2 (Debian 4.6.2-12) ) #1 SMP Thu Jan 26 03:51:41 EET 2012
[...]
[19419.407855] XFS (dm-7): Mounting Filesystem
[19419.726935] XFS (dm-7): Ending clean mount
[...]
[35380.253189] INFO: task tar:3312 blocked for more than 120 seconds.
[35380.253192] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[35380.253194] tar D ffff880220adc678 0 3312 3311 0x00000000
[35380.253198] ffff880107a1d778 0000000000000082 0000000000000000 ffff8800c552be30
[35380.253202] ffff880220adc2f0 ffff880107a1dfd8 ffff880107a1dfd8 ffff880107a1dfd8
[35380.253206] ffff880223d01650 ffff880220adc2f0 0000000000000000 ffffffff00000000
[35380.253210] Call Trace:
[35380.253217] [<ffffffff813ed17a>] schedule+0x3a/0x50
[35380.253220] [<ffffffff813ed6a5>] schedule_timeout+0x1c5/0x300
[35380.253237] [<ffffffffa0a85ea5>] ? _xfs_buf_find+0xb5/0x240 [xfs]
[35380.253240] [<ffffffff813ee257>] __down_common+0x95/0xe5
[35380.253249] [<ffffffffa0a85ebe>] ? _xfs_buf_find+0xce/0x240 [xfs]
[35380.253252] [<ffffffff813ee306>] __down+0x18/0x1a
[35380.253255] [<ffffffff8107214c>] down+0x3c/0x50
[35380.253263] [<ffffffffa0a85d24>] xfs_buf_lock+0x44/0x110 [xfs]
[35380.253272] [<ffffffffa0a85ebe>] _xfs_buf_find+0xce/0x240 [xfs]
[35380.253280] [<ffffffffa0a8629f>] xfs_buf_get+0x2f/0x1d0 [xfs]
[35380.253289] [<ffffffffa0a86b38>] xfs_buf_read+0x28/0x120 [xfs]
[35380.253303] [<ffffffffa0ae0f87>] xfs_trans_read_buf+0x187/0x470 [xfs]
[35380.253316] [<ffffffffa0ae1345>] ? xfs_trans_brelse+0xd5/0x160 [xfs]
[35380.253329] [<ffffffffa0ac9732>] xfs_imap_to_bp.isra.9+0x42/0x120 [xfs]
[35380.253341] [<ffffffffa0acd441>] xfs_iread+0x81/0x1c0 [xfs]
[35380.253352] [<ffffffffa0a9bfc7>] ? kmem_zone_alloc+0x67/0xe0 [xfs]
[35380.253362] [<ffffffffa0a8d043>] xfs_iget+0x2a3/0x820 [xfs]
[35380.253371] [<ffffffffa0a8cd1c>] ? xfs_iunlock+0xbc/0x130 [xfs]
[35380.253382] [<ffffffffa0a99f96>] xfs_lookup+0xb6/0x130 [xfs]
[35380.253392] [<ffffffffa0a90c89>] xfs_vn_lookup+0x49/0x90 [xfs]
[35380.253395] [<ffffffff811362b4>] ? d_alloc+0x24/0x70
[35380.253399] [<ffffffff81129d90>] d_alloc_and_lookup+0x40/0x80
[35380.253401] [<ffffffff81136670>] ? d_lookup+0x30/0x50
[35380.253403] [<ffffffff8112c0ad>] do_lookup+0x2bd/0x3c0
[35380.253406] [<ffffffff8112d1d4>] path_lookupat+0x114/0x740
[35380.253408] [<ffffffff8112d82c>] do_path_lookup+0x2c/0xc0
[35380.253410] [<ffffffff8112ebc4>] user_path_at_empty+0x54/0xa0
[35380.253414] [<ffffffff8113c63f>] ? mntput_no_expire+0x1f/0x100
[35380.253416] [<ffffffff8112ec1c>] user_path_at+0xc/0x10
[35380.253418] [<ffffffff8112f249>] sys_linkat+0x59/0x150
[35380.253421] [<ffffffff8111fc35>] ? sys_read+0x45/0x90
[35380.253425] [<ffffffff813f6812>] system_call_fastpath+0x16/0x1b
[36339.636777] INFO: task tar:3312 blocked for more than 120 seconds.
[36339.636779] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[36339.636782] tar D ffff880220adc678 0 3312 3311 0x00000000
[36339.636786] ffff880107a1d6f8 0000000000000082 ffff880107a1d6d8 ffffffff8100177a
[36339.636790] ffff880220adc2f0 ffff880107a1dfd8 ffff880107a1dfd8 ffff880107a1dfd8
[36339.636793] ffff88021e222ca0 ffff880220adc2f0 ffff88021d8a7380 ffff88022040fa80
[36339.636797] Call Trace:
[36339.636803] [<ffffffff8100177a>] ? __switch_to+0x1ea/0x310
[36339.636808] [<ffffffff813ed17a>] schedule+0x3a/0x50
[36339.636811] [<ffffffff813ed6a5>] schedule_timeout+0x1c5/0x300
[36339.636813] [<ffffffff813ed17a>] ? schedule+0x3a/0x50
[36339.636816] [<ffffffff813ee257>] __down_common+0x95/0xe5
[36339.636832] [<ffffffffa0a85ebe>] ? _xfs_buf_find+0xce/0x240 [xfs]
[36339.636835] [<ffffffff813ee306>] __down+0x18/0x1a
[36339.636838] [<ffffffff8107214c>] down+0x3c/0x50
[36339.636847] [<ffffffffa0a85d24>] xfs_buf_lock+0x44/0x110 [xfs]
[36339.636856] [<ffffffffa0a85ebe>] _xfs_buf_find+0xce/0x240 [xfs]
[36339.636865] [<ffffffffa0a8629f>] xfs_buf_get+0x2f/0x1d0 [xfs]
[36339.636874] [<ffffffffa0a86b38>] xfs_buf_read+0x28/0x120 [xfs]
[36339.636889] [<ffffffffa0ae0f87>] xfs_trans_read_buf+0x187/0x470 [xfs]
[36339.636901] [<ffffffffa0abaf9e>] xfs_da_do_buf+0x24e/0x620 [xfs]
[36339.636904] [<ffffffff8107218d>] ? up+0x2d/0x50
[36339.636916] [<ffffffffa0abb3cc>] xfs_da_read_buf+0x1c/0x20 [xfs]
[36339.636918] [<ffffffff8106ccd9>] ? wake_up_bit+0x29/0x40
[36339.636931] [<ffffffffa0ac158b>] xfs_dir2_leaf_lookup_int+0x5b/0x2d0 [xfs]
[36339.636942] [<ffffffffa0aa8d5e>] ? xfs_bmap_last_extent.constprop.23+0x6e/0xb0 [xfs]
[36339.636953] [<ffffffffa0ac1cc4>] xfs_dir2_leaf_lookup+0x34/0x110 [xfs]
[36339.636965] [<ffffffffa0abd7c1>] ? xfs_dir2_isleaf+0x21/0x60 [xfs]
[36339.636976] [<ffffffffa0abdd3a>] xfs_dir_lookup+0x14a/0x160 [xfs]
[36339.636987] [<ffffffffa0a99f5f>] xfs_lookup+0x7f/0x130 [xfs]
[36339.636997] [<ffffffffa0a90c89>] xfs_vn_lookup+0x49/0x90 [xfs]
[36339.637000] [<ffffffff811362b4>] ? d_alloc+0x24/0x70
[36339.637003] [<ffffffff81129d90>] d_alloc_and_lookup+0x40/0x80
[36339.637006] [<ffffffff81136670>] ? d_lookup+0x30/0x50
[36339.637008] [<ffffffff8112a7cf>] __lookup_hash.part.28+0xbf/0xe0
[36339.637012] [<ffffffff811a7847>] ? security_inode_permission+0x17/0x20
[36339.637014] [<ffffffff8112ab88>] lookup_hash+0x48/0x60
[36339.637016] [<ffffffff8112da03>] kern_path_create+0x83/0x120
[36339.637019] [<ffffffff811deabc>] ? strncpy_from_user+0x2c/0x40
[36339.637022] [<ffffffff8112a310>] ? getname_flags+0x140/0x260
[36339.637024] [<ffffffff8112dae5>] user_path_create+0x45/0x70
[36339.637027] [<ffffffff8112f279>] sys_linkat+0x89/0x150
[36339.637029] [<ffffffff8111fc35>] ? sys_read+0x45/0x90
[36339.637033] [<ffffffff813f6812>] system_call_fastpath+0x16/0x1b
------------------------------------------------------------

Afterwards when BackupPC was doing a backup, I got these additional
warnings:

------------------------------------------------------------
[91863.941820] INFO: task kworker/0:5:19584 blocked for more than 120 seconds.
[91863.941823] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[91863.941825] kworker/0:5 D ffff8802205699d8 0 19584 2 0x00000000
[91863.941829] ffff88005fe9bb70 0000000000000046 ffff88005fe9bb00 0000000000000086
[91863.941833] ffff880220569650 ffff88005fe9bfd8 ffff88005fe9bfd8 ffff88005fe9bfd8
[91863.941837] ffff88021e4c8000 ffff880220569650 ffff88005fe9bb80 ffffffff81044ecd
[91863.941840] Call Trace:
[91863.941847] [<ffffffff81044ecd>] ? try_to_wake_up+0x22d/0x290
[91863.941852] [<ffffffff813ed17a>] schedule+0x3a/0x50
[91863.941855] [<ffffffff813ed6a5>] schedule_timeout+0x1c5/0x300
[91863.941858] [<ffffffff81115124>] ? kmem_cache_free+0x104/0x110
[91863.941863] [<ffffffff810d7172>] ? mempool_free_slab+0x12/0x20
[91863.941866] [<ffffffff813ee257>] __down_common+0x95/0xe5
[91863.941886] [<ffffffffa0ad4e07>] ? xfs_getsb+0x37/0x60 [xfs]
[91863.941889] [<ffffffff813ee306>] __down+0x18/0x1a
[91863.941892] [<ffffffff8107214c>] down+0x3c/0x50
[91863.941902] [<ffffffffa0a85d24>] xfs_buf_lock+0x44/0x110 [xfs]
[91863.941915] [<ffffffffa0ad4e07>] xfs_getsb+0x37/0x60 [xfs]
[91863.941929] [<ffffffffa0ae0d03>] xfs_trans_getsb+0x43/0x140 [xfs]
[91863.941942] [<ffffffffa0ad4b36>] xfs_mod_sb+0x46/0xc0 [xfs]
[91863.941952] [<ffffffffa0a96320>] ? xfs_sync_inode_attr+0xf0/0xf0 [xfs]
[91863.941962] [<ffffffffa0a8c29f>] xfs_fs_log_dummy+0x4f/0x90 [xfs]
[91863.941975] [<ffffffffa0adad03>] ? xfs_log_need_covered+0x83/0xb0 [xfs]
[91863.941985] [<ffffffffa0a963a4>] xfs_sync_worker+0x84/0x90 [xfs]
[91863.941988] [<ffffffff81066ec8>] process_one_work+0x118/0x470
[91863.941991] [<ffffffff81067dee>] worker_thread+0x15e/0x350
[91863.941994] [<ffffffff81067c90>] ? manage_workers.isra.29+0x220/0x220
[91863.941996] [<ffffffff8106c7a7>] kthread+0x87/0x90
[91863.941999] [<ffffffff813f8974>] kernel_thread_helper+0x4/0x10
[91863.942002] [<ffffffff8106c720>] ? kthread_worker_fn+0x190/0x190
[91863.942004] [<ffffffff813f8970>] ? gs_change+0x13/0x13
[92103.787573] INFO: task cp:18226 blocked for more than 120 seconds.
[92103.787576] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[92103.787578] cp D ffff8802078e19d8 0 18226 28931 0x00000000
[92103.787582] ffff880100f116f8 0000000000000082 ffff880100f116d8 ffffffff8100177a
[92103.787586] ffff8802078e1650 ffff880100f11fd8 ffff880100f11fd8 ffff880100f11fd8
[92103.787590] ffff880103439650 ffff8802078e1650 ffff880220c06c80 ffff88021f968000
[92103.787593] Call Trace:
[92103.787599] [<ffffffff8100177a>] ? __switch_to+0x1ea/0x310
[92103.787604] [<ffffffff813ed17a>] schedule+0x3a/0x50
[92103.787607] [<ffffffff813ed6a5>] schedule_timeout+0x1c5/0x300
[92103.787623] [<ffffffffa0a85c38>] ? xfs_buf_trylock+0x28/0xd0 [xfs]
[92103.787626] [<ffffffff813ed17a>] ? schedule+0x3a/0x50
[92103.787629] [<ffffffff813ee257>] __down_common+0x95/0xe5
[92103.787637] [<ffffffffa0a85ebe>] ? _xfs_buf_find+0xce/0x240 [xfs]
[92103.787640] [<ffffffff813ee306>] __down+0x18/0x1a
[92103.787643] [<ffffffff8107214c>] down+0x3c/0x50
[92103.787652] [<ffffffffa0a85d24>] xfs_buf_lock+0x44/0x110 [xfs]
[92103.787661] [<ffffffffa0a85ebe>] _xfs_buf_find+0xce/0x240 [xfs]
[92103.787670] [<ffffffffa0a8629f>] xfs_buf_get+0x2f/0x1d0 [xfs]
[92103.787678] [<ffffffffa0a86b38>] xfs_buf_read+0x28/0x120 [xfs]
[92103.787693] [<ffffffffa0ae0f87>] xfs_trans_read_buf+0x187/0x470 [xfs]
[92103.787706] [<ffffffffa0abaf9e>] xfs_da_do_buf+0x24e/0x620 [xfs]
[92103.787709] [<ffffffff8107218d>] ? up+0x2d/0x50
[92103.787720] [<ffffffffa0abb3cc>] xfs_da_read_buf+0x1c/0x20 [xfs]
[92103.787723] [<ffffffff8106ccd9>] ? wake_up_bit+0x29/0x40
[92103.787735] [<ffffffffa0ac158b>] xfs_dir2_leaf_lookup_int+0x5b/0x2d0 [xfs]
[92103.787746] [<ffffffffa0aa8d5e>] ? xfs_bmap_last_extent.constprop.23+0x6e/0xb0 [xfs]
[92103.787758] [<ffffffffa0ac1cc4>] xfs_dir2_leaf_lookup+0x34/0x110 [xfs]
[92103.787770] [<ffffffffa0abd7c1>] ? xfs_dir2_isleaf+0x21/0x60 [xfs]
[92103.787781] [<ffffffffa0abdd3a>] xfs_dir_lookup+0x14a/0x160 [xfs]
[92103.787791] [<ffffffffa0a99f5f>] xfs_lookup+0x7f/0x130 [xfs]
[92103.787801] [<ffffffffa0a90c89>] xfs_vn_lookup+0x49/0x90 [xfs]
[92103.787804] [<ffffffff811362b4>] ? d_alloc+0x24/0x70
[92103.787808] [<ffffffff81129d90>] d_alloc_and_lookup+0x40/0x80
[92103.787810] [<ffffffff81136670>] ? d_lookup+0x30/0x50
[92103.787813] [<ffffffff8112a7cf>] __lookup_hash.part.28+0xbf/0xe0
[92103.787817] [<ffffffff811a7847>] ? security_inode_permission+0x17/0x20
[92103.787819] [<ffffffff8112ab88>] lookup_hash+0x48/0x60
[92103.787822] [<ffffffff8112da03>] kern_path_create+0x83/0x120
[92103.787825] [<ffffffff811deabc>] ? strncpy_from_user+0x2c/0x40
[92103.787828] [<ffffffff8112a310>] ? getname_flags+0x140/0x260
[92103.787830] [<ffffffff8112dae5>] user_path_create+0x45/0x70
[92103.787832] [<ffffffff8112f279>] sys_linkat+0x89/0x150
[92103.787836] [<ffffffff813f6812>] system_call_fastpath+0x16/0x1b
[92103.787842] INFO: task kworker/0:1:19995 blocked for more than 120 seconds.
[92103.787844] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[92103.787845] kworker/0:1 D ffff88021a6719d8 0 19995 2 0x00000000
[92103.787848] ffff8800bfbd1b70 0000000000000046 ffff8800bfbd1b10 ffffffff811d2106
[92103.787852] ffff88021a671650 ffff8800bfbd1fd8 ffff8800bfbd1fd8 ffff8800bfbd1fd8
[92103.787855] ffff880226185940 ffff88021a671650 ffff8800bfbd1d90 ffff8800bfbd1e2c
[92103.787858] Call Trace:
[92103.787863] [<ffffffff811d2106>] ? cpumask_next_and+0x36/0x50
[92103.787866] [<ffffffff813ed17a>] schedule+0x3a/0x50
[92103.787868] [<ffffffff813ed6a5>] schedule_timeout+0x1c5/0x300
[92103.787872] [<ffffffffa09fd200>] ? cpufreq_stat_notifier_trans+0xa0/0xc0 [cpufreq_stats]
[92103.787875] [<ffffffff813f289d>] ? notifier_call_chain+0x4d/0x70
[92103.787879] [<ffffffff813ee257>] __down_common+0x95/0xe5
[92103.787892] [<ffffffffa0ad4e07>] ? xfs_getsb+0x37/0x60 [xfs]
[92103.787895] [<ffffffff813ee306>] __down+0x18/0x1a
[92103.787897] [<ffffffff8107214c>] down+0x3c/0x50
[92103.787906] [<ffffffffa0a85d24>] xfs_buf_lock+0x44/0x110 [xfs]
[92103.787918] [<ffffffffa0ad4e07>] xfs_getsb+0x37/0x60 [xfs]
[92103.787931] [<ffffffffa0ae0d03>] xfs_trans_getsb+0x43/0x140 [xfs]
[92103.787944] [<ffffffffa0ad4b36>] xfs_mod_sb+0x46/0xc0 [xfs]
[92103.787954] [<ffffffffa0a96320>] ? xfs_sync_inode_attr+0xf0/0xf0 [xfs]
[92103.787964] [<ffffffffa0a8c29f>] xfs_fs_log_dummy+0x4f/0x90 [xfs]
[92103.787977] [<ffffffffa0adad03>] ? xfs_log_need_covered+0x83/0xb0 [xfs]
[92103.787987] [<ffffffffa0a963a4>] xfs_sync_worker+0x84/0x90 [xfs]
[92103.787991] [<ffffffff81066ec8>] process_one_work+0x118/0x470
[92103.787994] [<ffffffff81067dee>] worker_thread+0x15e/0x350
[92103.787996] [<ffffffff81067c90>] ? manage_workers.isra.29+0x220/0x220
[92103.787999] [<ffffffff8106c7a7>] kthread+0x87/0x90
[92103.788002] [<ffffffff813f8974>] kernel_thread_helper+0x4/0x10
[92103.788004] [<ffffffff8106c720>] ? kthread_worker_fn+0x190/0x190
[92103.788007] [<ffffffff813f8970>] ? gs_change+0x13/0x13
------------------------------------------------------------