From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752041Ab1CZN3l (ORCPT ); Sat, 26 Mar 2011 09:29:41 -0400 Received: from lucidpixels.com ([75.144.35.66]:48226 "EHLO lucidpixels.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751660Ab1CZN3k (ORCPT ); Sat, 26 Mar 2011 09:29:40 -0400 Date: Sat, 26 Mar 2011 09:29:36 -0400 (EDT) From: Justin Piszcz To: linux-kernel@vger.kernel.org, xfs@oss.sgi.com Subject: 2.6.38.1: CPU#0 stuck for 67s! / xfs_ail_splice Message-ID: User-Agent: Alpine 2.02 (DEB 1266 2009-07-14) MIME-Version: 1.0 Content-Type: TEXT/PLAIN; format=flowed; charset=US-ASCII Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Hi, When I rm -rf a directory of a few hundred thousand files/directories on XFS under 2.6.38.1, I see the following, is this normal? [69501.486071] BUG: soft lockup - CPU#0 stuck for 67s! [kworker/0:2:19517] [69501.486074] Modules linked in: tcp_diag inet_diag sata_mv [69501.486077] CPU 0 [69501.486078] Modules linked in: tcp_diag inet_diag sata_mv [69501.486080] [69501.486081] Pid: 19517, comm: kworker/0:2 Not tainted 2.6.38.1 #2 /DP55KG [69501.486085] RIP: 0010:[] [] xfs_ail_splice+0x19/0x90 [69501.486091] RSP: 0018:ffff88011270fb78 EFLAGS: 00000202 [69501.486092] RAX: ffff88023705ced0 RBX: ffff88023715b000 RCX: ffff88017c841588 [69501.486093] RDX: 0000007d0039770e RSI: ffff88011270fbb0 RDI: 0000007d0039770f [69501.486095] RBP: 0000000000000001 R08: 000000000000007d R09: ffff880418e1ab48 [69501.486096] R10: 000000000000007d R11: ffff88029da55058 R12: ffffffff814b578e [69501.486097] R13: ffffffff810a123c R14: ffff88023715b000 R15: 0000000000000097 [69501.486099] FS: 0000000000000000(0000) GS:ffff8800df200000(0000) knlGS:0000000000000000 [69501.486101] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b [69501.486102] CR2: 00007f0da6832010 CR3: 00000003daac1000 CR4: 00000000000006f0 [69501.486103] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [69501.486104] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [69501.486106] Process kworker/0:2 (pid: 19517, threadinfo ffff88011270e000, task ffff880414fa0e50) [69501.486107] Stack: [69501.486108] ffffffff81228dbb 000000000000001b 00000001810a14b8 ffff880300000000 [69501.486111] ffff88029157b1b0 ffff8803c6b9c150 0039770e00000003 ffff880101dcb228 [69501.486113] ffff880101dcb228 0000000000000000 ffff880101dcb228 ffff88029dbf1cc0 [69501.486116] Call Trace: [69501.486119] [] ? xfs_trans_ail_update_bulk+0xdb/0x150 [69501.486122] [] ? xfs_trans_committed_bulk+0xd6/0x200 [69501.486125] [] ? xlog_cil_committed+0x24/0xe0 [69501.486127] [] ? xlog_state_do_callback+0x15f/0x2d0 [69501.486129] [] ? xfs_buf_iodone_work+0x0/0x50 [69501.486133] [] ? process_one_work+0xfb/0x370 [69501.486135] [] ? worker_thread+0x15e/0x320 [69501.486138] [] ? __wake_up_common+0x50/0x80 [69501.486140] [] ? worker_thread+0x0/0x320 [69501.486142] [] ? worker_thread+0x0/0x320 [69501.486144] [] ? kthread+0x96/0xa0 [69501.486146] [] ? kernel_thread_helper+0x4/0x10 [69501.486148] [] ? kthread+0x0/0xa0 [69501.486150] [] ? kernel_thread_helper+0x0/0x10 [69501.486151] Code: 0f 45 c2 c3 66 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 4c 8d 4f 08 4c 3b 4f 08 74 66 49 89 d2 48 8b 47 10 49 c1 ea 20 48 8b 48 08 <49> 39 c1 0f 18 09 74 12 48 8b 78 10 49 89 f8 49 c1 e8 20 45 39 [69501.486167] Call Trace: [69501.486169] [] ? xfs_trans_ail_update_bulk+0xdb/0x150 [69501.486171] [] ? xfs_trans_committed_bulk+0xd6/0x200 [69501.486174] [] ? xlog_cil_committed+0x24/0xe0 [69501.486175] [] ? xlog_state_do_callback+0x15f/0x2d0 [69501.486177] [] ? xfs_buf_iodone_work+0x0/0x50 [69501.486179] [] ? process_one_work+0xfb/0x370 [69501.486181] [] ? worker_thread+0x15e/0x320 [69501.486183] [] ? __wake_up_common+0x50/0x80 [69501.486185] [] ? worker_thread+0x0/0x320 [69501.486187] [] ? worker_thread+0x0/0x320 [69501.486189] [] ? kthread+0x96/0xa0 [69501.486191] [] ? kernel_thread_helper+0x4/0x10 [69501.486192] [] ? kthread+0x0/0xa0 [69501.486194] [] ? kernel_thread_helper+0x0/0x10 [69585.468274] BUG: soft lockup - CPU#0 stuck for 67s! [kworker/0:2:19517] [69585.468277] Modules linked in: tcp_diag inet_diag sata_mv [69585.468280] CPU 0 [69585.468281] Modules linked in: tcp_diag inet_diag sata_mv [69585.468283] [69585.468285] Pid: 19517, comm: kworker/0:2 Not tainted 2.6.38.1 #2 /DP55KG [69585.468288] RIP: 0010:[] [] xfs_ail_splice+0x19/0x90 [69585.468294] RSP: 0018:ffff88011270fb78 EFLAGS: 00000202 [69585.468295] RAX: ffff8800899559c0 RBX: ffff880279648000 RCX: ffff8800899558e8 [69585.468297] RDX: 0000007d0039770e RSI: ffff88011270fbb0 RDI: 0000007d0039770f [69585.468298] RBP: 0000000000000001 R08: 000000000000007d R09: ffff880418e1ab48 [69585.468299] R10: 000000000000007d R11: ffff8802acabb9b8 R12: ffffffff814b578e [69585.468301] R13: ffffffff810a123c R14: ffff880279648000 R15: 0000000000000097 [69585.468302] FS: 0000000000000000(0000) GS:ffff8800df200000(0000) knlGS:0000000000000000 [69585.468304] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b [69585.468305] CR2: 00007f0da6832010 CR3: 00000003daac1000 CR4: 00000000000006f0 [69585.468306] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [69585.468308] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [69585.468309] Process kworker/0:2 (pid: 19517, threadinfo ffff88011270e000, task ffff880414fa0e50) [69585.468311] Stack: [69585.468311] ffffffff81228dbb 000000000000001b 00000001810a14b8 ffff880418e1ab40 [69585.468314] ffff8800d7020170 ffff8803c6b9c150 0039770e00000003 ffff880032b59078 [69585.468317] ffff880032b59078 0000000000000000 ffff880032b59078 ffff88016581bf40 [69585.468319] Call Trace: [69585.468322] [] ? xfs_trans_ail_update_bulk+0xdb/0x150 [69585.468325] [] ? xfs_trans_committed_bulk+0xd6/0x200 [69585.468328] [] ? xlog_cil_committed+0x24/0xe0 [69585.468330] [] ? xlog_state_do_callback+0x15f/0x2d0 [69585.468333] [] ? xfs_buf_iodone_work+0x0/0x50 [69585.468336] [] ? process_one_work+0xfb/0x370 [69585.468338] [] ? worker_thread+0x15e/0x320 [69585.468341] [] ? __wake_up_common+0x50/0x80 [69585.468343] [] ? worker_thread+0x0/0x320 [69585.468345] [] ? worker_thread+0x0/0x320 [69585.468347] [] ? kthread+0x96/0xa0 [69585.468349] [] ? kernel_thread_helper+0x4/0x10 [69585.468351] [] ? kthread+0x0/0xa0 [69585.468353] [] ? kernel_thread_helper+0x0/0x10 [69585.468354] Code: 0f 45 c2 c3 66 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 4c 8d 4f 08 4c 3b 4f 08 74 66 49 89 d2 48 8b 47 10 49 c1 ea 20 48 8b 48 08 <49> 39 c1 0f 18 09 74 12 48 8b 78 10 49 89 f8 49 c1 e8 20 45 39 [69585.468370] Call Trace: [69585.468372] [] ? xfs_trans_ail_update_bulk+0xdb/0x150 [69585.468374] [] ? xfs_trans_committed_bulk+0xd6/0x200 [69585.468376] [] ? xlog_cil_committed+0x24/0xe0 [69585.468378] [] ? xlog_state_do_callback+0x15f/0x2d0 [69585.468380] [] ? xfs_buf_iodone_work+0x0/0x50 [69585.468382] [] ? process_one_work+0xfb/0x370 [69585.468384] [] ? worker_thread+0x15e/0x320 [69585.468386] [] ? __wake_up_common+0x50/0x80 [69585.468388] [] ? worker_thread+0x0/0x320 [69585.468390] [] ? worker_thread+0x0/0x320 [69585.468392] [] ? kthread+0x96/0xa0 [69585.468394] [] ? kernel_thread_helper+0x4/0x10 [69585.468395] [] ? kthread+0x0/0xa0 [69585.468397] [] ? kernel_thread_helper+0x0/0x10 [69586.159176] INFO: task rm:21483 blocked for more than 120 seconds. [69586.159179] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [69586.159180] rm D ffff8803f4bce650 0 21483 21466 0x00000004 [69586.159183] ffff8803f4bce650 0000000000000086 0000000000000000 0000000000000000 [69586.159186] ffff88041fd71190 0000000000011280 ffff88033d69bfd8 0000000000011280 [69586.159189] 0000000000004000 0000000000004000 ffff8803f4bce8a8 ffff88033d69a000 [69586.159192] Call Trace: [69586.159197] [] ? _xfs_buf_ioapply+0x16c/0x2d0 [69586.159200] [] ? xfs_buf_iorequest+0x3b/0x60 [69586.159202] [] ? xlog_bdstrat+0x1d/0x50 [69586.159204] [] ? xlog_sync+0x1fe/0x390 [69586.159206] [] ? _xfs_log_force_lsn+0x296/0x2d0 [69586.159210] [] ? default_wake_function+0x0/0x20 [69586.159212] [] ? _xfs_trans_commit+0x29d/0x2b0 [69586.159215] [] ? xfs_itruncate_finish+0x18d/0x310 [69586.159217] [] ? xfs_inactive+0x2e5/0x450 [69586.159220] [] ? xfs_fs_evict_inode+0x82/0x90 [69586.159223] [] ? evict+0x17/0xa0 [69586.159224] [] ? iput+0x1a3/0x270 [69586.159227] [] ? do_unlinkat+0x125/0x1c0 [69586.159230] [] ? system_call_fastpath+0x16/0x1b