Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751464Ab3III6Q (ORCPT ); Mon, 9 Sep 2013 04:58:16 -0400 Received: from mail-la0-f52.google.com ([209.85.215.52]:53402 "EHLO mail-la0-f52.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751025Ab3III6O (ORCPT ); Mon, 9 Sep 2013 04:58:14 -0400 MIME-Version: 1.0 Date: Mon, 9 Sep 2013 10:58:12 +0200 Message-ID: Subject: [3.10.7] Reproductible soft lockup, recover but freeze even the mouse From: Bastien ROUCARIES To: "linux-kernel@vger.kernel.org" Cc: Neil Brown , "Theodore Ts'o" , Andreas Dilger Content-Type: text/plain; charset=UTF-8 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 16339 Lines: 298 Hi, I experiment a soft lockup. during 20 s I have no mouse, could not switch back to console and so on. I achieve to get a backtrace by echo 15 > /proc/sys/kernel/hung_task_timeout_secs Seems file system related (hdd led is on). My filesystems are ext4 over raid0 so add some cc How can I debug ? It seems related to fsync but not sure why it should lockup my box.Look like firefox is the source of fsync. Get some bugreport about this on: - https://bugs.launchpad.net/ubuntu/+source/firefox-3.5/+bug/510656 I see a thread "Excessive stall times on ext4 in 3.9-rc2" and question about "Question about ext4 excessive stall time" that this bug was worked arround for 3.10 but it seems it is not the case if it is the same bug. Bastien [ 5313.553442] INFO: task jbd2/dm-0-8:349 blocked for more than 15 seconds. [ 5313.553445] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 5313.553447] jbd2/dm-0-8 D ffff88042dc53f40 0 349 2 0x00000000 [ 5313.553451] ffff8804191ba780 0000000000000046 ffff88041d0d8040 0000000000013f40 [ 5313.553455] ffff88041909dfd8 ffff88041909dfd8 ffff8804191ba780 ffff88042dc53f40 [ 5313.553458] ffff8804191ba780 ffff88041909dcc8 ffffffff8112c313 0000000000000002 [ 5313.553461] Call Trace: [ 5313.553467] [] ? do_thaw_one+0x6d/0x6d [ 5313.553472] [] ? io_schedule+0x54/0x69 [ 5313.553475] [] ? sleep_on_buffer+0x5/0x8 [ 5313.553477] [] ? __wait_on_bit+0x3b/0x6e [ 5313.553480] [] ? out_of_line_wait_on_bit+0x6d/0x76 [ 5313.553482] [] ? do_thaw_one+0x6d/0x6d [ 5313.553486] [] ? autoremove_wake_function+0x2a/0x2a [ 5313.553506] [] ? jbd2_journal_commit_transaction+0xdaa/0x138b [jbd2] [ 5313.553509] [] ? _raw_spin_lock_irqsave+0x14/0x35 [ 5313.553516] [] ? kjournald2+0xb7/0x239 [jbd2] [ 5313.553519] [] ? abort_exclusive_wait+0x79/0x79 [ 5313.553524] [] ? jbd2_superblock_csum+0x31/0x31 [jbd2] [ 5313.553527] [] ? kthread+0x7d/0x85 [ 5313.553529] [] ? __kthread_parkme+0x59/0x59 [ 5313.553532] [] ? ret_from_fork+0x7c/0xb0 [ 5313.553535] [] ? __kthread_parkme+0x59/0x59 [ 5313.553539] INFO: task kworker/2:2:726 blocked for more than 15 seconds. [ 5313.553540] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 5313.553541] kworker/2:2 D ffff88042dc53f40 0 726 2 0x00000000 [ 5313.553550] Workqueue: md submit_flushes [md_mod] [ 5313.553552] ffff880417ba77c0 0000000000000046 ffff88041d0d8040 0000000000013f40 [ 5313.553554] ffff88041b21bfd8 ffff88041b21bfd8 ffff880417ba77c0 ffff88042dc53f40 [ 5313.553557] ffff880417ba77c0 0000000000000000 ffff88041c68e3a0 ffff88021c8f5440 [ 5313.553560] Call Trace: [ 5313.553563] [] ? io_schedule+0x54/0x69 [ 5313.553566] [] ? get_request+0x4b1/0x55e [ 5313.553570] [] ? ____cache_alloc+0x1d3/0x290 [ 5313.553573] [] ? abort_exclusive_wait+0x79/0x79 [ 5313.553576] [] ? blk_queue_bio+0x1c0/0x2e8 [ 5313.553578] [] ? generic_make_request+0x96/0xd5 [ 5313.553581] [] ? submit_bio+0x10a/0x13b [ 5313.553584] [] ? bio_alloc_bioset+0xd0/0x172 [ 5313.553590] [] ? submit_flushes+0xbe/0x116 [md_mod] [ 5313.553594] [] ? process_one_work+0x18b/0x287 [ 5313.553597] [] ? worker_thread+0x121/0x1e7 [ 5313.553599] [] ? rescuer_thread+0x265/0x265 [ 5313.553602] [] ? kthread+0x7d/0x85 [ 5313.553604] [] ? __kthread_parkme+0x59/0x59 [ 5313.553607] [] ? ret_from_fork+0x7c/0xb0 [ 5313.553609] [] ? __kthread_parkme+0x59/0x59 [ 5313.553614] INFO: task jbd2/dm-1-8:1601 blocked for more than 15 seconds. [ 5313.553615] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 5313.553617] jbd2/dm-1-8 D ffff88042dc13f40 0 1601 2 0x00000000 [ 5313.553619] ffff880419bfc800 0000000000000046 ffffffff81613400 0000000000013f40 [ 5313.553622] ffff88041b365fd8 ffff88041b365fd8 ffff880419bfc800 ffff88042dc13f40 [ 5313.553625] ffff880419bfc800 ffff88041b365cc8 ffffffff8112c313 0000000000000002 [ 5313.553627] Call Trace: [ 5313.553630] [] ? do_thaw_one+0x6d/0x6d [ 5313.553633] [] ? io_schedule+0x54/0x69 [ 5313.553635] [] ? sleep_on_buffer+0x5/0x8 [ 5313.553638] [] ? __wait_on_bit+0x3b/0x6e [ 5313.553640] [] ? out_of_line_wait_on_bit+0x6d/0x76 [ 5313.553642] [] ? do_thaw_one+0x6d/0x6d [ 5313.553645] [] ? autoremove_wake_function+0x2a/0x2a [ 5313.553651] [] ? jbd2_journal_commit_transaction+0xdaa/0x138b [jbd2] [ 5313.553655] [] ? _raw_spin_lock_irqsave+0x14/0x35 [ 5313.553661] [] ? kjournald2+0xb7/0x239 [jbd2] [ 5313.553664] [] ? abort_exclusive_wait+0x79/0x79 [ 5313.553669] [] ? jbd2_superblock_csum+0x31/0x31 [jbd2] [ 5313.553672] [] ? kthread+0x7d/0x85 [ 5313.553675] [] ? do_exit+0x901/0x918 [ 5313.553678] [] ? __kthread_parkme+0x59/0x59 [ 5313.553680] [] ? ret_from_fork+0x7c/0xb0 [ 5313.553683] [] ? __kthread_parkme+0x59/0x59 [ 5313.553721] INFO: task mysqld:5039 blocked for more than 15 seconds. [ 5313.553722] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 5313.553724] mysqld D ffff88042dc13f40 0 5039 5029 0x00000000 [ 5313.553726] ffff8804190a2080 0000000000000086 ffffffff81613400 0000000000013f40 [ 5313.553729] ffff8803f0943fd8 ffff8803f0943fd8 ffff8804190a2080 ffff88041a212000 [ 5313.553732] ffff8803f0943eb0 ffff88041a212024 00000000008180f2 ffff8803f0943ec8 [ 5313.553734] Call Trace: [ 5313.553742] [] ? jbd2_log_wait_commit+0xc3/0x118 [jbd2] [ 5313.553744] [] ? abort_exclusive_wait+0x79/0x79 [ 5313.553753] [] ? ext4_sync_file+0x269/0x2ec [ext4] [ 5313.553757] [] ? do_fsync+0x2b/0x4e [ 5313.553760] [] ? SyS_io_getevents+0x64/0x78 [ 5313.553763] [] ? SyS_fsync+0x7/0xa [ 5313.553766] [] ? system_call_fastpath+0x16/0x1b [ 5313.553785] INFO: task virtuoso-t:5274 blocked for more than 15 seconds. [ 5313.553786] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 5313.553787] virtuoso-t D ffff88042dc33f40 0 5274 5062 0x00000000 [ 5313.553790] ffff88041a297100 0000000000000086 ffff88041d0d8780 0000000000013f40 [ 5313.553792] ffff8803d6a99fd8 ffff8803d6a99fd8 ffff88041a297100 ffff88042dc33f40 [ 5313.553794] ffff88041a297100 0000000000000005 ffff88041926b130 ffff88041c4026e0 [ 5313.553797] Call Trace: [ 5313.553800] [] ? io_schedule+0x54/0x69 [ 5313.553802] [] ? get_request+0x4b1/0x55e [ 5313.553806] [] ? ioc_lookup_icq+0x23/0x3b [ 5313.553808] [] ? abort_exclusive_wait+0x79/0x79 [ 5313.553811] [] ? blk_queue_bio+0x1c0/0x2e8 [ 5313.553819] [] ? dm_request+0x14c/0x15e [dm_mod] [ 5313.553821] [] ? generic_make_request+0x96/0xd5 [ 5313.553823] [] ? submit_bio+0x10a/0x13b [ 5313.553831] [] ? ext4_io_submit+0x21/0x4a [ext4] [ 5313.553839] [] ? mpage_da_submit_io+0x26a/0x280 [ext4] [ 5313.553847] [] ? mpage_da_map_and_submit+0x314/0x32a [ext4] [ 5313.553855] [] ? write_cache_pages_da+0x111/0x360 [ext4] [ 5313.553863] [] ? ext4_da_writepages+0x275/0x447 [ext4] [ 5313.553867] [] ? __filemap_fdatawrite_range+0x4d/0x52 [ 5313.553869] [] ? filemap_write_and_wait_range+0x20/0x50 [ 5313.553876] [] ? ext4_sync_file+0x84/0x2ec [ext4] [ 5313.553880] [] ? do_fsync+0x2b/0x4e [ 5313.553882] [] ? SyS_fsync+0x7/0xa [ 5313.553885] [] ? system_call_fastpath+0x16/0x1b [ 5313.553901] INFO: task kworker/0:0:17733 blocked for more than 15 seconds. [ 5313.553902] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 5313.553904] kworker/0:0 D ffff88042dc13f40 0 17733 2 0x00000000 [ 5313.553911] Workqueue: kdmflush dm_wq_work [dm_mod] [ 5313.553912] ffff8804199ba040 0000000000000046 ffffffff81613400 0000000000013f40 [ 5313.553915] ffff880210f15fd8 ffff880210f15fd8 ffff8804199ba040 ffff88042dc13f40 [ 5313.553918] ffff8804199ba040 0000000000000000 ffff880418bee7b0 ffff8803e14496a0 [ 5313.553921] Call Trace: [ 5313.553924] [] ? io_schedule+0x54/0x69 [ 5313.553926] [] ? get_request+0x4b1/0x55e [ 5313.553929] [] ? abort_exclusive_wait+0x79/0x79 [ 5313.553931] [] ? blk_queue_bio+0x1c0/0x2e8 [ 5313.553934] [] ? generic_make_request+0x96/0xd5 [ 5313.553940] [] ? __clone_and_map_data_bio+0x1cd/0x1ee [dm_mod] [ 5313.553946] [] ? __split_and_process_bio+0x276/0x420 [dm_mod] [ 5313.553951] [] ? dm_wq_work+0x9e/0xb7 [dm_mod] [ 5313.553954] [] ? process_one_work+0x18b/0x287 [ 5313.553956] [] ? worker_thread+0x121/0x1e7 [ 5313.553959] [] ? rescuer_thread+0x265/0x265 [ 5313.553961] [] ? kthread+0x7d/0x85 [ 5313.553964] [] ? __kthread_parkme+0x59/0x59 [ 5313.553966] [] ? ret_from_fork+0x7c/0xb0 [ 5313.553969] [] ? __kthread_parkme+0x59/0x59 [ 6619.155867] INFO: task kworker/2:2:726 blocked for more than 15 seconds. [ 6619.155872] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6619.155874] kworker/2:2 D ffff88042dc53f40 0 726 2 0x00000000 [ 6619.155901] Workqueue: md submit_flushes [md_mod] [ 6619.155903] ffff880417ba77c0 0000000000000046 ffff88041d0d8040 0000000000013f40 [ 6619.155915] ffff88041b21bfd8 ffff88041b21bfd8 ffff880417ba77c0 ffff88042dc53f40 [ 6619.155917] ffff880417ba77c0 0000000000000000 ffff88041c68e3a0 ffff880221258300 [ 6619.155919] Call Trace: [ 6619.155925] [] ? io_schedule+0x54/0x69 [ 6619.155928] [] ? get_request+0x4b1/0x55e [ 6619.155931] [] ? abort_exclusive_wait+0x79/0x79 [ 6619.155933] [] ? blk_queue_bio+0x1c0/0x2e8 [ 6619.155934] [] ? generic_make_request+0x96/0xd5 [ 6619.155936] [] ? submit_bio+0x10a/0x13b [ 6619.155939] [] ? bio_alloc_bioset+0xd0/0x172 [ 6619.155943] [] ? submit_flushes+0xbe/0x116 [md_mod] [ 6619.155946] [] ? process_one_work+0x18b/0x287 [ 6619.155948] [] ? worker_thread+0x121/0x1e7 [ 6619.155950] [] ? rescuer_thread+0x265/0x265 [ 6619.155951] [] ? kthread+0x7d/0x85 [ 6619.155952] [] ? __kthread_parkme+0x59/0x59 [ 6619.155955] [] ? ret_from_fork+0x7c/0xb0 [ 6619.155956] [] ? __kthread_parkme+0x59/0x59 [ 6619.155960] INFO: task jbd2/dm-1-8:1601 blocked for more than 15 seconds. [ 6619.155960] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6619.155961] jbd2/dm-1-8 D ffff88042dc53f40 0 1601 2 0x00000000 [ 6619.155963] ffff880419bfc800 0000000000000046 ffff88041d0d8040 0000000000013f40 [ 6619.155964] ffff88041b365fd8 ffff88041b365fd8 ffff880419bfc800 ffff88042dc53f40 [ 6619.155966] ffff880419bfc800 ffff88041b365cc8 ffffffff8112c313 0000000000000002 [ 6619.155968] Call Trace: [ 6619.155969] [] ? do_thaw_one+0x6d/0x6d [ 6619.155971] [] ? io_schedule+0x54/0x69 [ 6619.155972] [] ? sleep_on_buffer+0x5/0x8 [ 6619.155974] [] ? __wait_on_bit+0x3b/0x6e [ 6619.155976] [] ? out_of_line_wait_on_bit+0x6d/0x76 [ 6619.155977] [] ? do_thaw_one+0x6d/0x6d [ 6619.155978] [] ? autoremove_wake_function+0x2a/0x2a [ 6619.155983] [] ? jbd2_journal_commit_transaction+0xdaa/0x138b [jbd2] [ 6619.155985] [] ? _raw_spin_lock_irqsave+0x14/0x35 [ 6619.155989] [] ? kjournald2+0xb7/0x239 [jbd2] [ 6619.155991] [] ? abort_exclusive_wait+0x79/0x79 [ 6619.155995] [] ? jbd2_superblock_csum+0x31/0x31 [jbd2] [ 6619.155996] [] ? kthread+0x7d/0x85 [ 6619.155999] [] ? do_exit+0x901/0x918 [ 6619.156000] [] ? __kthread_parkme+0x59/0x59 [ 6619.156002] [] ? ret_from_fork+0x7c/0xb0 [ 6619.156003] [] ? __kthread_parkme+0x59/0x59 [ 6619.156049] INFO: task iceweasel:5196 blocked for more than 15 seconds. [ 6619.156050] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6619.156051] iceweasel D ffff88042dc13f40 0 5196 4814 0x00000000 [ 6619.156052] ffff8803d73d0780 0000000000000082 ffffffff81613400 0000000000013f40 [ 6619.156054] ffff8803f088ffd8 ffff8803f088ffd8 ffff8803d73d0780 ffff88041a212000 [ 6619.156055] ffff8803f088feb0 ffff88041a212024 0000000000818286 ffff8803f088fec8 [ 6619.156057] Call Trace: [ 6619.156062] [] ? jbd2_log_wait_commit+0xc3/0x118 [jbd2] [ 6619.156063] [] ? abort_exclusive_wait+0x79/0x79 [ 6619.156069] [] ? ext4_sync_file+0x269/0x2ec [ext4] [ 6619.156072] [] ? do_fsync+0x2b/0x4e [ 6619.156073] [] ? SyS_fsync+0x7/0xa [ 6619.156075] [] ? system_call_fastpath+0x16/0x1b [ 6619.156082] INFO: task virtuoso-t:5274 blocked for more than 15 seconds. [ 6619.156083] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6619.156084] virtuoso-t D ffff88042dc33f40 0 5274 5062 0x00000000 [ 6619.156085] ffff88041a297100 0000000000000086 ffff88041d0d8780 0000000000013f40 [ 6619.156087] ffff8803d6a99fd8 ffff8803d6a99fd8 ffff88041a297100 ffff88042dc33f40 [ 6619.156088] ffff88041a297100 0000000000000000 ffff88041926b130 ffff880223b00be0 [ 6619.156090] Call Trace: [ 6619.156092] [] ? io_schedule+0x54/0x69 [ 6619.156093] [] ? get_request+0x4b1/0x55e [ 6619.156095] [] ? ioc_lookup_icq+0x23/0x3b [ 6619.156097] [] ? abort_exclusive_wait+0x79/0x79 [ 6619.156098] [] ? blk_queue_bio+0x1c0/0x2e8 [ 6619.156103] [] ? dm_request+0x14c/0x15e [dm_mod] [ 6619.156104] [] ? generic_make_request+0x96/0xd5 [ 6619.156105] [] ? submit_bio+0x10a/0x13b [ 6619.156111] [] ? ext4_io_submit+0x21/0x4a [ext4] [ 6619.156116] [] ? mpage_da_submit_io+0x26a/0x280 [ext4] [ 6619.156121] [] ? mpage_da_map_and_submit+0x314/0x32a [ext4] [ 6619.156126] [] ? write_cache_pages_da+0x111/0x360 [ext4] [ 6619.156130] [] ? ext4_da_writepages+0x275/0x447 [ext4] [ 6619.156133] [] ? __filemap_fdatawrite_range+0x4d/0x52 [ 6619.156135] [] ? filemap_write_and_wait_range+0x20/0x50 [ 6619.156139] [] ? ext4_sync_file+0x84/0x2ec [ext4] [ 6619.156141] [] ? do_fsync+0x2b/0x4e [ 6619.156150] [] ? SyS_fsync+0x7/0xa [ 6619.156151] [] ? system_call_fastpath+0x16/0x1b -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/