From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from cuda.sgi.com (cuda2.sgi.com [192.48.176.25]) by oss.sgi.com (8.14.3/8.14.3/SuSE Linux 0.8) with ESMTP id q0U0KYSW177143 for ; Sun, 29 Jan 2012 18:20:35 -0600 Received: from smtp-3.hut.fi (smtp-3.hut.fi [130.233.228.93]) by cuda.sgi.com with ESMTP id W3HHnf2cAF4oryWO (version=TLSv1 cipher=AES256-SHA bits=256 verify=NO) for ; Sun, 29 Jan 2012 16:20:31 -0800 (PST) Received: from localhost (katosiko.hut.fi [130.233.228.115]) by smtp-3.hut.fi (8.13.6/8.12.10) with ESMTP id q0U0KTum022995 for ; Mon, 30 Jan 2012 02:20:29 +0200 Received: from smtp-3.hut.fi ([130.233.228.93]) by localhost (katosiko.hut.fi [130.233.228.115]) (amavisd-new, port 10024) with LMTP id 06953-386 for ; Mon, 30 Jan 2012 02:20:29 +0200 (EET) Received: from kosh.localdomain (kosh.hut.fi [130.233.228.12]) by smtp-3.hut.fi (8.13.6/8.12.10) with ESMTP id q0U0KQVA022979 for ; Mon, 30 Jan 2012 02:20:26 +0200 Date: Mon, 30 Jan 2012 02:20:26 +0200 From: Sami Liedes Subject: xfs task blocked for more than 120 seconds Message-ID: <20120130002026.GG10174@sli.dy.fi> MIME-Version: 1.0 Content-Disposition: inline List-Id: XFS Filesystem from SGI List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Sender: xfs-bounces@oss.sgi.com Errors-To: xfs-bounces@oss.sgi.com To: xfs@oss.sgi.com 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] [] schedule+0x3a/0x50 [35380.253220] [] schedule_timeout+0x1c5/0x300 [35380.253237] [] ? _xfs_buf_find+0xb5/0x240 [xfs] [35380.253240] [] __down_common+0x95/0xe5 [35380.253249] [] ? _xfs_buf_find+0xce/0x240 [xfs] [35380.253252] [] __down+0x18/0x1a [35380.253255] [] down+0x3c/0x50 [35380.253263] [] xfs_buf_lock+0x44/0x110 [xfs] [35380.253272] [] _xfs_buf_find+0xce/0x240 [xfs] [35380.253280] [] xfs_buf_get+0x2f/0x1d0 [xfs] [35380.253289] [] xfs_buf_read+0x28/0x120 [xfs] [35380.253303] [] xfs_trans_read_buf+0x187/0x470 [xfs] [35380.253316] [] ? xfs_trans_brelse+0xd5/0x160 [xfs] [35380.253329] [] xfs_imap_to_bp.isra.9+0x42/0x120 [xfs] [35380.253341] [] xfs_iread+0x81/0x1c0 [xfs] [35380.253352] [] ? kmem_zone_alloc+0x67/0xe0 [xfs] [35380.253362] [] xfs_iget+0x2a3/0x820 [xfs] [35380.253371] [] ? xfs_iunlock+0xbc/0x130 [xfs] [35380.253382] [] xfs_lookup+0xb6/0x130 [xfs] [35380.253392] [] xfs_vn_lookup+0x49/0x90 [xfs] [35380.253395] [] ? d_alloc+0x24/0x70 [35380.253399] [] d_alloc_and_lookup+0x40/0x80 [35380.253401] [] ? d_lookup+0x30/0x50 [35380.253403] [] do_lookup+0x2bd/0x3c0 [35380.253406] [] path_lookupat+0x114/0x740 [35380.253408] [] do_path_lookup+0x2c/0xc0 [35380.253410] [] user_path_at_empty+0x54/0xa0 [35380.253414] [] ? mntput_no_expire+0x1f/0x100 [35380.253416] [] user_path_at+0xc/0x10 [35380.253418] [] sys_linkat+0x59/0x150 [35380.253421] [] ? sys_read+0x45/0x90 [35380.253425] [] 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] [] ? __switch_to+0x1ea/0x310 [36339.636808] [] schedule+0x3a/0x50 [36339.636811] [] schedule_timeout+0x1c5/0x300 [36339.636813] [] ? schedule+0x3a/0x50 [36339.636816] [] __down_common+0x95/0xe5 [36339.636832] [] ? _xfs_buf_find+0xce/0x240 [xfs] [36339.636835] [] __down+0x18/0x1a [36339.636838] [] down+0x3c/0x50 [36339.636847] [] xfs_buf_lock+0x44/0x110 [xfs] [36339.636856] [] _xfs_buf_find+0xce/0x240 [xfs] [36339.636865] [] xfs_buf_get+0x2f/0x1d0 [xfs] [36339.636874] [] xfs_buf_read+0x28/0x120 [xfs] [36339.636889] [] xfs_trans_read_buf+0x187/0x470 [xfs] [36339.636901] [] xfs_da_do_buf+0x24e/0x620 [xfs] [36339.636904] [] ? up+0x2d/0x50 [36339.636916] [] xfs_da_read_buf+0x1c/0x20 [xfs] [36339.636918] [] ? wake_up_bit+0x29/0x40 [36339.636931] [] xfs_dir2_leaf_lookup_int+0x5b/0x2d0 [xfs] [36339.636942] [] ? xfs_bmap_last_extent.constprop.23+0x6e/0xb0 [xfs] [36339.636953] [] xfs_dir2_leaf_lookup+0x34/0x110 [xfs] [36339.636965] [] ? xfs_dir2_isleaf+0x21/0x60 [xfs] [36339.636976] [] xfs_dir_lookup+0x14a/0x160 [xfs] [36339.636987] [] xfs_lookup+0x7f/0x130 [xfs] [36339.636997] [] xfs_vn_lookup+0x49/0x90 [xfs] [36339.637000] [] ? d_alloc+0x24/0x70 [36339.637003] [] d_alloc_and_lookup+0x40/0x80 [36339.637006] [] ? d_lookup+0x30/0x50 [36339.637008] [] __lookup_hash.part.28+0xbf/0xe0 [36339.637012] [] ? security_inode_permission+0x17/0x20 [36339.637014] [] lookup_hash+0x48/0x60 [36339.637016] [] kern_path_create+0x83/0x120 [36339.637019] [] ? strncpy_from_user+0x2c/0x40 [36339.637022] [] ? getname_flags+0x140/0x260 [36339.637024] [] user_path_create+0x45/0x70 [36339.637027] [] sys_linkat+0x89/0x150 [36339.637029] [] ? sys_read+0x45/0x90 [36339.637033] [] 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] [] ? try_to_wake_up+0x22d/0x290 [91863.941852] [] schedule+0x3a/0x50 [91863.941855] [] schedule_timeout+0x1c5/0x300 [91863.941858] [] ? kmem_cache_free+0x104/0x110 [91863.941863] [] ? mempool_free_slab+0x12/0x20 [91863.941866] [] __down_common+0x95/0xe5 [91863.941886] [] ? xfs_getsb+0x37/0x60 [xfs] [91863.941889] [] __down+0x18/0x1a [91863.941892] [] down+0x3c/0x50 [91863.941902] [] xfs_buf_lock+0x44/0x110 [xfs] [91863.941915] [] xfs_getsb+0x37/0x60 [xfs] [91863.941929] [] xfs_trans_getsb+0x43/0x140 [xfs] [91863.941942] [] xfs_mod_sb+0x46/0xc0 [xfs] [91863.941952] [] ? xfs_sync_inode_attr+0xf0/0xf0 [xfs] [91863.941962] [] xfs_fs_log_dummy+0x4f/0x90 [xfs] [91863.941975] [] ? xfs_log_need_covered+0x83/0xb0 [xfs] [91863.941985] [] xfs_sync_worker+0x84/0x90 [xfs] [91863.941988] [] process_one_work+0x118/0x470 [91863.941991] [] worker_thread+0x15e/0x350 [91863.941994] [] ? manage_workers.isra.29+0x220/0x220 [91863.941996] [] kthread+0x87/0x90 [91863.941999] [] kernel_thread_helper+0x4/0x10 [91863.942002] [] ? kthread_worker_fn+0x190/0x190 [91863.942004] [] ? 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] [] ? __switch_to+0x1ea/0x310 [92103.787604] [] schedule+0x3a/0x50 [92103.787607] [] schedule_timeout+0x1c5/0x300 [92103.787623] [] ? xfs_buf_trylock+0x28/0xd0 [xfs] [92103.787626] [] ? schedule+0x3a/0x50 [92103.787629] [] __down_common+0x95/0xe5 [92103.787637] [] ? _xfs_buf_find+0xce/0x240 [xfs] [92103.787640] [] __down+0x18/0x1a [92103.787643] [] down+0x3c/0x50 [92103.787652] [] xfs_buf_lock+0x44/0x110 [xfs] [92103.787661] [] _xfs_buf_find+0xce/0x240 [xfs] [92103.787670] [] xfs_buf_get+0x2f/0x1d0 [xfs] [92103.787678] [] xfs_buf_read+0x28/0x120 [xfs] [92103.787693] [] xfs_trans_read_buf+0x187/0x470 [xfs] [92103.787706] [] xfs_da_do_buf+0x24e/0x620 [xfs] [92103.787709] [] ? up+0x2d/0x50 [92103.787720] [] xfs_da_read_buf+0x1c/0x20 [xfs] [92103.787723] [] ? wake_up_bit+0x29/0x40 [92103.787735] [] xfs_dir2_leaf_lookup_int+0x5b/0x2d0 [xfs] [92103.787746] [] ? xfs_bmap_last_extent.constprop.23+0x6e/0xb0 [xfs] [92103.787758] [] xfs_dir2_leaf_lookup+0x34/0x110 [xfs] [92103.787770] [] ? xfs_dir2_isleaf+0x21/0x60 [xfs] [92103.787781] [] xfs_dir_lookup+0x14a/0x160 [xfs] [92103.787791] [] xfs_lookup+0x7f/0x130 [xfs] [92103.787801] [] xfs_vn_lookup+0x49/0x90 [xfs] [92103.787804] [] ? d_alloc+0x24/0x70 [92103.787808] [] d_alloc_and_lookup+0x40/0x80 [92103.787810] [] ? d_lookup+0x30/0x50 [92103.787813] [] __lookup_hash.part.28+0xbf/0xe0 [92103.787817] [] ? security_inode_permission+0x17/0x20 [92103.787819] [] lookup_hash+0x48/0x60 [92103.787822] [] kern_path_create+0x83/0x120 [92103.787825] [] ? strncpy_from_user+0x2c/0x40 [92103.787828] [] ? getname_flags+0x140/0x260 [92103.787830] [] user_path_create+0x45/0x70 [92103.787832] [] sys_linkat+0x89/0x150 [92103.787836] [] 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] [] ? cpumask_next_and+0x36/0x50 [92103.787866] [] schedule+0x3a/0x50 [92103.787868] [] schedule_timeout+0x1c5/0x300 [92103.787872] [] ? cpufreq_stat_notifier_trans+0xa0/0xc0 [cpufreq_stats] [92103.787875] [] ? notifier_call_chain+0x4d/0x70 [92103.787879] [] __down_common+0x95/0xe5 [92103.787892] [] ? xfs_getsb+0x37/0x60 [xfs] [92103.787895] [] __down+0x18/0x1a [92103.787897] [] down+0x3c/0x50 [92103.787906] [] xfs_buf_lock+0x44/0x110 [xfs] [92103.787918] [] xfs_getsb+0x37/0x60 [xfs] [92103.787931] [] xfs_trans_getsb+0x43/0x140 [xfs] [92103.787944] [] xfs_mod_sb+0x46/0xc0 [xfs] [92103.787954] [] ? xfs_sync_inode_attr+0xf0/0xf0 [xfs] [92103.787964] [] xfs_fs_log_dummy+0x4f/0x90 [xfs] [92103.787977] [] ? xfs_log_need_covered+0x83/0xb0 [xfs] [92103.787987] [] xfs_sync_worker+0x84/0x90 [xfs] [92103.787991] [] process_one_work+0x118/0x470 [92103.787994] [] worker_thread+0x15e/0x350 [92103.787996] [] ? manage_workers.isra.29+0x220/0x220 [92103.787999] [] kthread+0x87/0x90 [92103.788002] [] kernel_thread_helper+0x4/0x10 [92103.788004] [] ? kthread_worker_fn+0x190/0x190 [92103.788007] [] ? gs_change+0x13/0x13 ------------------------------------------------------------ Sami _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs