* XFS crash? @ 2014-03-05 23:08 Austin Schuh 2014-03-05 23:35 ` Dave Chinner 0 siblings, 1 reply; 30+ messages in thread From: Austin Schuh @ 2014-03-05 23:08 UTC (permalink / raw) To: xfs Howdy, I'm running a config_preempt_rt patched version of the 3.10.11 kernel, and I'm seeing a couple lockups and crashes which I think are related to XFS. After the first lockup, I booted into single user mode, mounted the filesystem readonly, and then ran xfs_repair -d. When I rebooted again, I initiated a large copy to a USB drive (formated EXT3) and continued editing source files and compiling. After a couple minutes, my laptop started locking up and after 2 minutes, the following showed up in the kernel. Austin $ uname -a Linux vpc5 3.10-3-rt-amd64 #5 SMP PREEMPT RT Debian 3.10.11-2 (2013-09-10) x86_64 GNU/Linux [ 1186.363397] usb 2-1: USB disconnect, device number 2 [ 1200.895262] INFO: task kworker/u16:5:250 blocked for more than 120 seconds. [ 1200.895267] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1200.895270] kworker/u16:5 D ffff88040dc62cc0 0 250 2 0x00000000 [ 1200.895281] Workqueue: writeback bdi_writeback_workfn (flush-8:0) [ 1200.895287] ffff880406fc5c20 0000000000000046 0000000000008000 ffff880407f06ce0 [ 1200.895288] 0000000000062cc0 ffff880407dfdfd8 0000000000062cc0 ffff880407dfdfd8 [ 1200.895290] ffff880407dfd5e8 ffff880406fc5c20 ffff880407dfd710 ffff880407dfd708 [ 1200.895294] Call Trace: [ 1200.895301] [<ffffffff813a10ef>] ? console_conditional_schedule+0xf/0xf [ 1200.895304] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 1200.895307] [<ffffffff813a111b>] ? schedule_timeout+0x2c/0x123 [ 1200.895310] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 [ 1200.895313] [<ffffffff81065cfd>] ? migrate_enable+0x1cd/0x1dd [ 1200.895317] [<ffffffff810651ab>] ? get_parent_ip+0x9/0x1b [ 1200.895319] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 [ 1200.895322] [<ffffffff813a188b>] ? __wait_for_common+0x78/0xd6 [ 1200.895356] [<ffffffffa01a5032>] ? xfs_bmapi_allocate+0x92/0x9e [xfs] [ 1200.895371] [<ffffffffa01a535d>] ? xfs_bmapi_write+0x31f/0x558 [xfs] [ 1200.895375] [<ffffffff81109680>] ? kmem_cache_alloc+0x7c/0x17d [ 1200.895390] [<ffffffffa01a2e6e>] ? __xfs_bmapi_allocate+0x22b/0x22b [xfs] [ 1200.895402] [<ffffffffa018b899>] ? xfs_iomap_write_allocate+0x1bc/0x2c8 [xfs] [ 1200.895414] [<ffffffffa017edc5>] ? xfs_map_blocks+0x125/0x1f5 [xfs] [ 1200.895424] [<ffffffffa017fc87>] ? xfs_vm_writepage+0x266/0x48f [xfs] [ 1200.895428] [<ffffffff810d3d14>] ? __writepage+0xd/0x2a [ 1200.895430] [<ffffffff810d4790>] ? write_cache_pages+0x207/0x302 [ 1200.895432] [<ffffffff810d3d07>] ? page_index+0x14/0x14 [ 1200.895435] [<ffffffff810d48c6>] ? generic_writepages+0x3b/0x57 [ 1200.895438] [<ffffffff81134698>] ? __writeback_single_inode+0x72/0x225 [ 1200.895441] [<ffffffff8113550b>] ? writeback_sb_inodes+0x215/0x36d [ 1200.895444] [<ffffffff811356cc>] ? __writeback_inodes_wb+0x69/0xab [ 1200.895446] [<ffffffff81135844>] ? wb_writeback+0x136/0x2a7 [ 1200.895448] [<ffffffff810d3fc8>] ? global_dirtyable_memory+0xd/0x46 [ 1200.895450] [<ffffffff810d4945>] ? global_dirty_limits+0x27/0x120 [ 1200.895453] [<ffffffff81135cc8>] ? wb_do_writeback+0x1a1/0x1dc [ 1200.895456] [<ffffffff81135d66>] ? bdi_writeback_workfn+0x63/0xf4 [ 1200.895460] [<ffffffff81055a49>] ? process_one_work+0x19b/0x2b2 [ 1200.895462] [<ffffffff81055f41>] ? worker_thread+0x12b/0x1f6 [ 1200.895465] [<ffffffff81055e16>] ? rescuer_thread+0x28f/0x28f [ 1200.895467] [<ffffffff8105a909>] ? kthread+0x81/0x89 [ 1200.895469] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 1200.895472] [<ffffffff813a75fc>] ? ret_from_fork+0x7c/0xb0 [ 1200.895474] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 1200.895477] INFO: task kworker/0:2:272 blocked for more than 120 seconds. [ 1200.895501] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1200.895503] kworker/0:2 D ffff880407f06ce0 0 272 2 0x00000000 [ 1200.895517] Workqueue: xfs-data/sda7 xfs_end_io [xfs] [ 1200.895520] ffff880407f06ce0 0000000000000046 ffffffffffffffff ffff88032dc7baa0 [ 1200.895522] 0000000000062cc0 ffff8804053f3fd8 0000000000062cc0 ffff8804053f3fd8 [ 1200.895524] 0000000000000001 ffff880407f06ce0 ffff88030fb5df80 0000000000000002 [ 1200.895526] Call Trace: [ 1200.895531] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 1200.895534] [<ffffffff813a2438>] ? __rt_mutex_slowlock+0x7b/0xb4 [ 1200.895537] [<ffffffff813a2577>] ? rt_mutex_slowlock+0xe5/0x150 [ 1200.895542] [<ffffffff8100c02f>] ? load_TLS+0x7/0xa [ 1200.895552] [<ffffffffa017eadb>] ? xfs_setfilesize+0x48/0x120 [xfs] [ 1200.895555] [<ffffffff81063d25>] ? finish_task_switch+0x80/0xc6 [ 1200.895565] [<ffffffffa017f62f>] ? xfs_end_io+0x7a/0x8e [xfs] [ 1200.895568] [<ffffffff81055a49>] ? process_one_work+0x19b/0x2b2 [ 1200.895570] [<ffffffff81055f41>] ? worker_thread+0x12b/0x1f6 [ 1200.895572] [<ffffffff81055e16>] ? rescuer_thread+0x28f/0x28f [ 1200.895574] [<ffffffff8105a909>] ? kthread+0x81/0x89 [ 1200.895576] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 1200.895579] [<ffffffff813a75fc>] ? ret_from_fork+0x7c/0xb0 [ 1200.895581] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 1200.895617] INFO: task BrowserBlocking:5547 blocked for more than 120 seconds. [ 1200.895628] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1200.895630] BrowserBlocking D ffff88040dc62cc0 0 5547 1 0x00000000 [ 1200.895635] ffff88040497baa0 0000000000000086 0000000000000000 ffffffff81616400 [ 1200.895636] 0000000000062cc0 ffff8803f07bbfd8 0000000000062cc0 ffff8803f07bbfd8 [ 1200.895638] ffff8803f07bb868 ffff88040497baa0 ffff8803f07bb990 ffff8803f07bb988 [ 1200.895641] Call Trace: [ 1200.895645] [<ffffffff813a10ef>] ? console_conditional_schedule+0xf/0xf [ 1200.895648] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 1200.895650] [<ffffffff813a111b>] ? schedule_timeout+0x2c/0x123 [ 1200.895653] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 [ 1200.895654] [<ffffffff81065cfd>] ? migrate_enable+0x1cd/0x1dd [ 1200.895657] [<ffffffff810651ab>] ? get_parent_ip+0x9/0x1b [ 1200.895659] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 [ 1200.895662] [<ffffffff813a188b>] ? __wait_for_common+0x78/0xd6 [ 1200.895676] [<ffffffffa01a5032>] ? xfs_bmapi_allocate+0x92/0x9e [xfs] [ 1200.895689] [<ffffffffa01a535d>] ? xfs_bmapi_write+0x31f/0x558 [xfs] [ 1200.895691] [<ffffffff81109680>] ? kmem_cache_alloc+0x7c/0x17d [ 1200.895705] [<ffffffffa01a2e6e>] ? __xfs_bmapi_allocate+0x22b/0x22b [xfs] [ 1200.895717] [<ffffffffa018b899>] ? xfs_iomap_write_allocate+0x1bc/0x2c8 [xfs] [ 1200.895728] [<ffffffffa017edc5>] ? xfs_map_blocks+0x125/0x1f5 [xfs] [ 1200.895739] [<ffffffffa017fc87>] ? xfs_vm_writepage+0x266/0x48f [xfs] [ 1200.895742] [<ffffffff810d3d14>] ? __writepage+0xd/0x2a [ 1200.895744] [<ffffffff810d4790>] ? write_cache_pages+0x207/0x302 [ 1200.895745] [<ffffffff810d3d07>] ? page_index+0x14/0x14 [ 1200.895749] [<ffffffff8104031a>] ? pin_current_cpu+0x3e/0x191 [ 1200.895752] [<ffffffff810d48c6>] ? generic_writepages+0x3b/0x57 [ 1200.895755] [<ffffffff810cd303>] ? __filemap_fdatawrite_range+0x50/0x55 [ 1200.895758] [<ffffffff810cd32d>] ? filemap_write_and_wait_range+0x25/0x59 [ 1200.895769] [<ffffffffa01844d4>] ? xfs_file_fsync+0x78/0x1ad [xfs] [ 1200.895773] [<ffffffff8113876b>] ? do_fsync+0x2b/0x50 [ 1200.895776] [<ffffffff8113897d>] ? SyS_fdatasync+0xb/0xf [ 1200.895778] [<ffffffff813a76a9>] ? system_call_fastpath+0x16/0x1b [ 1200.895780] INFO: task BrowserBlocking:5558 blocked for more than 120 seconds. [ 1200.895800] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1200.895801] BrowserBlocking D ffff88040dde2cc0 0 5558 1 0x00000000 [ 1200.895806] ffff8804093ac300 0000000000000086 ffff8803efd94000 ffff88040ad28000 [ 1200.895808] 0000000000062cc0 ffff8803efd95fd8 0000000000062cc0 ffff8803efd95fd8 [ 1200.895809] ffff88041e52efc0 ffff8804093ac300 ffff8804093ac300 ffff8803efd95da0 [ 1200.895812] Call Trace: [ 1200.895816] [<ffffffff810cc034>] ? __lock_page+0x66/0x66 [ 1200.895819] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 1200.895821] [<ffffffff813a1ff9>] ? io_schedule+0x55/0x6b [ 1200.895823] [<ffffffff810cc03a>] ? sleep_on_page+0x6/0xa [ 1200.895826] [<ffffffff813a128f>] ? __wait_on_bit+0x3e/0x75 [ 1200.895828] [<ffffffff810cc4a4>] ? find_get_pages_tag+0xfa/0x125 [ 1200.895830] [<ffffffff810cc0f3>] ? wait_on_page_bit+0x6e/0x73 [ 1200.895833] [<ffffffff8105b333>] ? autoremove_wake_function+0x2a/0x2a [ 1200.895835] [<ffffffff810cc7bf>] ? filemap_fdatawait_range+0x66/0xfe [ 1200.895838] [<ffffffff810cd303>] ? __filemap_fdatawrite_range+0x50/0x55 [ 1200.895841] [<ffffffff810cd342>] ? filemap_write_and_wait_range+0x3a/0x59 [ 1200.895852] [<ffffffffa01844d4>] ? xfs_file_fsync+0x78/0x1ad [xfs] [ 1200.895855] [<ffffffff8113876b>] ? do_fsync+0x2b/0x50 [ 1200.895858] [<ffffffff8113897d>] ? SyS_fdatasync+0xb/0xf [ 1200.895860] [<ffffffff813a76a9>] ? system_call_fastpath+0x16/0x1b [ 1200.895863] INFO: task BrowserBlocking:5575 blocked for more than 120 seconds. [ 1200.895874] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1200.895876] BrowserBlocking D ffff88040dd62cc0 0 5575 1 0x00000000 [ 1200.895881] ffff880408c46480 0000000000000086 ffff8803f064e000 ffff88040accf540 [ 1200.895882] 0000000000062cc0 ffff8803f064ffd8 0000000000062cc0 ffff8803f064ffd8 [ 1200.895884] ffff88041e54dfc0 ffff880408c46480 ffff880408c46480 ffff8803f064fda0 [ 1200.895887] Call Trace: [ 1200.895891] [<ffffffff810cc034>] ? __lock_page+0x66/0x66 [ 1200.895893] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 1200.895896] [<ffffffff813a1ff9>] ? io_schedule+0x55/0x6b [ 1200.895898] [<ffffffff810cc03a>] ? sleep_on_page+0x6/0xa [ 1200.895900] [<ffffffff813a128f>] ? __wait_on_bit+0x3e/0x75 [ 1200.895902] [<ffffffff810cc4a4>] ? find_get_pages_tag+0xfa/0x125 [ 1200.895905] [<ffffffff810cc0f3>] ? wait_on_page_bit+0x6e/0x73 [ 1200.895907] [<ffffffff8105b333>] ? autoremove_wake_function+0x2a/0x2a [ 1200.895909] [<ffffffff810cc7bf>] ? filemap_fdatawait_range+0x66/0xfe [ 1200.895912] [<ffffffff810cd303>] ? __filemap_fdatawrite_range+0x50/0x55 [ 1200.895915] [<ffffffff810cd342>] ? filemap_write_and_wait_range+0x3a/0x59 [ 1200.895926] [<ffffffffa01844d4>] ? xfs_file_fsync+0x78/0x1ad [xfs] [ 1200.895929] [<ffffffff8113876b>] ? do_fsync+0x2b/0x50 [ 1200.895932] [<ffffffff8113896d>] ? SyS_fsync+0x9/0xe [ 1200.895934] [<ffffffff813a76a9>] ? system_call_fastpath+0x16/0x1b [ 1200.895965] INFO: task xterm:6032 blocked for more than 120 seconds. [ 1200.895977] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1200.895979] xterm D ffff88040dc62cc0 0 6032 1 0x00000000 [ 1200.895983] ffff880407ce9920 0000000000000086 ffff8803b8473700 ffffffff81616400 [ 1200.895985] 0000000000062cc0 ffff8803b86affd8 0000000000062cc0 ffff8803b86affd8 [ 1200.895986] ffff8803b86afc48 ffff880407ce9920 ffff8803b86afd50 ffff8803b86afd48 [ 1200.895989] Call Trace: [ 1200.895994] [<ffffffff813a10ef>] ? console_conditional_schedule+0xf/0xf [ 1200.895996] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 1200.895999] [<ffffffff813a111b>] ? schedule_timeout+0x2c/0x123 [ 1200.896002] [<ffffffff810651ab>] ? get_parent_ip+0x9/0x1b [ 1200.896004] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 [ 1200.896006] [<ffffffff813a188b>] ? __wait_for_common+0x78/0xd6 [ 1200.896009] [<ffffffff810549bb>] ? flush_work+0xf6/0x119 [ 1200.896011] [<ffffffff8105344b>] ? create_and_start_worker+0x5e/0x5e [ 1200.896016] [<ffffffff812606fa>] ? input_available_p+0x15/0x53 [ 1200.896019] [<ffffffff812629fd>] ? n_tty_read+0x374/0x78f [ 1200.896022] [<ffffffff810671e8>] ? try_to_wake_up+0x1ca/0x1ca [ 1200.896024] [<ffffffff8125e28c>] ? tty_read+0x79/0xbd [ 1200.896029] [<ffffffff8111587c>] ? vfs_read+0x93/0xf5 [ 1200.896032] [<ffffffff811159f5>] ? SyS_read+0x51/0x80 [ 1200.896035] [<ffffffff813a76a9>] ? system_call_fastpath+0x16/0x1b [ 1200.896046] INFO: task tup:12846 blocked for more than 120 seconds. [ 1200.896058] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1200.896060] tup D ffff88040dc62cc0 0 12846 7061 0x00000000 [ 1200.896064] ffff88032dc7baa0 0000000000000086 ffff8802cc83dde8 ffffffff81616400 [ 1200.896066] 0000000000062cc0 ffff8802cc83dfd8 0000000000062cc0 ffff8802cc83dfd8 [ 1200.896068] ffff8802dd120818 ffff88032dc7baa0 ffff88030fb5df80 0000000000000002 [ 1200.896071] Call Trace: [ 1200.896075] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 1200.896078] [<ffffffff813a2438>] ? __rt_mutex_slowlock+0x7b/0xb4 [ 1200.896081] [<ffffffff813a2577>] ? rt_mutex_slowlock+0xe5/0x150 [ 1200.896094] [<ffffffffa018c3ec>] ? xfs_vn_update_time+0xa0/0x16f [xfs] [ 1200.896097] [<ffffffff81128b78>] ? file_update_time+0x95/0xb5 [ 1200.896098] [<ffffffff81065cfd>] ? migrate_enable+0x1cd/0x1dd [ 1200.896109] [<ffffffffa018524b>] ? xfs_file_aio_write_checks+0xa3/0xc0 [xfs] [ 1200.896120] [<ffffffffa01852cf>] ? xfs_file_buffered_aio_write+0x67/0x175 [xfs] [ 1200.896122] [<ffffffff810671e8>] ? try_to_wake_up+0x1ca/0x1ca [ 1200.896133] [<ffffffffa018549a>] ? xfs_file_aio_write+0xbd/0x10f [xfs] [ 1200.896136] [<ffffffff81114d6f>] ? do_sync_write+0x55/0x7c [ 1200.896140] [<ffffffff81115783>] ? vfs_write+0x9e/0x104 [ 1200.896143] [<ffffffff81115b8c>] ? SyS_pwrite64+0x61/0x87 [ 1200.896146] [<ffffffff813a76a9>] ? system_call_fastpath+0x16/0x1b [ 1200.896149] INFO: task ld:12961 blocked for more than 120 seconds. [ 1200.896160] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1200.896162] ld D ffff8802d3c4a180 0 12961 1 0x00000004 [ 1200.896166] ffff8802d3c4a180 0000000000000086 ffff8802dd1b7ec0 ffff8802d41fbaa0 [ 1200.896168] 0000000000062cc0 ffff8802d3c9ffd8 0000000000062cc0 ffff8802d3c9ffd8 [ 1200.896169] ffff8802dd1b7ec0 ffff8802d3c4a180 ffff880406cd1000 ffff8802d3c9fb90 [ 1200.896172] Call Trace: [ 1200.896176] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 1200.896180] [<ffffffffa07bbd11>] ? __fuse_request_send+0x1fa/0x2d0 [fuse] [ 1200.896183] [<ffffffff8105b309>] ? abort_exclusive_wait+0x7f/0x7f [ 1200.896187] [<ffffffffa07c045e>] ? fuse_send_write+0x118/0x12b [fuse] [ 1200.896190] [<ffffffffa07c04e1>] ? fuse_send_write_pages+0x70/0x10f [fuse] [ 1200.896193] [<ffffffff8104047a>] ? unpin_current_cpu+0xd/0x51 [ 1200.896198] [<ffffffffa07c1ae9>] ? fuse_perform_write+0x27a/0x2fd [fuse] [ 1200.896202] [<ffffffffa07c1dba>] ? fuse_file_aio_write+0x24e/0x297 [fuse] [ 1200.896205] [<ffffffff81114d6f>] ? do_sync_write+0x55/0x7c [ 1200.896209] [<ffffffff81115783>] ? vfs_write+0x9e/0x104 [ 1200.896212] [<ffffffff81115a75>] ? SyS_write+0x51/0x80 [ 1200.896215] [<ffffffff813a76a9>] ? system_call_fastpath+0x16/0x1b [ 1200.896217] INFO: task ld:12970 blocked for more than 120 seconds. [ 1200.896226] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1200.896228] ld D ffff88040dce2cc0 0 12970 1 0x00000006 [ 1200.896232] ffff8802d3d090c0 0000000000000046 ffff8802dd1b64f8 ffff88040accece0 [ 1200.896234] 0000000000062cc0 ffff880373e47fd8 0000000000062cc0 ffff880373e47fd8 [ 1200.896236] ffff8802dd1b64f8 ffff8802d3d090c0 ffff880406cd1000 ffff880373e47be0 [ 1200.896239] Call Trace: [ 1200.896243] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 1200.896246] [<ffffffffa07bbd11>] ? __fuse_request_send+0x1fa/0x2d0 [fuse] [ 1200.896248] [<ffffffff8105b309>] ? abort_exclusive_wait+0x7f/0x7f [ 1200.896252] [<ffffffffa07c030a>] ? fuse_flush+0xba/0xf6 [fuse] [ 1200.896254] [<ffffffff81113a4a>] ? filp_close+0x37/0x68 [ 1200.896257] [<ffffffff8112aabf>] ? put_files_struct+0x6c/0xc5 [ 1200.896260] [<ffffffff8104204d>] ? do_exit+0x3d5/0x946 [ 1200.896263] [<ffffffff8104031a>] ? pin_current_cpu+0x3e/0x191 [ 1200.896265] [<ffffffff8104265a>] ? do_group_exit+0x77/0xac [ 1200.896268] [<ffffffff8104e14a>] ? get_signal_to_deliver+0x4ff/0x543 [ 1200.896272] [<ffffffff8100d1f7>] ? do_signal+0x3c/0x434 [ 1200.896275] [<ffffffff8111587c>] ? vfs_read+0x93/0xf5 [ 1200.896278] [<ffffffff8100d641>] ? do_notify_resume+0x52/0x97 [ 1200.896281] [<ffffffff813a7966>] ? int_signal+0x12/0x17 [ 1320.927310] INFO: task khubd:210 blocked for more than 120 seconds. [ 1320.927335] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1320.927338] khubd D ffff88040dd62cc0 0 210 2 0x00000000 [ 1320.927346] ffff880407a0dc20 0000000000000046 0000000000000000 ffff88040accf540 [ 1320.927348] 0000000000062cc0 ffff880404843fd8 0000000000062cc0 ffff880404843fd8 [ 1320.927350] 0000000000000000 ffff880407a0dc20 ffff880404843a70 ffff880404843a68 [ 1320.927354] Call Trace: [ 1320.927364] [<ffffffff813a10ef>] ? console_conditional_schedule+0xf/0xf [ 1320.927367] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 1320.927370] [<ffffffff813a111b>] ? schedule_timeout+0x2c/0x123 [ 1320.927374] [<ffffffff8102c27b>] ? _flat_send_IPI_mask+0x68/0x78 [ 1320.927378] [<ffffffff810651ab>] ? get_parent_ip+0x9/0x1b [ 1320.927381] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 [ 1320.927382] [<ffffffff813a188b>] ? __wait_for_common+0x78/0xd6 [ 1320.927394] [<ffffffff810549bb>] ? flush_work+0xf6/0x119 [ 1320.927396] [<ffffffff8105344b>] ? create_and_start_worker+0x5e/0x5e [ 1320.927400] [<ffffffff810d7309>] ? __pagevec_release+0x20/0x20 [ 1320.927402] [<ffffffff810564cc>] ? schedule_on_each_cpu+0x9e/0xd5 [ 1320.927422] [<ffffffff8113f5a0>] ? invalidate_bdev+0x1d/0x2e [ 1320.927425] [<ffffffff8113f5f4>] ? __invalidate_device+0x43/0x4b [ 1320.927427] [<ffffffff811bf94d>] ? invalidate_partition+0x27/0x41 [ 1320.927429] [<ffffffff811c09f9>] ? del_gendisk+0x86/0x1bb [ 1320.927435] [<ffffffffa00de643>] ? sd_remove+0x5f/0x98 [sd_mod] [ 1320.927443] [<ffffffff8128d2a0>] ? __device_release_driver+0x7f/0xd5 [ 1320.927444] [<ffffffff8128d53a>] ? device_release_driver+0x1a/0x25 [ 1320.927446] [<ffffffff8128cee7>] ? bus_remove_device+0xe7/0xfc [ 1320.927448] [<ffffffff8128ada0>] ? device_del+0x120/0x176 [ 1320.927455] [<ffffffffa0029a0f>] ? __scsi_remove_device+0x4d/0xaf [scsi_mod] [ 1320.927461] [<ffffffffa002898c>] ? scsi_forget_host+0x48/0x68 [scsi_mod] [ 1320.927467] [<ffffffffa002025c>] ? scsi_remove_host+0x85/0x101 [scsi_mod] [ 1320.927472] [<ffffffffa00d1f7c>] ? usb_stor_disconnect+0x63/0xae [usb_storage] [ 1320.927479] [<ffffffffa0071d31>] ? usb_unbind_interface+0x5e/0x135 [usbcore] [ 1320.927488] [<ffffffff8128d2a0>] ? __device_release_driver+0x7f/0xd5 [ 1320.927490] [<ffffffff8128d53a>] ? device_release_driver+0x1a/0x25 [ 1320.927491] [<ffffffff8128cee7>] ? bus_remove_device+0xe7/0xfc [ 1320.927493] [<ffffffff8128ada0>] ? device_del+0x120/0x176 [ 1320.927501] [<ffffffffa0070025>] ? usb_disable_device+0x6a/0x180 [usbcore] [ 1320.927509] [<ffffffffa0069507>] ? usb_disconnect+0x79/0x151 [usbcore] [ 1320.927515] [<ffffffffa006abee>] ? hub_thread+0x60d/0xea2 [usbcore] [ 1320.927518] [<ffffffff8105b309>] ? abort_exclusive_wait+0x7f/0x7f [ 1320.927524] [<ffffffffa006a5e1>] ? hub_port_debounce+0xcf/0xcf [usbcore] [ 1320.927526] [<ffffffff8105a909>] ? kthread+0x81/0x89 [ 1320.927528] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 1320.927530] [<ffffffff813a75fc>] ? ret_from_fork+0x7c/0xb0 [ 1320.927532] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: XFS crash? 2014-03-05 23:08 XFS crash? Austin Schuh @ 2014-03-05 23:35 ` Dave Chinner 2014-03-06 0:53 ` Austin Schuh 0 siblings, 1 reply; 30+ messages in thread From: Dave Chinner @ 2014-03-05 23:35 UTC (permalink / raw) To: Austin Schuh; +Cc: xfs On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote: > Howdy, > > I'm running a config_preempt_rt patched version of the 3.10.11 kernel, > and I'm seeing a couple lockups and crashes which I think are related > to XFS. I think they ar emore likely related to RT issues.... > After the first lockup, I booted into single user mode, mounted the > filesystem readonly, and then ran xfs_repair -d. When I rebooted > again, I initiated a large copy to a USB drive (formated EXT3) and > continued editing source files and compiling. After a couple minutes, > my laptop started locking up and after 2 minutes, the following showed > up in the kernel. > > Austin > > $ uname -a > Linux vpc5 3.10-3-rt-amd64 #5 SMP PREEMPT RT Debian 3.10.11-2 > (2013-09-10) x86_64 GNU/Linux > > [ 1186.363397] usb 2-1: USB disconnect, device number 2 > [ 1200.895262] INFO: task kworker/u16:5:250 blocked for more than 120 seconds. > [ 1200.895267] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 1200.895270] kworker/u16:5 D ffff88040dc62cc0 0 250 2 0x00000000 > [ 1200.895281] Workqueue: writeback bdi_writeback_workfn (flush-8:0) .... > [ 1200.895294] Call Trace: > [ 1200.895301] [<ffffffff813a10ef>] ? console_conditional_schedule+0xf/0xf > [ 1200.895304] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c > [ 1200.895307] [<ffffffff813a111b>] ? schedule_timeout+0x2c/0x123 > [ 1200.895310] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 > [ 1200.895313] [<ffffffff81065cfd>] ? migrate_enable+0x1cd/0x1dd > [ 1200.895317] [<ffffffff810651ab>] ? get_parent_ip+0x9/0x1b > [ 1200.895319] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 > [ 1200.895322] [<ffffffff813a188b>] ? __wait_for_common+0x78/0xd6 > [ 1200.895356] [<ffffffffa01a5032>] ? xfs_bmapi_allocate+0x92/0x9e [xfs] > [ 1200.895371] [<ffffffffa01a535d>] ? xfs_bmapi_write+0x31f/0x558 [xfs] > [ 1200.895375] [<ffffffff81109680>] ? kmem_cache_alloc+0x7c/0x17d > [ 1200.895390] [<ffffffffa01a2e6e>] ? __xfs_bmapi_allocate+0x22b/0x22b [xfs] > [ 1200.895402] [<ffffffffa018b899>] ? xfs_iomap_write_allocate+0x1bc/0x2c8 [xfs] > [ 1200.895414] [<ffffffffa017edc5>] ? xfs_map_blocks+0x125/0x1f5 [xfs] > [ 1200.895424] [<ffffffffa017fc87>] ? xfs_vm_writepage+0x266/0x48f [xfs] > [ 1200.895428] [<ffffffff810d3d14>] ? __writepage+0xd/0x2a > [ 1200.895430] [<ffffffff810d4790>] ? write_cache_pages+0x207/0x302 > [ 1200.895432] [<ffffffff810d3d07>] ? page_index+0x14/0x14 > [ 1200.895435] [<ffffffff810d48c6>] ? generic_writepages+0x3b/0x57 > [ 1200.895438] [<ffffffff81134698>] ? __writeback_single_inode+0x72/0x225 > [ 1200.895441] [<ffffffff8113550b>] ? writeback_sb_inodes+0x215/0x36d > [ 1200.895444] [<ffffffff811356cc>] ? __writeback_inodes_wb+0x69/0xab > [ 1200.895446] [<ffffffff81135844>] ? wb_writeback+0x136/0x2a7 That's waiting for allocation of blocks to complete during writeback of dirty data via background writeback. > [ 1200.895517] Workqueue: xfs-data/sda7 xfs_end_io [xfs] .... > [ 1200.895526] Call Trace: > [ 1200.895531] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c > [ 1200.895534] [<ffffffff813a2438>] ? __rt_mutex_slowlock+0x7b/0xb4 > [ 1200.895537] [<ffffffff813a2577>] ? rt_mutex_slowlock+0xe5/0x150 > [ 1200.895542] [<ffffffff8100c02f>] ? load_TLS+0x7/0xa > [ 1200.895552] [<ffffffffa017eadb>] ? xfs_setfilesize+0x48/0x120 [xfs] > [ 1200.895555] [<ffffffff81063d25>] ? finish_task_switch+0x80/0xc6 > [ 1200.895565] [<ffffffffa017f62f>] ? xfs_end_io+0x7a/0x8e [xfs] > [ 1200.895568] [<ffffffff81055a49>] ? process_one_work+0x19b/0x2b2 > [ 1200.895570] [<ffffffff81055f41>] ? worker_thread+0x12b/0x1f6 > [ 1200.895572] [<ffffffff81055e16>] ? rescuer_thread+0x28f/0x28f > [ 1200.895574] [<ffffffff8105a909>] ? kthread+0x81/0x89 > [ 1200.895576] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c > [ 1200.895579] [<ffffffff813a75fc>] ? ret_from_fork+0x7c/0xb0 > [ 1200.895581] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c IO completion waiting on a lock. No idea what lock, because the rt code replaces various different types of locks with "rt_mutexes". > [ 1200.895630] BrowserBlocking D ffff88040dc62cc0 0 5547 1 0x00000000 fsync waiting for allocation completion during data writeback. > [ 1200.895801] BrowserBlocking D ffff88040dde2cc0 0 5558 1 0x00000000 fsync waiting for IO completion of a data page during data writeback. > [ 1200.895876] BrowserBlocking D ffff88040dd62cc0 0 5575 1 0x00000000 ditto. > [ 1200.895979] xterm D ffff88040dc62cc0 0 6032 1 0x00000000 Blocked waiting on a workqueue flush. Completely unrealted to filesystems and IO. > [ 1200.896060] tup D ffff88040dc62cc0 0 12846 7061 0x00000000 Blocked on an inode lock (rt_mutex, again) during timestamp updates on a write(2) syscall. > [ 1200.896162] ld D ffff8802d3c4a180 0 12961 1 0x00000004 FUSE filesystem write blocked ?something? in it's IO path. > [ 1200.896228] ld D ffff88040dce2cc0 0 12970 1 0x00000006 FUSE filesystem write blocked ?something? in it's IO path after recieving a signal in read(2) call. > [ 1320.927338] khubd D ffff88040dd62cc0 0 210 2 0x00000000 This is the smoking gun: > [ 1320.927364] [<ffffffff813a10ef>] ? console_conditional_schedule+0xf/0xf > [ 1320.927367] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c > [ 1320.927370] [<ffffffff813a111b>] ? schedule_timeout+0x2c/0x123 > [ 1320.927374] [<ffffffff8102c27b>] ? _flat_send_IPI_mask+0x68/0x78 > [ 1320.927378] [<ffffffff810651ab>] ? get_parent_ip+0x9/0x1b > [ 1320.927381] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 > [ 1320.927382] [<ffffffff813a188b>] ? __wait_for_common+0x78/0xd6 > [ 1320.927394] [<ffffffff810549bb>] ? flush_work+0xf6/0x119 > [ 1320.927396] [<ffffffff8105344b>] ? create_and_start_worker+0x5e/0x5e > [ 1320.927400] [<ffffffff810d7309>] ? __pagevec_release+0x20/0x20 > [ 1320.927402] [<ffffffff810564cc>] ? schedule_on_each_cpu+0x9e/0xd5 > [ 1320.927422] [<ffffffff8113f5a0>] ? invalidate_bdev+0x1d/0x2e > [ 1320.927425] [<ffffffff8113f5f4>] ? __invalidate_device+0x43/0x4b > [ 1320.927427] [<ffffffff811bf94d>] ? invalidate_partition+0x27/0x41 > [ 1320.927429] [<ffffffff811c09f9>] ? del_gendisk+0x86/0x1bb > [ 1320.927435] [<ffffffffa00de643>] ? sd_remove+0x5f/0x98 [sd_mod] > [ 1320.927443] [<ffffffff8128d2a0>] ? __device_release_driver+0x7f/0xd5 > [ 1320.927444] [<ffffffff8128d53a>] ? device_release_driver+0x1a/0x25 > [ 1320.927446] [<ffffffff8128cee7>] ? bus_remove_device+0xe7/0xfc > [ 1320.927448] [<ffffffff8128ada0>] ? device_del+0x120/0x176 > [ 1320.927455] [<ffffffffa0029a0f>] ? __scsi_remove_device+0x4d/0xaf [scsi_mod] > [ 1320.927461] [<ffffffffa002898c>] ? scsi_forget_host+0x48/0x68 [scsi_mod] > [ 1320.927467] [<ffffffffa002025c>] ? scsi_remove_host+0x85/0x101 [scsi_mod] > [ 1320.927472] [<ffffffffa00d1f7c>] ? usb_stor_disconnect+0x63/0xae > [usb_storage] > [ 1320.927479] [<ffffffffa0071d31>] ? usb_unbind_interface+0x5e/0x135 [usbcore] > [ 1320.927488] [<ffffffff8128d2a0>] ? __device_release_driver+0x7f/0xd5 > [ 1320.927490] [<ffffffff8128d53a>] ? device_release_driver+0x1a/0x25 > [ 1320.927491] [<ffffffff8128cee7>] ? bus_remove_device+0xe7/0xfc > [ 1320.927493] [<ffffffff8128ada0>] ? device_del+0x120/0x176 > [ 1320.927501] [<ffffffffa0070025>] ? usb_disable_device+0x6a/0x180 [usbcore] > [ 1320.927509] [<ffffffffa0069507>] ? usb_disconnect+0x79/0x151 [usbcore] > [ 1320.927515] [<ffffffffa006abee>] ? hub_thread+0x60d/0xea2 [usbcore] > [ 1320.927518] [<ffffffff8105b309>] ? abort_exclusive_wait+0x7f/0x7f > [ 1320.927524] [<ffffffffa006a5e1>] ? hub_port_debounce+0xcf/0xcf [usbcore] > [ 1320.927526] [<ffffffff8105a909>] ? kthread+0x81/0x89 > [ 1320.927528] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c > [ 1320.927530] [<ffffffff813a75fc>] ? ret_from_fork+0x7c/0xb0 > [ 1320.927532] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c Your usb device has disconnected and gone down the device removal/invalidate partition route. and it's trying to flush the device, which is stuck on IO completion which is stuck waiting for the device error handling to error them out. So, this is a block device problem error handling problem caused by device unplug getting stuck because it's decided to ask the filesystem to complete operations that can't be completed until the device error handling progress far enough to error out the IOs that the filesystem is waiting for completion on. Cheers, Dave. -- Dave Chinner david@fromorbit.com _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: XFS crash? 2014-03-05 23:35 ` Dave Chinner @ 2014-03-06 0:53 ` Austin Schuh 2014-05-13 1:29 ` Austin Schuh 0 siblings, 1 reply; 30+ messages in thread From: Austin Schuh @ 2014-03-06 0:53 UTC (permalink / raw) To: Dave Chinner; +Cc: xfs Hi Dave, On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner <david@fromorbit.com> wrote: > On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote: >> Howdy, >> >> I'm running a config_preempt_rt patched version of the 3.10.11 kernel, >> and I'm seeing a couple lockups and crashes which I think are related >> to XFS. > > I think they ar emore likely related to RT issues.... > That very well may be true. > Your usb device has disconnected and gone down the device > removal/invalidate partition route. and it's trying to flush the > device, which is stuck on IO completion which is stuck waiting for > the device error handling to error them out. > > So, this is a block device problem error handling problem caused by > device unplug getting stuck because it's decided to ask the > filesystem to complete operations that can't be completed until the > device error handling progress far enough to error out the IOs that > the filesystem is waiting for completion on. > > Cheers, > > Dave. > -- > Dave Chinner > david@fromorbit.com I unplugged the USB device _after_ the rest of the system started locking up to see if that might unstick things. Austin _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: XFS crash? 2014-03-06 0:53 ` Austin Schuh @ 2014-05-13 1:29 ` Austin Schuh 2014-05-13 3:10 ` Austin Schuh ` (2 more replies) 0 siblings, 3 replies; 30+ messages in thread From: Austin Schuh @ 2014-05-13 1:29 UTC (permalink / raw) To: Dave Chinner; +Cc: xfs On Wed, Mar 5, 2014 at 4:53 PM, Austin Schuh <austin@peloton-tech.com> wrote: > Hi Dave, > > On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner <david@fromorbit.com> wrote: >> On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote: >>> Howdy, >>> >>> I'm running a config_preempt_rt patched version of the 3.10.11 kernel, >>> and I'm seeing a couple lockups and crashes which I think are related >>> to XFS. >> >> I think they ar emore likely related to RT issues.... >> > > That very well may be true. > >> Your usb device has disconnected and gone down the device >> removal/invalidate partition route. and it's trying to flush the >> device, which is stuck on IO completion which is stuck waiting for >> the device error handling to error them out. >> >> So, this is a block device problem error handling problem caused by >> device unplug getting stuck because it's decided to ask the >> filesystem to complete operations that can't be completed until the >> device error handling progress far enough to error out the IOs that >> the filesystem is waiting for completion on. >> >> Cheers, >> >> Dave. >> -- >> Dave Chinner >> david@fromorbit.com I had the issue reproduce itself today with just the main SSD installed. This was on a new machine that was built this morning. There is a lot less going on in this trace than the previous one. [ 360.448156] INFO: task kworker/1:1:42 blocked for more than 120 seconds. [ 360.450266] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 360.452404] kworker/1:1 D ffff88042e0e2cc0 0 42 2 0x00000000 [ 360.452429] Workqueue: xfs-data/sda5 xfs_end_io [xfs] [ 360.452432] ffff88042af38000 0000000000000046 0000000000000000 ffff88042b0cece0 [ 360.452433] 0000000000062cc0 ffff88042af1ffd8 0000000000062cc0 ffff88042af1ffd8 [ 360.452435] 0000000000062cc0 ffff88042af38000 ffff8803eac3be40 0000000000000002 [ 360.452437] Call Trace: [ 360.452443] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 360.452445] [<ffffffff813a2438>] ? __rt_mutex_slowlock+0x7b/0xb4 [ 360.452447] [<ffffffff813a2577>] ? rt_mutex_slowlock+0xe5/0x150 [ 360.452455] [<ffffffffa0099adb>] ? xfs_setfilesize+0x48/0x120 [xfs] [ 360.452462] [<ffffffffa009a62f>] ? xfs_end_io+0x7a/0x8e [xfs] [ 360.452465] [<ffffffff81055a49>] ? process_one_work+0x19b/0x2b2 [ 360.452468] [<ffffffff81055f41>] ? worker_thread+0x12b/0x1f6 [ 360.452469] [<ffffffff81055e16>] ? rescuer_thread+0x28f/0x28f [ 360.452471] [<ffffffff8105a909>] ? kthread+0x81/0x89 [ 360.452473] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 360.452475] [<ffffffff813a75fc>] ? ret_from_fork+0x7c/0xb0 [ 360.452477] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 360.452483] INFO: task kworker/u16:4:222 blocked for more than 120 seconds. [ 360.454614] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 360.456801] kworker/u16:4 D ffff88042e062cc0 0 222 2 0x00000000 [ 360.456807] Workqueue: writeback bdi_writeback_workfn (flush-8:0) [ 360.456810] ffff88042af3cb60 0000000000000046 ffff8804292a0000 ffffffff81616400 [ 360.456812] 0000000000062cc0 ffff8804292a1fd8 0000000000062cc0 ffff8804292a1fd8 [ 360.456813] ffff8804292a1978 ffff88042af3cb60 ffff88042af3cb60 ffff8804292a1a50 [ 360.456815] Call Trace: [ 360.456819] [<ffffffff810cc034>] ? __lock_page+0x66/0x66 [ 360.456822] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 360.456824] [<ffffffff813a1ff9>] ? io_schedule+0x55/0x6b [ 360.456825] [<ffffffff810cc03a>] ? sleep_on_page+0x6/0xa [ 360.456827] [<ffffffff813a137a>] ? __wait_on_bit_lock+0x3c/0x85 [ 360.456829] [<ffffffff810cc4a4>] ? find_get_pages_tag+0xfa/0x125 [ 360.456831] [<ffffffff810cc02f>] ? __lock_page+0x61/0x66 [ 360.456833] [<ffffffff8105b333>] ? autoremove_wake_function+0x2a/0x2a [ 360.456835] [<ffffffff810d4700>] ? write_cache_pages+0x177/0x302 [ 360.456836] [<ffffffff810d3d07>] ? page_index+0x14/0x14 [ 360.456838] [<ffffffff810d48c6>] ? generic_writepages+0x3b/0x57 [ 360.456840] [<ffffffff81134698>] ? __writeback_single_inode+0x72/0x225 [ 360.456842] [<ffffffff8113550b>] ? writeback_sb_inodes+0x215/0x36d [ 360.456844] [<ffffffff811356cc>] ? __writeback_inodes_wb+0x69/0xab [ 360.456846] [<ffffffff81135844>] ? wb_writeback+0x136/0x2a7 [ 360.456848] [<ffffffff81135c88>] ? wb_do_writeback+0x161/0x1dc [ 360.456851] [<ffffffff81135d66>] ? bdi_writeback_workfn+0x63/0xf4 [ 360.456852] [<ffffffff81055a49>] ? process_one_work+0x19b/0x2b2 [ 360.456854] [<ffffffff81055f41>] ? worker_thread+0x12b/0x1f6 [ 360.456856] [<ffffffff81055e16>] ? rescuer_thread+0x28f/0x28f [ 360.456857] [<ffffffff8105a909>] ? kthread+0x81/0x89 [ 360.456859] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 360.456860] [<ffffffff813a75fc>] ? ret_from_fork+0x7c/0xb0 [ 360.456862] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 360.456881] INFO: task dpkg:5140 blocked for more than 120 seconds. [ 360.459062] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 360.461283] dpkg D ffff88042e0e2cc0 0 5140 5112 0x00000000 [ 360.461287] ffff8804290d2180 0000000000000086 000000000000020c ffff88042af38000 [ 360.461289] 0000000000062cc0 ffff880429bf7fd8 0000000000062cc0 ffff880429bf7fd8 [ 360.461290] ffff880429bf78e8 ffff8804290d2180 ffff880429bf7a10 ffff880429bf7a08 [ 360.461292] Call Trace: [ 360.461296] [<ffffffff813a10ef>] ? console_conditional_schedule+0xf/0xf [ 360.461298] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 360.461299] [<ffffffff813a111b>] ? schedule_timeout+0x2c/0x123 [ 360.461301] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 [ 360.461303] [<ffffffff81065cfd>] ? migrate_enable+0x1cd/0x1dd [ 360.461306] [<ffffffff810651ab>] ? get_parent_ip+0x9/0x1b [ 360.461308] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 [ 360.461310] [<ffffffff813a188b>] ? __wait_for_common+0x78/0xd6 [ 360.461323] [<ffffffffa00c0032>] ? xfs_bmapi_allocate+0x92/0x9e [xfs] [ 360.461333] [<ffffffffa00c035d>] ? xfs_bmapi_write+0x31f/0x558 [xfs] [ 360.461336] [<ffffffff81109680>] ? kmem_cache_alloc+0x7c/0x17d [ 360.461346] [<ffffffffa00bde6e>] ? __xfs_bmapi_allocate+0x22b/0x22b [xfs] [ 360.461354] [<ffffffffa00a6899>] ? xfs_iomap_write_allocate+0x1bc/0x2c8 [xfs] [ 360.461362] [<ffffffffa0099dc5>] ? xfs_map_blocks+0x125/0x1f5 [xfs] [ 360.461369] [<ffffffffa009ac87>] ? xfs_vm_writepage+0x266/0x48f [xfs] [ 360.461371] [<ffffffff810d3d14>] ? __writepage+0xd/0x2a [ 360.461372] [<ffffffff810d4790>] ? write_cache_pages+0x207/0x302 [ 360.461374] [<ffffffff810d3d07>] ? page_index+0x14/0x14 [ 360.461376] [<ffffffff810d48c6>] ? generic_writepages+0x3b/0x57 [ 360.461378] [<ffffffff810cd303>] ? __filemap_fdatawrite_range+0x50/0x55 [ 360.461380] [<ffffffff81138a63>] ? SyS_sync_file_range+0xe2/0x127 [ 360.461382] [<ffffffff813a76a9>] ? system_call_fastpath+0x16/0x1b Austin _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: XFS crash? 2014-05-13 1:29 ` Austin Schuh @ 2014-05-13 3:10 ` Austin Schuh 2014-05-13 3:33 ` Austin Schuh 2014-05-13 3:46 ` Dave Chinner 2 siblings, 0 replies; 30+ messages in thread From: Austin Schuh @ 2014-05-13 3:10 UTC (permalink / raw) To: Dave Chinner; +Cc: xfs On Mon, May 12, 2014 at 6:29 PM, Austin Schuh <austin@peloton-tech.com> wrote: > On Wed, Mar 5, 2014 at 4:53 PM, Austin Schuh <austin@peloton-tech.com> wrote: >> Hi Dave, >> >> On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner <david@fromorbit.com> wrote: >>> On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote: >>>> Howdy, >>>> >>>> I'm running a config_preempt_rt patched version of the 3.10.11 kernel, >>>> and I'm seeing a couple lockups and crashes which I think are related >>>> to XFS. >>> >>> I think they ar emore likely related to RT issues.... >>> >> >> That very well may be true. >> >>> Your usb device has disconnected and gone down the device >>> removal/invalidate partition route. and it's trying to flush the >>> device, which is stuck on IO completion which is stuck waiting for >>> the device error handling to error them out. >>> >>> So, this is a block device problem error handling problem caused by >>> device unplug getting stuck because it's decided to ask the >>> filesystem to complete operations that can't be completed until the >>> device error handling progress far enough to error out the IOs that >>> the filesystem is waiting for completion on. >>> >>> Cheers, >>> >>> Dave. >>> -- >>> Dave Chinner >>> david@fromorbit.com > > I had the issue reproduce itself today with just the main SSD > installed. This was on a new machine that was built this morning. > There is a lot less going on in this trace than the previous one. > > [ 360.448156] INFO: task kworker/1:1:42 blocked for more than 120 seconds. > [ 360.450266] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 360.452404] kworker/1:1 D ffff88042e0e2cc0 0 42 2 0x00000000 > [ 360.452429] Workqueue: xfs-data/sda5 xfs_end_io [xfs] > [ 360.452432] ffff88042af38000 0000000000000046 0000000000000000 > ffff88042b0cece0 > [ 360.452433] 0000000000062cc0 ffff88042af1ffd8 0000000000062cc0 > ffff88042af1ffd8 > [ 360.452435] 0000000000062cc0 ffff88042af38000 ffff8803eac3be40 > 0000000000000002 > [ 360.452437] Call Trace: > [ 360.452443] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c > [ 360.452445] [<ffffffff813a2438>] ? __rt_mutex_slowlock+0x7b/0xb4 > [ 360.452447] [<ffffffff813a2577>] ? rt_mutex_slowlock+0xe5/0x150 > [ 360.452455] [<ffffffffa0099adb>] ? xfs_setfilesize+0x48/0x120 [xfs] > [ 360.452462] [<ffffffffa009a62f>] ? xfs_end_io+0x7a/0x8e [xfs] > [ 360.452465] [<ffffffff81055a49>] ? process_one_work+0x19b/0x2b2 > [ 360.452468] [<ffffffff81055f41>] ? worker_thread+0x12b/0x1f6 > [ 360.452469] [<ffffffff81055e16>] ? rescuer_thread+0x28f/0x28f > [ 360.452471] [<ffffffff8105a909>] ? kthread+0x81/0x89 > [ 360.452473] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c > [ 360.452475] [<ffffffff813a75fc>] ? ret_from_fork+0x7c/0xb0 > [ 360.452477] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c > [ 360.452483] INFO: task kworker/u16:4:222 blocked for more than 120 seconds. > [ 360.454614] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 360.456801] kworker/u16:4 D ffff88042e062cc0 0 222 2 0x00000000 > [ 360.456807] Workqueue: writeback bdi_writeback_workfn (flush-8:0) > [ 360.456810] ffff88042af3cb60 0000000000000046 ffff8804292a0000 > ffffffff81616400 > [ 360.456812] 0000000000062cc0 ffff8804292a1fd8 0000000000062cc0 > ffff8804292a1fd8 > [ 360.456813] ffff8804292a1978 ffff88042af3cb60 ffff88042af3cb60 > ffff8804292a1a50 > [ 360.456815] Call Trace: > [ 360.456819] [<ffffffff810cc034>] ? __lock_page+0x66/0x66 > [ 360.456822] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c > [ 360.456824] [<ffffffff813a1ff9>] ? io_schedule+0x55/0x6b > [ 360.456825] [<ffffffff810cc03a>] ? sleep_on_page+0x6/0xa > [ 360.456827] [<ffffffff813a137a>] ? __wait_on_bit_lock+0x3c/0x85 > [ 360.456829] [<ffffffff810cc4a4>] ? find_get_pages_tag+0xfa/0x125 > [ 360.456831] [<ffffffff810cc02f>] ? __lock_page+0x61/0x66 > [ 360.456833] [<ffffffff8105b333>] ? autoremove_wake_function+0x2a/0x2a > [ 360.456835] [<ffffffff810d4700>] ? write_cache_pages+0x177/0x302 > [ 360.456836] [<ffffffff810d3d07>] ? page_index+0x14/0x14 > [ 360.456838] [<ffffffff810d48c6>] ? generic_writepages+0x3b/0x57 > [ 360.456840] [<ffffffff81134698>] ? __writeback_single_inode+0x72/0x225 > [ 360.456842] [<ffffffff8113550b>] ? writeback_sb_inodes+0x215/0x36d > [ 360.456844] [<ffffffff811356cc>] ? __writeback_inodes_wb+0x69/0xab > [ 360.456846] [<ffffffff81135844>] ? wb_writeback+0x136/0x2a7 > [ 360.456848] [<ffffffff81135c88>] ? wb_do_writeback+0x161/0x1dc > [ 360.456851] [<ffffffff81135d66>] ? bdi_writeback_workfn+0x63/0xf4 > [ 360.456852] [<ffffffff81055a49>] ? process_one_work+0x19b/0x2b2 > [ 360.456854] [<ffffffff81055f41>] ? worker_thread+0x12b/0x1f6 > [ 360.456856] [<ffffffff81055e16>] ? rescuer_thread+0x28f/0x28f > [ 360.456857] [<ffffffff8105a909>] ? kthread+0x81/0x89 > [ 360.456859] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c > [ 360.456860] [<ffffffff813a75fc>] ? ret_from_fork+0x7c/0xb0 > [ 360.456862] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c > [ 360.456881] INFO: task dpkg:5140 blocked for more than 120 seconds. > [ 360.459062] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 360.461283] dpkg D ffff88042e0e2cc0 0 5140 5112 0x00000000 > [ 360.461287] ffff8804290d2180 0000000000000086 000000000000020c > ffff88042af38000 > [ 360.461289] 0000000000062cc0 ffff880429bf7fd8 0000000000062cc0 > ffff880429bf7fd8 > [ 360.461290] ffff880429bf78e8 ffff8804290d2180 ffff880429bf7a10 > ffff880429bf7a08 > [ 360.461292] Call Trace: > [ 360.461296] [<ffffffff813a10ef>] ? console_conditional_schedule+0xf/0xf > [ 360.461298] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c > [ 360.461299] [<ffffffff813a111b>] ? schedule_timeout+0x2c/0x123 > [ 360.461301] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 > [ 360.461303] [<ffffffff81065cfd>] ? migrate_enable+0x1cd/0x1dd > [ 360.461306] [<ffffffff810651ab>] ? get_parent_ip+0x9/0x1b > [ 360.461308] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 > [ 360.461310] [<ffffffff813a188b>] ? __wait_for_common+0x78/0xd6 > [ 360.461323] [<ffffffffa00c0032>] ? xfs_bmapi_allocate+0x92/0x9e [xfs] > [ 360.461333] [<ffffffffa00c035d>] ? xfs_bmapi_write+0x31f/0x558 [xfs] > [ 360.461336] [<ffffffff81109680>] ? kmem_cache_alloc+0x7c/0x17d > [ 360.461346] [<ffffffffa00bde6e>] ? __xfs_bmapi_allocate+0x22b/0x22b [xfs] > [ 360.461354] [<ffffffffa00a6899>] ? > xfs_iomap_write_allocate+0x1bc/0x2c8 [xfs] > [ 360.461362] [<ffffffffa0099dc5>] ? xfs_map_blocks+0x125/0x1f5 [xfs] > [ 360.461369] [<ffffffffa009ac87>] ? xfs_vm_writepage+0x266/0x48f [xfs] > [ 360.461371] [<ffffffff810d3d14>] ? __writepage+0xd/0x2a > [ 360.461372] [<ffffffff810d4790>] ? write_cache_pages+0x207/0x302 > [ 360.461374] [<ffffffff810d3d07>] ? page_index+0x14/0x14 > [ 360.461376] [<ffffffff810d48c6>] ? generic_writepages+0x3b/0x57 > [ 360.461378] [<ffffffff810cd303>] ? __filemap_fdatawrite_range+0x50/0x55 > [ 360.461380] [<ffffffff81138a63>] ? SyS_sync_file_range+0xe2/0x127 > [ 360.461382] [<ffffffff813a76a9>] ? system_call_fastpath+0x16/0x1b > > Austin Fun times... I rebooted the machine (had to power cycle it to get it to go down), repeated the same set of commands and it locked up again. I ran apt-get update; dpkg --configure -a; apt-get update; apt-get upgrade, and then it locked up during the upgrade. It was in the middle of unpacking a 348 MB package. [ 241.634377] INFO: task kworker/1:2:60 blocked for more than 120 seconds. [ 241.641284] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 241.648252] kworker/1:2 D ffff880429ed10c0 0 60 2 0x00000000 [ 241.648310] Workqueue: xfs-data/sda5 xfs_end_io [xfs] [ 241.648320] ffff880429ed10c0 0000000000000046 ffffffffffffffff ffff8804240053c0 [ 241.648327] 0000000000062cc0 ffff880429f4dfd8 0000000000062cc0 ffff880429f4dfd8 [ 241.648331] 0000000000000001 ffff880429ed10c0 ffff8803eb87dac0 0000000000000002 [ 241.648339] Call Trace: [ 241.648358] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 241.648365] [<ffffffff813a2438>] ? __rt_mutex_slowlock+0x7b/0xb4 [ 241.648371] [<ffffffff813a2577>] ? rt_mutex_slowlock+0xe5/0x150 [ 241.648380] [<ffffffff8100c02f>] ? load_TLS+0x7/0xa [ 241.648415] [<ffffffffa00a9adb>] ? xfs_setfilesize+0x48/0x120 [xfs] [ 241.648423] [<ffffffff81063d25>] ? finish_task_switch+0x80/0xc6 [ 241.648447] [<ffffffffa00aa62f>] ? xfs_end_io+0x7a/0x8e [xfs] [ 241.648455] [<ffffffff81055a49>] ? process_one_work+0x19b/0x2b2 [ 241.648462] [<ffffffff81055f41>] ? worker_thread+0x12b/0x1f6 [ 241.648468] [<ffffffff81055e16>] ? rescuer_thread+0x28f/0x28f [ 241.648473] [<ffffffff8105a909>] ? kthread+0x81/0x89 [ 241.648481] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 241.648487] [<ffffffff813a75fc>] ? ret_from_fork+0x7c/0xb0 [ 241.648492] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 241.648531] INFO: task dpkg:5181 blocked for more than 120 seconds. [ 241.655649] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 241.662711] dpkg D ffff88042e0e2cc0 0 5181 5153 0x00000000 [ 241.662727] ffff8804240053c0 0000000000000086 0000000000000018 ffff88042b0cece0 [ 241.662731] 0000000000062cc0 ffff88042989dfd8 0000000000062cc0 ffff88042989dfd8 [ 241.662735] ffff88042989d8e8 ffff8804240053c0 ffff88042989da10 ffff88042989da08 [ 241.662742] Call Trace: [ 241.662754] [<ffffffff813a10ef>] ? console_conditional_schedule+0xf/0xf [ 241.662760] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 241.662767] [<ffffffff813a111b>] ? schedule_timeout+0x2c/0x123 [ 241.662772] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 [ 241.662777] [<ffffffff81065cfd>] ? migrate_enable+0x1cd/0x1dd [ 241.662786] [<ffffffff810651ab>] ? get_parent_ip+0x9/0x1b [ 241.662791] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 [ 241.662797] [<ffffffff813a188b>] ? __wait_for_common+0x78/0xd6 [ 241.662845] [<ffffffffa00d0032>] ? xfs_bmapi_allocate+0x92/0x9e [xfs] [ 241.662878] [<ffffffffa00d035d>] ? xfs_bmapi_write+0x31f/0x558 [xfs] [ 241.662884] [<ffffffff81063d25>] ? finish_task_switch+0x80/0xc6 [ 241.662924] [<ffffffffa00cde6e>] ? __xfs_bmapi_allocate+0x22b/0x22b [xfs] [ 241.662950] [<ffffffffa00b6899>] ? xfs_iomap_write_allocate+0x1bc/0x2c8 [xfs] [ 241.662977] [<ffffffffa00a9dc5>] ? xfs_map_blocks+0x125/0x1f5 [xfs] [ 241.663001] [<ffffffffa00aac87>] ? xfs_vm_writepage+0x266/0x48f [xfs] [ 241.663010] [<ffffffff810d3d14>] ? __writepage+0xd/0x2a [ 241.663014] [<ffffffff810d4790>] ? write_cache_pages+0x207/0x302 [ 241.663018] [<ffffffff810d3d07>] ? page_index+0x14/0x14 [ 241.663025] [<ffffffff810d48c6>] ? generic_writepages+0x3b/0x57 [ 241.663034] [<ffffffff810cd303>] ? __filemap_fdatawrite_range+0x50/0x55 [ 241.663039] [<ffffffff81138a63>] ? SyS_sync_file_range+0xe2/0x127 [ 241.663047] [<ffffffff813a76a9>] ? system_call_fastpath+0x16/0x1b _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: XFS crash? 2014-05-13 1:29 ` Austin Schuh 2014-05-13 3:10 ` Austin Schuh @ 2014-05-13 3:33 ` Austin Schuh 2014-05-13 3:46 ` Dave Chinner 2 siblings, 0 replies; 30+ messages in thread From: Austin Schuh @ 2014-05-13 3:33 UTC (permalink / raw) To: Dave Chinner; +Cc: xfs On Mon, May 12, 2014 at 6:29 PM, Austin Schuh <austin@peloton-tech.com> wrote: > On Wed, Mar 5, 2014 at 4:53 PM, Austin Schuh <austin@peloton-tech.com> wrote: >> Hi Dave, >> >> On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner <david@fromorbit.com> wrote: >>> On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote: >>>> Howdy, >>>> >>>> I'm running a config_preempt_rt patched version of the 3.10.11 kernel, >>>> and I'm seeing a couple lockups and crashes which I think are related >>>> to XFS. >>> >>> I think they ar emore likely related to RT issues.... >>> >> >> That very well may be true. >> >>> Your usb device has disconnected and gone down the device >>> removal/invalidate partition route. and it's trying to flush the >>> device, which is stuck on IO completion which is stuck waiting for >>> the device error handling to error them out. >>> >>> So, this is a block device problem error handling problem caused by >>> device unplug getting stuck because it's decided to ask the >>> filesystem to complete operations that can't be completed until the >>> device error handling progress far enough to error out the IOs that >>> the filesystem is waiting for completion on. >>> >>> Cheers, >>> >>> Dave. >>> -- >>> Dave Chinner >>> david@fromorbit.com > > I had the issue reproduce itself today with just the main SSD > installed. This was on a new machine that was built this morning. > There is a lot less going on in this trace than the previous one. Fun times... I rebooted the machine (had to power cycle it to get it to go down), repeated the same set of commands and it locked up again. I ran apt-get update; dpkg --configure -a; apt-get update; apt-get upgrade, and then it locked up during the upgrade. It was in the middle of unpacking a 348 MB package. [ 241.634377] INFO: task kworker/1:2:60 blocked for more than 120 seconds. [ 241.641284] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 241.648252] kworker/1:2 D ffff880429ed10c0 0 60 2 0x00000000 [ 241.648310] Workqueue: xfs-data/sda5 xfs_end_io [xfs] [ 241.648320] ffff880429ed10c0 0000000000000046 ffffffffffffffff ffff8804240053c0 [ 241.648327] 0000000000062cc0 ffff880429f4dfd8 0000000000062cc0 ffff880429f4dfd8 [ 241.648331] 0000000000000001 ffff880429ed10c0 ffff8803eb87dac0 0000000000000002 [ 241.648339] Call Trace: [ 241.648358] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 241.648365] [<ffffffff813a2438>] ? __rt_mutex_slowlock+0x7b/0xb4 [ 241.648371] [<ffffffff813a2577>] ? rt_mutex_slowlock+0xe5/0x150 [ 241.648380] [<ffffffff8100c02f>] ? load_TLS+0x7/0xa [ 241.648415] [<ffffffffa00a9adb>] ? xfs_setfilesize+0x48/0x120 [xfs] [ 241.648423] [<ffffffff81063d25>] ? finish_task_switch+0x80/0xc6 [ 241.648447] [<ffffffffa00aa62f>] ? xfs_end_io+0x7a/0x8e [xfs] [ 241.648455] [<ffffffff81055a49>] ? process_one_work+0x19b/0x2b2 [ 241.648462] [<ffffffff81055f41>] ? worker_thread+0x12b/0x1f6 [ 241.648468] [<ffffffff81055e16>] ? rescuer_thread+0x28f/0x28f [ 241.648473] [<ffffffff8105a909>] ? kthread+0x81/0x89 [ 241.648481] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 241.648487] [<ffffffff813a75fc>] ? ret_from_fork+0x7c/0xb0 [ 241.648492] [<ffffffff8105a888>] ? __kthread_parkme+0x5c/0x5c [ 241.648531] INFO: task dpkg:5181 blocked for more than 120 seconds. [ 241.655649] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 241.662711] dpkg D ffff88042e0e2cc0 0 5181 5153 0x00000000 [ 241.662727] ffff8804240053c0 0000000000000086 0000000000000018 ffff88042b0cece0 [ 241.662731] 0000000000062cc0 ffff88042989dfd8 0000000000062cc0 ffff88042989dfd8 [ 241.662735] ffff88042989d8e8 ffff8804240053c0 ffff88042989da10 ffff88042989da08 [ 241.662742] Call Trace: [ 241.662754] [<ffffffff813a10ef>] ? console_conditional_schedule+0xf/0xf [ 241.662760] [<ffffffff813a1f93>] ? schedule+0x6b/0x7c [ 241.662767] [<ffffffff813a111b>] ? schedule_timeout+0x2c/0x123 [ 241.662772] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 [ 241.662777] [<ffffffff81065cfd>] ? migrate_enable+0x1cd/0x1dd [ 241.662786] [<ffffffff810651ab>] ? get_parent_ip+0x9/0x1b [ 241.662791] [<ffffffff813a5c20>] ? add_preempt_count+0xb7/0xe0 [ 241.662797] [<ffffffff813a188b>] ? __wait_for_common+0x78/0xd6 [ 241.662845] [<ffffffffa00d0032>] ? xfs_bmapi_allocate+0x92/0x9e [xfs] [ 241.662878] [<ffffffffa00d035d>] ? xfs_bmapi_write+0x31f/0x558 [xfs] [ 241.662884] [<ffffffff81063d25>] ? finish_task_switch+0x80/0xc6 [ 241.662924] [<ffffffffa00cde6e>] ? __xfs_bmapi_allocate+0x22b/0x22b [xfs] [ 241.662950] [<ffffffffa00b6899>] ? xfs_iomap_write_allocate+0x1bc/0x2c8 [xfs] [ 241.662977] [<ffffffffa00a9dc5>] ? xfs_map_blocks+0x125/0x1f5 [xfs] [ 241.663001] [<ffffffffa00aac87>] ? xfs_vm_writepage+0x266/0x48f [xfs] [ 241.663010] [<ffffffff810d3d14>] ? __writepage+0xd/0x2a [ 241.663014] [<ffffffff810d4790>] ? write_cache_pages+0x207/0x302 [ 241.663018] [<ffffffff810d3d07>] ? page_index+0x14/0x14 [ 241.663025] [<ffffffff810d48c6>] ? generic_writepages+0x3b/0x57 [ 241.663034] [<ffffffff810cd303>] ? __filemap_fdatawrite_range+0x50/0x55 [ 241.663039] [<ffffffff81138a63>] ? SyS_sync_file_range+0xe2/0x127 [ 241.663047] [<ffffffff813a76a9>] ? system_call_fastpath+0x16/0x1b _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: XFS crash? 2014-05-13 1:29 ` Austin Schuh 2014-05-13 3:10 ` Austin Schuh 2014-05-13 3:33 ` Austin Schuh @ 2014-05-13 3:46 ` Dave Chinner 2014-05-13 4:03 ` Austin Schuh 2 siblings, 1 reply; 30+ messages in thread From: Dave Chinner @ 2014-05-13 3:46 UTC (permalink / raw) To: Austin Schuh; +Cc: xfs On Mon, May 12, 2014 at 06:29:28PM -0700, Austin Schuh wrote: > On Wed, Mar 5, 2014 at 4:53 PM, Austin Schuh <austin@peloton-tech.com> wrote: > > Hi Dave, > > > > On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner <david@fromorbit.com> wrote: > >> On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote: > >>> Howdy, > >>> > >>> I'm running a config_preempt_rt patched version of the 3.10.11 kernel, > >>> and I'm seeing a couple lockups and crashes which I think are related > >>> to XFS. > >> > >> I think they ar emore likely related to RT issues.... > >> > > > > That very well may be true. > > > >> Your usb device has disconnected and gone down the device > >> removal/invalidate partition route. and it's trying to flush the > >> device, which is stuck on IO completion which is stuck waiting for > >> the device error handling to error them out. > >> > >> So, this is a block device problem error handling problem caused by > >> device unplug getting stuck because it's decided to ask the > >> filesystem to complete operations that can't be completed until the > >> device error handling progress far enough to error out the IOs that > >> the filesystem is waiting for completion on. > >> > >> Cheers, > >> > >> Dave. > >> -- > >> Dave Chinner > >> david@fromorbit.com > > I had the issue reproduce itself today with just the main SSD > installed. This was on a new machine that was built this morning. > There is a lot less going on in this trace than the previous one. The three blocked threads: 1. kworker running IO completion waiting on an inode lock, holding locked pages. 2. kworker running writeback flusher work waiting for a page lock 3. direct flush work waiting for allocation, holding page locks and the inode lock. What's the kworker thread running the allocation work doing? You might need to run `echo w > proc-sysrq-trigger` to get this information... Cheers, Dave. -- Dave Chinner david@fromorbit.com _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: XFS crash? 2014-05-13 3:46 ` Dave Chinner @ 2014-05-13 4:03 ` Austin Schuh 2014-05-13 6:39 ` Dave Chinner 0 siblings, 1 reply; 30+ messages in thread From: Austin Schuh @ 2014-05-13 4:03 UTC (permalink / raw) To: Dave Chinner; +Cc: xfs [-- Attachment #1: Type: text/plain, Size: 2284 bytes --] On Mon, May 12, 2014 at 8:46 PM, Dave Chinner <david@fromorbit.com> wrote: > On Mon, May 12, 2014 at 06:29:28PM -0700, Austin Schuh wrote: >> On Wed, Mar 5, 2014 at 4:53 PM, Austin Schuh <austin@peloton-tech.com> wrote: >> > Hi Dave, >> > >> > On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner <david@fromorbit.com> wrote: >> >> On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote: >> >>> Howdy, >> >>> >> >>> I'm running a config_preempt_rt patched version of the 3.10.11 kernel, >> >>> and I'm seeing a couple lockups and crashes which I think are related >> >>> to XFS. >> >> >> >> I think they ar emore likely related to RT issues.... >> >> >> > >> > That very well may be true. >> > >> >> Your usb device has disconnected and gone down the device >> >> removal/invalidate partition route. and it's trying to flush the >> >> device, which is stuck on IO completion which is stuck waiting for >> >> the device error handling to error them out. >> >> >> >> So, this is a block device problem error handling problem caused by >> >> device unplug getting stuck because it's decided to ask the >> >> filesystem to complete operations that can't be completed until the >> >> device error handling progress far enough to error out the IOs that >> >> the filesystem is waiting for completion on. >> >> >> >> Cheers, >> >> >> >> Dave. >> >> -- >> >> Dave Chinner >> >> david@fromorbit.com >> >> I had the issue reproduce itself today with just the main SSD >> installed. This was on a new machine that was built this morning. >> There is a lot less going on in this trace than the previous one. > > The three blocked threads: > > 1. kworker running IO completion waiting on an inode lock, > holding locked pages. > 2. kworker running writeback flusher work waiting for a page lock > 3. direct flush work waiting for allocation, holding page > locks and the inode lock. > > What's the kworker thread running the allocation work doing? > > You might need to run `echo w > proc-sysrq-trigger` to get this > information... I was able to reproduce the lockup. I ran `echo w > /proc/sysrq-trigger` per your suggestion. I don't know how to figure out what the kworker thread is doing, but I'll happily do it if you can give me some guidance. [-- Attachment #2: dmesg --] [-- Type: application/octet-stream, Size: 33300 bytes --] [ 1250.199560] SysRq : Show Blocked State [ 1250.199772] task PC stack pid father [ 1250.199798] kworker/3:1 D ffff88042dbe1e40 0 91 2 0x00000000 [ 1250.199820] Workqueue: xfs-data/sda5 xfs_end_io [ 1250.199824] ffff88041a8d70f0 0000000000000002 ffff88041af96840 0000000000000000 [ 1250.199827] 0000000000061e40 ffff8804195ddfd8 0000000000061e40 ffff8804195ddfd8 [ 1250.199836] 0000000000000400 ffff88041a8d70f0 ffff880357bb2b40 0000000000000002 [ 1250.199839] Call Trace: [ 1250.199847] [<ffffffff8147a22f>] ? schedule+0x70/0x81 [ 1250.199848] [<ffffffff8147a738>] ? __rt_mutex_slowlock+0x80/0xb9 [ 1250.199850] [<ffffffff8147a886>] ? rt_mutex_slowlock+0xea/0x155 [ 1250.199852] [<ffffffff811996dd>] ? xfs_setfilesize+0x4d/0x125 [ 1250.199856] [<ffffffff8105ab1e>] ? finish_task_switch+0x60/0xac [ 1250.199857] [<ffffffff8119a338>] ? xfs_end_io+0x7f/0x93 [ 1250.199860] [<ffffffff8104bb96>] ? process_one_work+0x1a0/0x2b7 [ 1250.199862] [<ffffffff8104c09b>] ? worker_thread+0x130/0x1fb [ 1250.199864] [<ffffffff8104bf6b>] ? rescuer_thread+0x294/0x294 [ 1250.199865] [<ffffffff81050e74>] ? kthread+0x86/0x8e [ 1250.199867] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1250.199870] [<ffffffff8147ffdc>] ? ret_from_fork+0x7c/0xb0 [ 1250.199872] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1250.199881] kworker/2:1 D ffff88042db61e40 0 196 2 0x00000000 [ 1250.199894] Workqueue: xfs-data/sda5 xfs_end_io [ 1250.199898] ffff8804182c0000 0000000000000002 ffff88041a964580 ffff880357bb2af8 [ 1250.199899] 0000000000061e40 ffff8804182c9fd8 0000000000061e40 ffff8804182c9fd8 [ 1250.199905] 0000000000000000 ffff8804182c0000 ffff880357bb2b40 0000000000000002 [ 1250.199907] Call Trace: [ 1250.199911] [<ffffffff8147a22f>] ? schedule+0x70/0x81 [ 1250.199913] [<ffffffff8147a738>] ? __rt_mutex_slowlock+0x80/0xb9 [ 1250.199914] [<ffffffff8147a886>] ? rt_mutex_slowlock+0xea/0x155 [ 1250.199916] [<ffffffff811996dd>] ? xfs_setfilesize+0x4d/0x125 [ 1250.199918] [<ffffffff8105ab1e>] ? finish_task_switch+0x60/0xac [ 1250.199920] [<ffffffff8119a338>] ? xfs_end_io+0x7f/0x93 [ 1250.199921] [<ffffffff8104bb96>] ? process_one_work+0x1a0/0x2b7 [ 1250.199923] [<ffffffff8104c09b>] ? worker_thread+0x130/0x1fb [ 1250.199925] [<ffffffff8104bf6b>] ? rescuer_thread+0x294/0x294 [ 1250.199927] [<ffffffff81050e74>] ? kthread+0x86/0x8e [ 1250.199928] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1250.199930] [<ffffffff8147ffdc>] ? ret_from_fork+0x7c/0xb0 [ 1250.199932] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1250.199939] kworker/u16:5 D ffff88042db61e40 0 247 2 0x00000000 [ 1250.199970] Workqueue: writeback bdi_writeback_workfn (flush-8:0) [ 1250.199979] ffff88041a964580 0000000000000002 ffff88041af95f90 ffff88041803f628 [ 1250.199980] 0000000000061e40 ffff88041803ffd8 0000000000061e40 ffff88041803ffd8 [ 1250.199982] ffff88041803f638 ffff88041a964580 ffff88041803f760 ffff88041803f758 [ 1250.199990] Call Trace: [ 1250.199993] [<ffffffff81479302>] ? console_conditional_schedule+0x1a/0x1a [ 1250.199996] [<ffffffff8147a22f>] ? schedule+0x70/0x81 [ 1250.199998] [<ffffffff81479333>] ? schedule_timeout+0x31/0x128 [ 1250.200000] [<ffffffff8147e115>] ? add_preempt_count+0xbc/0xe5 [ 1250.200001] [<ffffffff8105cb3f>] ? migrate_enable+0x1d3/0x1e3 [ 1250.200003] [<ffffffff8105c244>] ? get_parent_ip+0x9/0x1b [ 1250.200004] [<ffffffff8147e115>] ? add_preempt_count+0xbc/0xe5 [ 1250.200006] [<ffffffff81479b11>] ? __wait_for_common+0x78/0xd6 [ 1250.200009] [<ffffffff811c06ce>] ? xfs_bmapi_allocate+0x97/0xa3 [ 1250.200011] [<ffffffff811c09fe>] ? xfs_bmapi_write+0x324/0x55d [ 1250.200013] [<ffffffff81102a7e>] ? kmem_cache_alloc+0x81/0x182 [ 1250.200021] [<ffffffff811be490>] ? __xfs_bmapi_allocate+0x230/0x230 [ 1250.200023] [<ffffffff811a6956>] ? xfs_iomap_write_allocate+0x1c1/0x2cd [ 1250.200026] [<ffffffff811999d8>] ? xfs_map_blocks+0x12a/0x1fa [ 1250.200027] [<ffffffff8119a9af>] ? xfs_vm_writepage+0x26b/0x494 [ 1250.200031] [<ffffffff810ce259>] ? __writepage+0x12/0x2f [ 1250.200034] [<ffffffff810cecd4>] ? write_cache_pages+0x20c/0x307 [ 1250.200036] [<ffffffff810ce247>] ? page_index+0x14/0x14 [ 1250.200038] [<ffffffff810cee0f>] ? generic_writepages+0x40/0x5c [ 1250.200040] [<ffffffff8112feb9>] ? __writeback_single_inode+0x77/0x22b [ 1250.200042] [<ffffffff81131039>] ? writeback_sb_inodes+0x21a/0x372 [ 1250.200045] [<ffffffff8113136f>] ? wb_writeback+0x12e/0x2ac [ 1250.200047] [<ffffffff811316f8>] ? wb_do_writeback+0x7e/0x1e1 [ 1250.200049] [<ffffffff8104d699>] ? set_worker_desc+0x66/0x71 [ 1250.200051] [<ffffffff811318c4>] ? bdi_writeback_workfn+0x69/0xfa [ 1250.200053] [<ffffffff8104bb96>] ? process_one_work+0x1a0/0x2b7 [ 1250.200055] [<ffffffff8104c09b>] ? worker_thread+0x130/0x1fb [ 1250.200057] [<ffffffff8104bf6b>] ? rescuer_thread+0x294/0x294 [ 1250.200058] [<ffffffff81050e74>] ? kthread+0x86/0x8e [ 1250.200060] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1250.200062] [<ffffffff8147ffdc>] ? ret_from_fork+0x7c/0xb0 [ 1250.200063] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1250.200070] xfsaild/sda5 D ffff88042da61e40 0 301 2 0x00000000 [ 1250.200117] ffff8804194fdf90 0000000000000002 ffffffff81813400 ffff8804197bfdb0 [ 1250.200118] 0000000000061e40 ffff8804197bffd8 0000000000061e40 ffff8804197bffd8 [ 1250.200119] ffff8804197bfe00 ffff8804194fdf90 0000000000000001 ffff8804182ed140 [ 1250.200127] Call Trace: [ 1250.200130] [<ffffffff8147a22f>] ? schedule+0x70/0x81 [ 1250.200132] [<ffffffff814793f2>] ? schedule_timeout+0xf0/0x128 [ 1250.200135] [<ffffffff8103f6d3>] ? ftrace_raw_event_timer_class+0x9d/0x9d [ 1250.200138] [<ffffffff811ec032>] ? xfsaild+0xcf/0x51e [ 1250.200140] [<ffffffff811ebf63>] ? xfs_trans_ail_cursor_first+0x7d/0x7d [ 1250.200142] [<ffffffff81050e74>] ? kthread+0x86/0x8e [ 1250.200143] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1250.200145] [<ffffffff8147ffdc>] ? ret_from_fork+0x7c/0xb0 [ 1250.200147] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1250.200179] shutdown D ffff88042dbe1e40 0 8686 6726 0x00000000 [ 1250.200196] ffff8804195bc580 0000000000000002 ffff88041af96840 0000000000000000 [ 1250.200197] 0000000000061e40 ffff8803ef239fd8 0000000000061e40 ffff8803ef239fd8 [ 1250.200203] ffff88041a964bc8 ffff8804195bc580 ffff8803ef239eb0 ffff8803ef239ea8 [ 1250.200205] Call Trace: [ 1250.200208] [<ffffffff81479302>] ? console_conditional_schedule+0x1a/0x1a [ 1250.200211] [<ffffffff8147a22f>] ? schedule+0x70/0x81 [ 1250.200213] [<ffffffff81479333>] ? schedule_timeout+0x31/0x128 [ 1250.200214] [<ffffffff8105c244>] ? get_parent_ip+0x9/0x1b [ 1250.200215] [<ffffffff8105c244>] ? get_parent_ip+0x9/0x1b [ 1250.200217] [<ffffffff8147e115>] ? add_preempt_count+0xbc/0xe5 [ 1250.200219] [<ffffffff81479b11>] ? __wait_for_common+0x78/0xd6 [ 1250.200221] [<ffffffff81130d09>] ? sync_inodes_sb+0xb2/0x1c8 [ 1250.200224] [<ffffffff8113438c>] ? fdatawrite_one_bdev+0x14/0x14 [ 1250.200226] [<ffffffff81112ea0>] ? iterate_supers+0x72/0xcd [ 1250.200228] [<ffffffff811344f0>] ? sys_sync+0x33/0x86 [ 1250.200230] [<ffffffff8148027d>] ? tracesys+0xdd/0xe2 [ 1250.200244] Sched Debug Version: v0.10, 3.10.24-rt22abs #1 [ 1250.200257] ktime : 1248567.801938 [ 1250.200259] sched_clk : 1250200.243781 [ 1250.200260] cpu_clk : 1250200.243828 [ 1250.200267] jiffies : 4295915864 [ 1250.200269] sched_clock_stable : 1 [ 1250.200270] [ 1250.200271] sysctl_sched [ 1250.200278] .sysctl_sched_latency : 18.000000 [ 1250.200279] .sysctl_sched_min_granularity : 2.250000 [ 1250.200280] .sysctl_sched_wakeup_granularity : 3.000000 [ 1250.200281] .sysctl_sched_child_runs_first : 0 [ 1250.200288] .sysctl_sched_features : 22139 [ 1250.200290] .sysctl_sched_tunable_scaling : 1 (logaritmic) [ 1250.200292] [ 1250.200309] cpu#0, 2194.795 MHz [ 1250.200310] .nr_running : 0 [ 1250.200312] .load : 0 [ 1250.200313] .nr_switches : 16832676 [ 1250.200315] .nr_load_updates : 1248568 [ 1250.200317] .nr_uninterruptible : 37 [ 1250.200318] .next_balance : 4295.915872 [ 1250.200326] .curr->pid : 0 [ 1250.200328] .clock : 1250199.449420 [ 1250.200329] .cpu_load[0] : 0 [ 1250.200337] .cpu_load[1] : 0 [ 1250.200338] .cpu_load[2] : 0 [ 1250.200339] .cpu_load[3] : 0 [ 1250.200340] .cpu_load[4] : 0 [ 1250.200349] [ 1250.200349] cfs_rq[0]:/autogroup-187 [ 1250.200350] .exec_clock : 0.000000 [ 1250.200352] .MIN_vruntime : 0.000001 [ 1250.200359] .min_vruntime : 17.683521 [ 1250.200360] .max_vruntime : 0.000001 [ 1250.200362] .spread : 0.000000 [ 1250.200380] .spread0 : -45523.266692 [ 1250.200381] .nr_spread_over : 0 [ 1250.200383] .nr_running : 0 [ 1250.200384] .load : 0 [ 1250.200385] .runnable_load_avg : 0 [ 1250.200387] .blocked_load_avg : 2 [ 1250.200399] .tg_load_avg : 2 [ 1250.200400] .tg_load_contrib : 2 [ 1250.200401] .tg_runnable_contrib : 2 [ 1250.200402] .tg->runnable_avg : 2 [ 1250.200403] .se->exec_start : 1250199.360813 [ 1250.200405] .se->vruntime : 45532.111840 [ 1250.200412] .se->sum_exec_runtime : 18.732097 [ 1250.200413] .se->load.weight : 2 [ 1250.200414] .se->avg.runnable_avg_sum : 107 [ 1250.200415] .se->avg.runnable_avg_period : 47150 [ 1250.200422] .se->avg.load_avg_contrib : 1 [ 1250.200423] .se->avg.decay_count : 1192284 [ 1250.200425] [ 1250.200425] cfs_rq[0]:/autogroup-23 [ 1250.200432] .exec_clock : 0.000000 [ 1250.200434] .MIN_vruntime : 0.000001 [ 1250.200435] .min_vruntime : 7909.675864 [ 1250.200437] .max_vruntime : 0.000001 [ 1250.200464] .spread : 0.000000 [ 1250.200466] .spread0 : -37631.274349 [ 1250.200468] .nr_spread_over : 0 [ 1250.200469] .nr_running : 0 [ 1250.200479] .load : 0 [ 1250.200491] .runnable_load_avg : 0 [ 1250.200501] .blocked_load_avg : 0 [ 1250.200514] .tg_load_avg : 0 [ 1250.200516] .tg_load_contrib : 0 [ 1250.200517] .tg_runnable_contrib : 0 [ 1250.200518] .tg->runnable_avg : 0 [ 1250.200520] .se->exec_start : 1250193.745232 [ 1250.200521] .se->vruntime : 45534.164663 [ 1250.200523] .se->sum_exec_runtime : 5352.648881 [ 1250.200524] .se->load.weight : 2 [ 1250.200525] .se->avg.runnable_avg_sum : 8 [ 1250.200527] .se->avg.runnable_avg_period : 47624 [ 1250.200541] .se->avg.load_avg_contrib : 0 [ 1250.200543] .se->avg.decay_count : 1192278 [ 1250.200551] [ 1250.200551] cfs_rq[0]:/ [ 1250.200552] .exec_clock : 0.000000 [ 1250.200553] .MIN_vruntime : 0.000001 [ 1250.200555] .min_vruntime : 45540.950213 [ 1250.200561] .max_vruntime : 0.000001 [ 1250.200562] .spread : 0.000000 [ 1250.200564] .spread0 : 0.000000 [ 1250.200565] .nr_spread_over : 0 [ 1250.200566] .nr_running : 1 [ 1250.200575] .load : 1024 [ 1250.200577] .runnable_load_avg : 0 [ 1250.200578] .blocked_load_avg : 0 [ 1250.200599] .tg_load_avg : 0 [ 1250.200601] .tg_load_contrib : 0 [ 1250.200602] .tg_runnable_contrib : 30 [ 1250.200603] .tg->runnable_avg : 1230 [ 1250.200604] .avg->runnable_avg_sum : 1367 [ 1250.200605] .avg->runnable_avg_period : 46273 [ 1250.200607] [ 1250.200607] rt_rq[0]: [ 1250.200615] .rt_nr_running : 0 [ 1250.200616] .rt_throttled : 0 [ 1250.200618] .rt_time : 96.917503 [ 1250.200626] .rt_runtime : 950.000000 [ 1250.200627] .rt_nr_migratory : 0 [ 1250.200629] [ 1250.200629] runnable tasks: [ 1250.200629] task PID tree-key switches prio exec-runtime sum-exec sum-sleep [ 1250.200629] ---------------------------------------------------------------------------------------------------------- [ 1250.200675] R rsyslogd 6368 18.253322 19 120 0 0 0.000000 0.000000 0.000000 /autogroup-167 [ 1250.200698] [ 1250.200699] cpu#1, 2194.795 MHz [ 1250.200707] .nr_running : 2 [ 1250.200709] .load : 2048 [ 1250.200710] .nr_switches : 40655522 [ 1250.200711] .nr_load_updates : 1231168 [ 1250.200721] .nr_uninterruptible : 46 [ 1250.200722] .next_balance : 4295.915866 [ 1250.200724] .curr->pid : 2015 [ 1250.200725] .clock : 1250200.715602 [ 1250.200726] .cpu_load[0] : 0 [ 1250.200727] .cpu_load[1] : 0 [ 1250.200729] .cpu_load[2] : 0 [ 1250.200730] .cpu_load[3] : 0 [ 1250.200732] .cpu_load[4] : 0 [ 1250.200743] [ 1250.200743] cfs_rq[1]:/autogroup-183 [ 1250.200745] .exec_clock : 0.000000 [ 1250.200755] .MIN_vruntime : 0.000001 [ 1250.200756] .min_vruntime : 0.616862 [ 1250.200758] .max_vruntime : 0.000001 [ 1250.200765] .spread : 0.000000 [ 1250.200767] .spread0 : -45540.333351 [ 1250.200768] .nr_spread_over : 0 [ 1250.200770] .nr_running : 1 [ 1250.200778] .load : 1024 [ 1250.200779] .runnable_load_avg : 0 [ 1250.200780] .blocked_load_avg : 0 [ 1250.200789] .tg_load_avg : 0 [ 1250.200790] .tg_load_contrib : 0 [ 1250.200791] .tg_runnable_contrib : 0 [ 1250.200793] .tg->runnable_avg : 0 [ 1250.200794] .se->exec_start : 1250200.777722 [ 1250.200796] .se->vruntime : 36158.952186 [ 1250.200797] .se->sum_exec_runtime : 1.696888 [ 1250.200798] .se->load.weight : 2 [ 1250.200799] .se->avg.runnable_avg_sum : 73 [ 1250.200801] .se->avg.runnable_avg_period : 48632 [ 1250.200802] .se->avg.load_avg_contrib : 0 [ 1250.200804] .se->avg.decay_count : 1192285 [ 1250.200814] [ 1250.200814] cfs_rq[1]:/autogroup-167 [ 1250.200816] .exec_clock : 0.000000 [ 1250.200818] .MIN_vruntime : 58.228650 [ 1250.200819] .min_vruntime : 58.228650 [ 1250.200827] .max_vruntime : 58.228650 [ 1250.200828] .spread : 0.000000 [ 1250.200830] .spread0 : -45482.721563 [ 1250.200831] .nr_spread_over : 0 [ 1250.200850] .nr_running : 1 [ 1250.200852] .load : 1024 [ 1250.200854] .runnable_load_avg : 0 [ 1250.200856] .blocked_load_avg : 0 [ 1250.200857] .tg_load_avg : 0 [ 1250.200877] .tg_load_contrib : 0 [ 1250.200878] .tg_runnable_contrib : 0 [ 1250.200879] .tg->runnable_avg : 0 [ 1250.200880] .se->exec_start : 1250200.853999 [ 1250.200882] .se->vruntime : 36159.054504 [ 1250.200883] .se->sum_exec_runtime : 17.862348 [ 1250.200901] .se->load.weight : 1024 [ 1250.200912] .se->avg.runnable_avg_sum : 274 [ 1250.200913] .se->avg.runnable_avg_period : 48740 [ 1250.200914] .se->avg.load_avg_contrib : 0 [ 1250.200916] .se->avg.decay_count : 1192285 [ 1250.200925] [ 1250.200925] cfs_rq[1]:/ [ 1250.200927] .exec_clock : 0.000000 [ 1250.200946] .MIN_vruntime : 36159.087569 [ 1250.200947] .min_vruntime : 36167.920736 [ 1250.200949] .max_vruntime : 36159.087569 [ 1250.200950] .spread : 0.000000 [ 1250.200951] .spread0 : -9373.029477 [ 1250.200959] .nr_spread_over : 0 [ 1250.200961] .nr_running : 1 [ 1250.200962] .load : 1024 [ 1250.200963] .runnable_load_avg : 0 [ 1250.200971] .blocked_load_avg : 0 [ 1250.200973] .tg_load_avg : 0 [ 1250.200974] .tg_load_contrib : 0 [ 1250.200981] .tg_runnable_contrib : 445 [ 1250.200983] .tg->runnable_avg : 1247 [ 1250.200986] .avg->runnable_avg_sum : 20193 [ 1250.200993] .avg->runnable_avg_period : 46452 [ 1250.200995] [ 1250.200995] rt_rq[1]: [ 1250.200997] .rt_nr_running : 1 [ 1250.200999] .rt_throttled : 0 [ 1250.201000] .rt_time : 201.849919 [ 1250.201031] .rt_runtime : 950.000000 [ 1250.201032] .rt_nr_migratory : 1 [ 1250.201034] [ 1250.201034] runnable tasks: [ 1250.201034] task PID tree-key switches prio exec-runtime sum-exec sum-sleep [ 1250.201034] ---------------------------------------------------------------------------------------------------------- [ 1250.201071] R irq/18-can1 2015 0.000000 17472905 49 0 0 0.000000 0.000000 0.000000 / [ 1250.201082] rs:main Q:Reg 6366 58.343361 757 120 0 0 0.000000 0.000000 0.000000 /autogroup-167 [ 1250.201100] [ 1250.201108] cpu#2, 2194.795 MHz [ 1250.201109] .nr_running : 0 [ 1250.201111] .load : 0 [ 1250.201119] .nr_switches : 74339322 [ 1250.201120] .nr_load_updates : 1289248 [ 1250.201122] .nr_uninterruptible : -139 [ 1250.201130] .next_balance : 4295.915866 [ 1250.201131] .curr->pid : 0 [ 1250.201133] .clock : 1250201.079957 [ 1250.201148] .cpu_load[0] : 0 [ 1250.201149] .cpu_load[1] : 0 [ 1250.201150] .cpu_load[2] : 0 [ 1250.201151] .cpu_load[3] : 0 [ 1250.201162] .cpu_load[4] : 0 [ 1250.201164] [ 1250.201164] cfs_rq[2]:/autogroup-23 [ 1250.201166] .exec_clock : 0.000000 [ 1250.201174] .MIN_vruntime : 0.000001 [ 1250.201176] .min_vruntime : 3636.083046 [ 1250.201177] .max_vruntime : 0.000001 [ 1250.201186] .spread : 0.000000 [ 1250.201191] .spread0 : -41904.867167 [ 1250.201200] .nr_spread_over : 0 [ 1250.201202] .nr_running : 0 [ 1250.201204] .load : 0 [ 1250.201237] .runnable_load_avg : 0 [ 1250.201239] .blocked_load_avg : 0 [ 1250.201241] .tg_load_avg : 0 [ 1250.201242] .tg_load_contrib : 0 [ 1250.201244] .tg_runnable_contrib : 0 [ 1250.201245] .tg->runnable_avg : 0 [ 1250.201247] .se->exec_start : 1250123.293600 [ 1250.201248] .se->vruntime : 44269.300196 [ 1250.201250] .se->sum_exec_runtime : 2291.524471 [ 1250.201252] .se->load.weight : 2 [ 1250.201254] .se->avg.runnable_avg_sum : 15 [ 1250.201256] .se->avg.runnable_avg_period : 47514 [ 1250.201258] .se->avg.load_avg_contrib : 0 [ 1250.201259] .se->avg.decay_count : 1192211 [ 1250.201260] [ 1250.201260] cfs_rq[2]:/ [ 1250.201262] .exec_clock : 0.000000 [ 1250.201264] .MIN_vruntime : 0.000001 [ 1250.201266] .min_vruntime : 44278.083100 [ 1250.201268] .max_vruntime : 0.000001 [ 1250.201269] .spread : 0.000000 [ 1250.201271] .spread0 : -1262.867113 [ 1250.201272] .nr_spread_over : 0 [ 1250.201274] .nr_running : 0 [ 1250.201295] .load : 0 [ 1250.201296] .runnable_load_avg : 0 [ 1250.201297] .blocked_load_avg : 0 [ 1250.201299] .tg_load_avg : 0 [ 1250.201301] .tg_load_contrib : 0 [ 1250.201302] .tg_runnable_contrib : 302 [ 1250.201303] .tg->runnable_avg : 1252 [ 1250.201304] .avg->runnable_avg_sum : 13644 [ 1250.201306] .avg->runnable_avg_period : 46555 [ 1250.201307] [ 1250.201307] rt_rq[2]: [ 1250.201308] .rt_nr_running : 0 [ 1250.201310] .rt_throttled : 0 [ 1250.201311] .rt_time : 173.402316 [ 1250.201313] .rt_runtime : 950.000000 [ 1250.201315] .rt_nr_migratory : 0 [ 1250.201316] [ 1250.201316] runnable tasks: [ 1250.201316] task PID tree-key switches prio exec-runtime sum-exec sum-sleep [ 1250.201316] ---------------------------------------------------------------------------------------------------------- [ 1250.201337] [ 1250.201339] cpu#3, 2194.795 MHz [ 1250.201341] .nr_running : 1 [ 1250.201342] .load : 1024 [ 1250.201344] .nr_switches : 102749194 [ 1250.201345] .nr_load_updates : 1287421 [ 1250.201363] .nr_uninterruptible : 61 [ 1250.201365] .next_balance : 4295.915885 [ 1250.201366] .curr->pid : 8718 [ 1250.201367] .clock : 1250201.361690 [ 1250.201368] .cpu_load[0] : 1024 [ 1250.201369] .cpu_load[1] : 768 [ 1250.201371] .cpu_load[2] : 448 [ 1250.201372] .cpu_load[3] : 240 [ 1250.201374] .cpu_load[4] : 124 [ 1250.201376] [ 1250.201376] cfs_rq[3]:/autogroup-188 [ 1250.201378] .exec_clock : 0.000000 [ 1250.201379] .MIN_vruntime : 0.000001 [ 1250.201381] .min_vruntime : 398.623639 [ 1250.201382] .max_vruntime : 0.000001 [ 1250.201384] .spread : 0.000000 [ 1250.201385] .spread0 : -45142.326574 [ 1250.201386] .nr_spread_over : 0 [ 1250.201388] .nr_running : 1 [ 1250.201390] .load : 1024 [ 1250.201391] .runnable_load_avg : 22 [ 1250.201392] .blocked_load_avg : 0 [ 1250.201393] .tg_load_avg : 0 [ 1250.201395] .tg_load_contrib : 0 [ 1250.201396] .tg_runnable_contrib : 23 [ 1250.201398] .tg->runnable_avg : 23 [ 1250.201400] .se->exec_start : 1250201.361690 [ 1250.201401] .se->vruntime : 53370.693519 [ 1250.201402] .se->sum_exec_runtime : 83.378026 [ 1250.201404] .se->load.weight : 1024 [ 1250.201405] .se->avg.runnable_avg_sum : 1940 [ 1250.201406] .se->avg.runnable_avg_period : 47013 [ 1250.201408] .se->avg.load_avg_contrib : 0 [ 1250.201409] .se->avg.decay_count : 0 [ 1250.201411] [ 1250.201411] cfs_rq[3]:/ [ 1250.201413] .exec_clock : 0.000000 [ 1250.201414] .MIN_vruntime : 0.000001 [ 1250.201415] .min_vruntime : 53370.693519 [ 1250.201433] .max_vruntime : 0.000001 [ 1250.201435] .spread : 0.000000 [ 1250.201437] .spread0 : 7829.743306 [ 1250.201438] .nr_spread_over : 0 [ 1250.201439] .nr_running : 1 [ 1250.201440] .load : 1024 [ 1250.201441] .runnable_load_avg : 0 [ 1250.201442] .blocked_load_avg : 0 [ 1250.201455] .tg_load_avg : 42 [ 1250.201457] .tg_load_contrib : 42 [ 1250.201459] .tg_runnable_contrib : 488 [ 1250.201461] .tg->runnable_avg : 1285 [ 1250.201462] .avg->runnable_avg_sum : 22203 [ 1250.201463] .avg->runnable_avg_period : 46581 [ 1250.201464] [ 1250.201464] rt_rq[3]: [ 1250.201466] .rt_nr_running : 0 [ 1250.201467] .rt_throttled : 0 [ 1250.201468] .rt_time : 221.302805 [ 1250.201470] .rt_runtime : 950.000000 [ 1250.201471] .rt_nr_migratory : 0 [ 1250.201473] [ 1250.201473] runnable tasks: [ 1250.201473] task PID tree-key switches prio exec-runtime sum-exec sum-sleep [ 1250.201473] ---------------------------------------------------------------------------------------------------------- [ 1250.201510] R bash 8718 398.728001 6342 120 0 0 0.000000 0.000000 0.000000 /autogroup-188 [ 1250.201516] [ 1322.381902] INFO: task kworker/3:1:91 blocked for more than 120 seconds. [ 1322.382075] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1322.382220] kworker/3:1 D ffff88042dbe1e40 0 91 2 0x00000000 [ 1322.382235] Workqueue: xfs-data/sda5 xfs_end_io [ 1322.382245] ffff88041a8d70f0 0000000000000002 ffff88041af96840 0000000000000000 [ 1322.382249] 0000000000061e40 ffff8804195ddfd8 0000000000061e40 ffff8804195ddfd8 [ 1322.382262] 0000000000000400 ffff88041a8d70f0 ffff880357bb2b40 0000000000000002 [ 1322.382265] Call Trace: [ 1322.382273] [<ffffffff8147a22f>] ? schedule+0x70/0x81 [ 1322.382276] [<ffffffff8147a738>] ? __rt_mutex_slowlock+0x80/0xb9 [ 1322.382277] [<ffffffff8147a886>] ? rt_mutex_slowlock+0xea/0x155 [ 1322.382280] [<ffffffff811996dd>] ? xfs_setfilesize+0x4d/0x125 [ 1322.382283] [<ffffffff8105ab1e>] ? finish_task_switch+0x60/0xac [ 1322.382285] [<ffffffff8119a338>] ? xfs_end_io+0x7f/0x93 [ 1322.382288] [<ffffffff8104bb96>] ? process_one_work+0x1a0/0x2b7 [ 1322.382290] [<ffffffff8104c09b>] ? worker_thread+0x130/0x1fb [ 1322.382291] [<ffffffff8104bf6b>] ? rescuer_thread+0x294/0x294 [ 1322.382293] [<ffffffff81050e74>] ? kthread+0x86/0x8e [ 1322.382295] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1322.382298] [<ffffffff8147ffdc>] ? ret_from_fork+0x7c/0xb0 [ 1322.382299] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1322.382306] INFO: task kworker/2:1:196 blocked for more than 120 seconds. [ 1322.382503] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1322.382649] kworker/2:1 D ffff88042db61e40 0 196 2 0x00000000 [ 1322.382653] Workqueue: xfs-data/sda5 xfs_end_io [ 1322.382661] ffff8804182c0000 0000000000000002 ffff88041a964580 ffff880357bb2af8 [ 1322.382663] 0000000000061e40 ffff8804182c9fd8 0000000000061e40 ffff8804182c9fd8 [ 1322.382672] 0000000000000000 ffff8804182c0000 ffff880357bb2b40 0000000000000002 [ 1322.382678] Call Trace: [ 1322.382682] [<ffffffff8147a22f>] ? schedule+0x70/0x81 [ 1322.382683] [<ffffffff8147a738>] ? __rt_mutex_slowlock+0x80/0xb9 [ 1322.382689] [<ffffffff8147a886>] ? rt_mutex_slowlock+0xea/0x155 [ 1322.382691] [<ffffffff811996dd>] ? xfs_setfilesize+0x4d/0x125 [ 1322.382693] [<ffffffff8105ab1e>] ? finish_task_switch+0x60/0xac [ 1322.382694] [<ffffffff8119a338>] ? xfs_end_io+0x7f/0x93 [ 1322.382696] [<ffffffff8104bb96>] ? process_one_work+0x1a0/0x2b7 [ 1322.382698] [<ffffffff8104c09b>] ? worker_thread+0x130/0x1fb [ 1322.382700] [<ffffffff8104bf6b>] ? rescuer_thread+0x294/0x294 [ 1322.382701] [<ffffffff81050e74>] ? kthread+0x86/0x8e [ 1322.382703] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1322.382705] [<ffffffff8147ffdc>] ? ret_from_fork+0x7c/0xb0 [ 1322.382707] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1322.382714] INFO: task kworker/u16:5:247 blocked for more than 120 seconds. [ 1322.382864] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1322.383034] kworker/u16:5 D ffff88042db61e40 0 247 2 0x00000000 [ 1322.383052] Workqueue: writeback bdi_writeback_workfn (flush-8:0) [ 1322.383067] ffff88041a964580 0000000000000002 ffff88041af95f90 ffff88041803f628 [ 1322.383072] 0000000000061e40 ffff88041803ffd8 0000000000061e40 ffff88041803ffd8 [ 1322.383702] ffff88041803f638 ffff88041a964580 ffff88041803f760 ffff88041803f758 [ 1322.383707] Call Trace: [ 1322.383715] [<ffffffff81479302>] ? console_conditional_schedule+0x1a/0x1a [ 1322.383728] [<ffffffff8147a22f>] ? schedule+0x70/0x81 [ 1322.383743] [<ffffffff81479333>] ? schedule_timeout+0x31/0x128 [ 1322.383746] [<ffffffff8147e115>] ? add_preempt_count+0xbc/0xe5 [ 1322.383748] [<ffffffff8105cb3f>] ? migrate_enable+0x1d3/0x1e3 [ 1322.383750] [<ffffffff8105c244>] ? get_parent_ip+0x9/0x1b [ 1322.383752] [<ffffffff8147e115>] ? add_preempt_count+0xbc/0xe5 [ 1322.383755] [<ffffffff81479b11>] ? __wait_for_common+0x78/0xd6 [ 1322.383758] [<ffffffff811c06ce>] ? xfs_bmapi_allocate+0x97/0xa3 [ 1322.383760] [<ffffffff811c09fe>] ? xfs_bmapi_write+0x324/0x55d [ 1322.383763] [<ffffffff81102a7e>] ? kmem_cache_alloc+0x81/0x182 [ 1322.383767] [<ffffffff811be490>] ? __xfs_bmapi_allocate+0x230/0x230 [ 1322.383769] [<ffffffff811a6956>] ? xfs_iomap_write_allocate+0x1c1/0x2cd [ 1322.383772] [<ffffffff811999d8>] ? xfs_map_blocks+0x12a/0x1fa [ 1322.383774] [<ffffffff8119a9af>] ? xfs_vm_writepage+0x26b/0x494 [ 1322.383778] [<ffffffff810ce259>] ? __writepage+0x12/0x2f [ 1322.383780] [<ffffffff810cecd4>] ? write_cache_pages+0x20c/0x307 [ 1322.383781] [<ffffffff810ce247>] ? page_index+0x14/0x14 [ 1322.383784] [<ffffffff810cee0f>] ? generic_writepages+0x40/0x5c [ 1322.383788] [<ffffffff8112feb9>] ? __writeback_single_inode+0x77/0x22b [ 1322.383790] [<ffffffff81131039>] ? writeback_sb_inodes+0x21a/0x372 [ 1322.383792] [<ffffffff8113136f>] ? wb_writeback+0x12e/0x2ac [ 1322.383795] [<ffffffff811316f8>] ? wb_do_writeback+0x7e/0x1e1 [ 1322.383798] [<ffffffff8104d699>] ? set_worker_desc+0x66/0x71 [ 1322.383801] [<ffffffff811318c4>] ? bdi_writeback_workfn+0x69/0xfa [ 1322.383803] [<ffffffff8104bb96>] ? process_one_work+0x1a0/0x2b7 [ 1322.383805] [<ffffffff8104c09b>] ? worker_thread+0x130/0x1fb [ 1322.383807] [<ffffffff8104bf6b>] ? rescuer_thread+0x294/0x294 [ 1322.383809] [<ffffffff81050e74>] ? kthread+0x86/0x8e [ 1322.383811] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1322.383814] [<ffffffff8147ffdc>] ? ret_from_fork+0x7c/0xb0 [ 1322.383816] [<ffffffff81050dee>] ? __kthread_parkme+0x60/0x60 [ 1322.383859] INFO: task shutdown:8686 blocked for more than 120 seconds. [ 1322.384186] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1322.384346] shutdown D ffff88042dbe1e40 0 8686 6726 0x00000000 [ 1322.384394] ffff8804195bc580 0000000000000002 ffff88041af96840 0000000000000000 [ 1322.384396] 0000000000061e40 ffff8803ef239fd8 0000000000061e40 ffff8803ef239fd8 [ 1322.384399] ffff88041a964bc8 ffff8804195bc580 ffff8803ef239eb0 ffff8803ef239ea8 [ 1322.384403] Call Trace: [ 1322.384409] [<ffffffff81479302>] ? console_conditional_schedule+0x1a/0x1a [ 1322.384411] [<ffffffff8147a22f>] ? schedule+0x70/0x81 [ 1322.384414] [<ffffffff81479333>] ? schedule_timeout+0x31/0x128 [ 1322.384417] [<ffffffff8105c244>] ? get_parent_ip+0x9/0x1b [ 1322.384425] [<ffffffff8105c244>] ? get_parent_ip+0x9/0x1b [ 1322.384435] [<ffffffff8147e115>] ? add_preempt_count+0xbc/0xe5 [ 1322.384438] [<ffffffff81479b11>] ? __wait_for_common+0x78/0xd6 [ 1322.384441] [<ffffffff81130d09>] ? sync_inodes_sb+0xb2/0x1c8 [ 1322.384444] [<ffffffff8113438c>] ? fdatawrite_one_bdev+0x14/0x14 [ 1322.384447] [<ffffffff81112ea0>] ? iterate_supers+0x72/0xcd [ 1322.384449] [<ffffffff811344f0>] ? sys_sync+0x33/0x86 [ 1322.384452] [<ffffffff8148027d>] ? tracesys+0xdd/0xe2 [-- Attachment #3: Type: text/plain, Size: 121 bytes --] _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: XFS crash? 2014-05-13 4:03 ` Austin Schuh @ 2014-05-13 6:39 ` Dave Chinner 2014-05-13 7:02 ` Austin Schuh 0 siblings, 1 reply; 30+ messages in thread From: Dave Chinner @ 2014-05-13 6:39 UTC (permalink / raw) To: Austin Schuh; +Cc: xfs On Mon, May 12, 2014 at 09:03:48PM -0700, Austin Schuh wrote: > On Mon, May 12, 2014 at 8:46 PM, Dave Chinner <david@fromorbit.com> wrote: > > On Mon, May 12, 2014 at 06:29:28PM -0700, Austin Schuh wrote: > >> On Wed, Mar 5, 2014 at 4:53 PM, Austin Schuh <austin@peloton-tech.com> wrote: > >> > Hi Dave, > >> > > >> > On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner <david@fromorbit.com> wrote: > >> >> On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote: > >> >>> Howdy, > >> >>> > >> >>> I'm running a config_preempt_rt patched version of the 3.10.11 kernel, > >> >>> and I'm seeing a couple lockups and crashes which I think are related > >> >>> to XFS. > >> >> > >> >> I think they ar emore likely related to RT issues.... > >> >> > >> > > >> > That very well may be true. > >> > > >> >> Your usb device has disconnected and gone down the device > >> >> removal/invalidate partition route. and it's trying to flush the > >> >> device, which is stuck on IO completion which is stuck waiting for > >> >> the device error handling to error them out. > >> >> > >> >> So, this is a block device problem error handling problem caused by > >> >> device unplug getting stuck because it's decided to ask the > >> >> filesystem to complete operations that can't be completed until the > >> >> device error handling progress far enough to error out the IOs that > >> >> the filesystem is waiting for completion on. > >> >> > >> >> Cheers, > >> >> > >> >> Dave. > >> >> -- > >> >> Dave Chinner > >> >> david@fromorbit.com > >> > >> I had the issue reproduce itself today with just the main SSD > >> installed. This was on a new machine that was built this morning. > >> There is a lot less going on in this trace than the previous one. > > > > The three blocked threads: > > > > 1. kworker running IO completion waiting on an inode lock, > > holding locked pages. > > 2. kworker running writeback flusher work waiting for a page lock > > 3. direct flush work waiting for allocation, holding page > > locks and the inode lock. > > > > What's the kworker thread running the allocation work doing? > > > > You might need to run `echo w > proc-sysrq-trigger` to get this > > information... > > I was able to reproduce the lockup. I ran `echo w > > /proc/sysrq-trigger` per your suggestion. I don't know how to figure > out what the kworker thread is doing, but I'll happily do it if you > can give me some guidance. There isn't a worker thread blocked doing an allocation in that dump, so it doesn't shed any light on the problem at all. try `echo l > /proc/sysrq-trigger`, followed by `echo t > /proc/sysrq-trigger` so we can see all the processes running on CPUs and all the processes in the system... Cheers, Dave. -- Dave Chinner david@fromorbit.com _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: XFS crash? 2014-05-13 6:39 ` Dave Chinner @ 2014-05-13 7:02 ` Austin Schuh 2014-05-13 9:03 ` Dave Chinner 0 siblings, 1 reply; 30+ messages in thread From: Austin Schuh @ 2014-05-13 7:02 UTC (permalink / raw) To: Dave Chinner; +Cc: xfs [-- Attachment #1: Type: text/plain, Size: 2320 bytes --] On Mon, May 12, 2014 at 11:39 PM, Dave Chinner <david@fromorbit.com> wrote: > On Mon, May 12, 2014 at 09:03:48PM -0700, Austin Schuh wrote: >> On Mon, May 12, 2014 at 8:46 PM, Dave Chinner <david@fromorbit.com> wrote: >> > On Mon, May 12, 2014 at 06:29:28PM -0700, Austin Schuh wrote: >> >> On Wed, Mar 5, 2014 at 4:53 PM, Austin Schuh <austin@peloton-tech.com> wrote: >> >> > Hi Dave, >> >> > >> >> > On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner <david@fromorbit.com> wrote: >> >> >> On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote: >> >> >>> Howdy, >> >> >>> >> >> >>> I'm running a config_preempt_rt patched version of the 3.10.11 kernel, >> >> >>> and I'm seeing a couple lockups and crashes which I think are related >> >> >>> to XFS. >> >> >> >> >> >> I think they ar emore likely related to RT issues.... >> >> >> >> >> > >> >> > That very well may be true. >> >> > >> >> >> Cheers, >> >> >> >> >> >> Dave. >> >> >> -- >> >> >> Dave Chinner >> >> >> >> I had the issue reproduce itself today with just the main SSD >> >> installed. This was on a new machine that was built this morning. >> >> There is a lot less going on in this trace than the previous one. >> > >> > The three blocked threads: >> > >> > 1. kworker running IO completion waiting on an inode lock, >> > holding locked pages. >> > 2. kworker running writeback flusher work waiting for a page lock >> > 3. direct flush work waiting for allocation, holding page >> > locks and the inode lock. >> > >> > What's the kworker thread running the allocation work doing? >> > >> > You might need to run `echo w > proc-sysrq-trigger` to get this >> > information... >> >> I was able to reproduce the lockup. I ran `echo w > >> /proc/sysrq-trigger` per your suggestion. I don't know how to figure >> out what the kworker thread is doing, but I'll happily do it if you >> can give me some guidance. > > There isn't a worker thread blocked doing an allocation in that > dump, so it doesn't shed any light on the problem at all. try > `echo l > /proc/sysrq-trigger`, followed by `echo t > > /proc/sysrq-trigger` so we can see all the processes running on CPUs > and all the processes in the system... > > Cheers, > > Dave. Attached is the output of the two commands you asked for. Thanks, Austin [-- Attachment #2: sysrq_dump.bz2 --] [-- Type: application/x-bzip2, Size: 30640 bytes --] [-- Attachment #3: Type: text/plain, Size: 121 bytes --] _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: XFS crash? 2014-05-13 7:02 ` Austin Schuh @ 2014-05-13 9:03 ` Dave Chinner 2014-05-13 17:11 ` Austin Schuh 0 siblings, 1 reply; 30+ messages in thread From: Dave Chinner @ 2014-05-13 9:03 UTC (permalink / raw) To: Austin Schuh; +Cc: xfs On Tue, May 13, 2014 at 12:02:18AM -0700, Austin Schuh wrote: > On Mon, May 12, 2014 at 11:39 PM, Dave Chinner <david@fromorbit.com> wrote: > > On Mon, May 12, 2014 at 09:03:48PM -0700, Austin Schuh wrote: > >> On Mon, May 12, 2014 at 8:46 PM, Dave Chinner <david@fromorbit.com> wrote: > >> > On Mon, May 12, 2014 at 06:29:28PM -0700, Austin Schuh wrote: > >> >> On Wed, Mar 5, 2014 at 4:53 PM, Austin Schuh <austin@peloton-tech.com> wrote: > >> >> > Hi Dave, > >> >> > > >> >> > On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner <david@fromorbit.com> wrote: > >> >> >> On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote: > >> >> >>> Howdy, > >> >> >>> > >> >> >>> I'm running a config_preempt_rt patched version of the 3.10.11 kernel, > >> >> >>> and I'm seeing a couple lockups and crashes which I think are related > >> >> >>> to XFS. > >> >> >> > >> >> >> I think they ar emore likely related to RT issues.... > >> >> >> > >> >> > > >> >> > That very well may be true. > >> >> > > >> >> >> Cheers, > >> >> >> > >> >> >> Dave. > >> >> >> -- > >> >> >> Dave Chinner > >> >> > >> >> I had the issue reproduce itself today with just the main SSD > >> >> installed. This was on a new machine that was built this morning. > >> >> There is a lot less going on in this trace than the previous one. > >> > > >> > The three blocked threads: > >> > > >> > 1. kworker running IO completion waiting on an inode lock, > >> > holding locked pages. > >> > 2. kworker running writeback flusher work waiting for a page lock > >> > 3. direct flush work waiting for allocation, holding page > >> > locks and the inode lock. > >> > > >> > What's the kworker thread running the allocation work doing? > >> > > >> > You might need to run `echo w > proc-sysrq-trigger` to get this > >> > information... > >> > >> I was able to reproduce the lockup. I ran `echo w > > >> /proc/sysrq-trigger` per your suggestion. I don't know how to figure > >> out what the kworker thread is doing, but I'll happily do it if you > >> can give me some guidance. > > > > There isn't a worker thread blocked doing an allocation in that > > dump, so it doesn't shed any light on the problem at all. try > > `echo l > /proc/sysrq-trigger`, followed by `echo t > > > /proc/sysrq-trigger` so we can see all the processes running on CPUs > > and all the processes in the system... > > > > Cheers, > > > > Dave. > > Attached is the output of the two commands you asked for. Nothing there. There's lots of processes waiting for allocation to run, and no kworkers running allocation work. This looks more like a rt-kernel workqueue issue, not an XFS problem. FWIW, it woul dbe really helpful if you compiled your kernels with frame pointers enabled - the stack traces are much more precise and readable (i.e. gets rid of all the false/stale entrys) and that helps understanding where things are stuck immensely. Cheers, Dave. -- Dave Chinner david@fromorbit.com _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: XFS crash? 2014-05-13 9:03 ` Dave Chinner @ 2014-05-13 17:11 ` Austin Schuh 2014-06-23 20:05 ` Austin Schuh 0 siblings, 1 reply; 30+ messages in thread From: Austin Schuh @ 2014-05-13 17:11 UTC (permalink / raw) To: Dave Chinner; +Cc: xfs On Tue, May 13, 2014 at 2:03 AM, Dave Chinner <david@fromorbit.com> wrote: > On Tue, May 13, 2014 at 12:02:18AM -0700, Austin Schuh wrote: >> On Mon, May 12, 2014 at 11:39 PM, Dave Chinner <david@fromorbit.com> wrote: >> > On Mon, May 12, 2014 at 09:03:48PM -0700, Austin Schuh wrote: >> >> On Mon, May 12, 2014 at 8:46 PM, Dave Chinner <david@fromorbit.com> wrote: >> >> > On Mon, May 12, 2014 at 06:29:28PM -0700, Austin Schuh wrote: >> >> >> On Wed, Mar 5, 2014 at 4:53 PM, Austin Schuh <austin@peloton-tech.com> wrote: >> >> >> > Hi Dave, >> >> >> > >> >> >> > On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner <david@fromorbit.com> wrote: >> >> >> >> On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote: >> >> >> >>> Howdy, >> >> >> >>> >> >> >> >>> I'm running a config_preempt_rt patched version of the 3.10.11 kernel, >> >> >> >>> and I'm seeing a couple lockups and crashes which I think are related >> >> >> >>> to XFS. >> >> >> >> >> >> >> >> I think they ar emore likely related to RT issues.... >> >> >> >> >> >> >> > >> >> >> > That very well may be true. >> >> >> > >> >> >> >> Cheers, >> >> >> >> >> >> >> >> Dave. >> >> >> >> -- >> >> >> >> Dave Chinner >> >> >> >> >> >> I had the issue reproduce itself today with just the main SSD >> >> >> installed. This was on a new machine that was built this morning. >> >> >> There is a lot less going on in this trace than the previous one. >> >> > >> >> > The three blocked threads: >> >> > >> >> > 1. kworker running IO completion waiting on an inode lock, >> >> > holding locked pages. >> >> > 2. kworker running writeback flusher work waiting for a page lock >> >> > 3. direct flush work waiting for allocation, holding page >> >> > locks and the inode lock. >> >> > >> >> > What's the kworker thread running the allocation work doing? >> >> > >> >> > You might need to run `echo w > proc-sysrq-trigger` to get this >> >> > information... >> >> >> >> I was able to reproduce the lockup. I ran `echo w > >> >> /proc/sysrq-trigger` per your suggestion. I don't know how to figure >> >> out what the kworker thread is doing, but I'll happily do it if you >> >> can give me some guidance. >> > >> > There isn't a worker thread blocked doing an allocation in that >> > dump, so it doesn't shed any light on the problem at all. try >> > `echo l > /proc/sysrq-trigger`, followed by `echo t > >> > /proc/sysrq-trigger` so we can see all the processes running on CPUs >> > and all the processes in the system... >> > >> > Cheers, >> > >> > Dave. >> >> Attached is the output of the two commands you asked for. > > Nothing there. There's lots of processes waiting for allocation to > run, and no kworkers running allocation work. This looks more > like a rt-kernel workqueue issue, not an XFS problem. > > FWIW, it woul dbe really helpful if you compiled your kernels with > frame pointers enabled - the stack traces are much more precise and > readable (i.e. gets rid of all the false/stale entrys) and that > helps understanding where things are stuck immensely. > > Cheers, > > Dave. Thanks Dave. I'll go check with the rt-kernel guys and take it from there. Thanks for the frame pointers suggestion. I'll make that change the next time I build a kernel. Austin _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: XFS crash? 2014-05-13 17:11 ` Austin Schuh @ 2014-06-23 20:05 ` Austin Schuh 2014-06-24 3:02 ` Dave Chinner 0 siblings, 1 reply; 30+ messages in thread From: Austin Schuh @ 2014-06-23 20:05 UTC (permalink / raw) To: Dave Chinner; +Cc: xfs [-- Attachment #1.1: Type: text/plain, Size: 9223 bytes --] Hi Dave, On Tue, May 13, 2014 at 10:11 AM, Austin Schuh <austin@peloton-tech.com> wrote: > On Tue, May 13, 2014 at 2:03 AM, Dave Chinner <david@fromorbit.com> wrote: > > On Tue, May 13, 2014 at 12:02:18AM -0700, Austin Schuh wrote: > >> On Mon, May 12, 2014 at 11:39 PM, Dave Chinner <david@fromorbit.com> > wrote: > >> > On Mon, May 12, 2014 at 09:03:48PM -0700, Austin Schuh wrote: > >> >> On Mon, May 12, 2014 at 8:46 PM, Dave Chinner <david@fromorbit.com> > wrote: > >> >> > On Mon, May 12, 2014 at 06:29:28PM -0700, Austin Schuh wrote: > >> >> >> On Wed, Mar 5, 2014 at 4:53 PM, Austin Schuh < > austin@peloton-tech.com> wrote: > >> >> >> > Hi Dave, > >> >> >> > > >> >> >> > On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner < > david@fromorbit.com> wrote: > >> >> >> >> On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote: > >> >> >> >>> Howdy, > >> >> >> >>> > >> >> >> >>> I'm running a config_preempt_rt patched version of the > 3.10.11 kernel, > >> >> >> >>> and I'm seeing a couple lockups and crashes which I think are > related > >> >> >> >>> to XFS. > >> >> >> >> > >> >> >> >> I think they ar emore likely related to RT issues.... > >> >> >> >> > >> >> >> > > >> >> >> > That very well may be true. > >> >> >> > > >> >> >> >> Cheers, > >> >> >> >> > >> >> >> >> Dave. > >> >> >> >> -- > >> >> >> >> Dave Chinner > >> >> >> > >> >> >> I had the issue reproduce itself today with just the main SSD > >> >> >> installed. This was on a new machine that was built this morning. > >> >> >> There is a lot less going on in this trace than the previous one. > >> >> > > >> >> > The three blocked threads: > >> >> > > >> >> > 1. kworker running IO completion waiting on an inode lock, > >> >> > holding locked pages. > >> >> > 2. kworker running writeback flusher work waiting for a > page lock > >> >> > 3. direct flush work waiting for allocation, holding page > >> >> > locks and the inode lock. > >> >> > > >> >> > What's the kworker thread running the allocation work doing? > >> >> > > >> >> > You might need to run `echo w > proc-sysrq-trigger` to get this > >> >> > information... > >> >> > >> >> I was able to reproduce the lockup. I ran `echo w > > >> >> /proc/sysrq-trigger` per your suggestion. I don't know how to figure > >> >> out what the kworker thread is doing, but I'll happily do it if you > >> >> can give me some guidance. > >> > > >> > There isn't a worker thread blocked doing an allocation in that > >> > dump, so it doesn't shed any light on the problem at all. try > >> > `echo l > /proc/sysrq-trigger`, followed by `echo t > > >> > /proc/sysrq-trigger` so we can see all the processes running on CPUs > >> > and all the processes in the system... > >> > > >> > Cheers, > >> > > >> > Dave. > >> > >> Attached is the output of the two commands you asked for. > > > > Nothing there. There's lots of processes waiting for allocation to > > run, and no kworkers running allocation work. This looks more > > like a rt-kernel workqueue issue, not an XFS problem. > > > > FWIW, it woul dbe really helpful if you compiled your kernels with > > frame pointers enabled - the stack traces are much more precise and > > readable (i.e. gets rid of all the false/stale entrys) and that > > helps understanding where things are stuck immensely. > > > > Cheers, > > > > Dave. > > Thanks Dave. > > I'll go check with the rt-kernel guys and take it from there. Thanks > for the frame pointers suggestion. I'll make that change the next > time I build a kernel. > > Austin > I found 1 bug in XFS which I fixed, and I've uncovered something else that I'm not completely sure how to fix. In xfs_bmapi_allocate, you create a completion, and use that to wait until the work has finished. Occasionally, I'm seeing a case where I get a context switch after the completion has been completed, but before the workqueue has finished doing it's internal book-keeping. This results in the work being deleted before the workqueue is done using it, corrupting the internal data structures. I fixed it by waiting using flush_work and removing the completion entirely. --- a/fs/xfs/xfs_bmap_util.c 2014-06-23 12:59:10.008678410 -0700 +++ b/fs/xfs/xfs_bmap_util.c 2014-06-23 12:59:14.116678239 -0700 @@ -263,7 +263,6 @@ current_set_flags_nested(&pflags, PF_FSTRANS); args->result = __xfs_bmapi_allocate(args); - complete(args->done); current_restore_flags_nested(&pflags, PF_FSTRANS); } @@ -277,16 +276,13 @@ xfs_bmapi_allocate( struct xfs_bmalloca *args) { - DECLARE_COMPLETION_ONSTACK(done); - if (!args->stack_switch) return __xfs_bmapi_allocate(args); - args->done = &done; INIT_WORK_ONSTACK(&args->work, xfs_bmapi_allocate_worker); queue_work(xfs_alloc_wq, &args->work); - wait_for_completion(&done); + flush_work(&args->work); destroy_work_on_stack(&args->work); return args->result; } --- a/fs/xfs/xfs_bmap_util.h 2014-06-23 12:59:10.008678410 -0700 +++ b/fs/xfs/xfs_bmap_util.h 2014-06-23 12:59:11.708678340 -0700 @@ -57,7 +57,6 @@ char conv; /* overwriting unwritten extents */ char stack_switch; int flags; - struct completion *done; struct work_struct work; int result; }; I enabled event tracing (and added a new event which lists the number of workers running in a queue whenever that is changed). To me, it looks like work is scheduled from irq/44-ahci-273 that will acquire an inode lock. scp-3986 then acquires the lock, and then goes and schedules work. That work is then scheduled behind the work from irq/44-ahci-273 in the same pool. The first work blocks waiting on the lock, and scp-3986 won't finish and release that lock until the second work gets run. Any ideas on how to deal with this? I think we need to create a new pool to make sure that xfs_bmapi_allocate_worker gets run in a separate thread to avoid this. irq/44-ahci-273 [000] ....1.5 76.340300: workqueue_queue_work: work struct=ffff880406a6b998 function=xfs_end_io workqueue=ffff88040af82000 pool=ffff88042da63fc0 req_cpu=512 cpu=0 irq/44-ahci-273 [000] ....1.5 76.340301: workqueue_activate_work: work struct ffff880406a6b998 scp-3986 [000] ....1.. 76.342711: xfs_ilock_nowait: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_SHARED caller xfs_map_blocks scp-3986 [000] ....1.. 76.342714: xfs_iunlock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_SHARED caller xfs_map_blocks scp-3986 [000] ....1.. 76.342722: xfs_ilock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_EXCL caller xfs_iomap_write_allocate scp-3986 [000] ....1.3 76.342729: workqueue_queue_work: work struct=ffff8800a5b8d900 function=xfs_bmapi_allocate_worker workqueue=ffff88040bb36000 pool=ffff88042da63fc0 req_cpu=512 cpu=0 scp-3986 [000] ....1.3 76.342730: workqueue_activate_work: work struct ffff8800a5b8d900 scp-3986 [000] ....1.4 76.342754: workqueue_queue_work: work struct=ffff88040a6a01c8 function=blk_delay_work workqueue=ffff88040c9f4a00 pool=ffff88042da644c0 req_cpu=512 cpu=0 scp-3986 [000] ....1.4 76.342755: workqueue_activate_work: work struct ffff88040a6a01c8 kworker/0:2-757 [000] ....1.1 76.342868: workqueue_nr_running: pool=ffff88042da63fc0 nr_running=1 kworker/0:2-757 [000] ....1.. 76.342869: workqueue_execute_start: work struct ffff880406a6b998: function xfs_end_io kworker/0:2-757 [000] ....1.. 76.342870: xfs_ilock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_EXCL caller xfs_setfilesize irq/44-ahci-273 [003] ....1.5 76.419037: workqueue_queue_work: work struct=ffff8800aebc3588 function=xfs_end_io workqueue=ffff88040af82000 pool=ffff88042dbe3fc0 req_cpu=512 cpu=3 irq/44-ahci-273 [003] ....1.5 76.419038: workqueue_activate_work: work struct ffff8800aebc3588 kworker/3:1-119 [003] ....1.1 76.419105: workqueue_nr_running: pool=ffff88042dbe3fc0 nr_running=1 kworker/3:1-119 [003] ....1.. 76.419106: workqueue_execute_start: work struct ffff8800aebc3588: function xfs_end_io kworker/3:1-119 [003] ....1.. 76.419107: xfs_ilock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_EXCL caller xfs_setfilesize irq/44-ahci-273 [002] ....1.5 76.426120: workqueue_queue_work: work struct=ffff880406a6b930 function=xfs_end_io workqueue=ffff88040af82000 pool=ffff88042db63fc0 req_cpu=512 cpu=2 irq/44-ahci-273 [002] .N..1.5 76.426127: workqueue_activate_work: work struct ffff880406a6b930 kworker/2:1-72 [002] ....1.1 76.426242: workqueue_nr_running: pool=ffff88042db63fc0 nr_running=1 kworker/2:1-72 [002] ....1.. 76.426243: workqueue_execute_start: work struct ffff880406a6b930: function xfs_end_io kworker/2:1-72 [002] ....1.. 76.426244: xfs_ilock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_EXCL caller xfs_setfilesize Thanks, Austin [-- Attachment #1.2: Type: text/html, Size: 14087 bytes --] [-- Attachment #2: Type: text/plain, Size: 121 bytes --] _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* On-stack work item completion race? (was Re: XFS crash?) 2014-06-23 20:05 ` Austin Schuh @ 2014-06-24 3:02 ` Dave Chinner 0 siblings, 0 replies; 30+ messages in thread From: Dave Chinner @ 2014-06-24 3:02 UTC (permalink / raw) To: Austin Schuh; +Cc: xfs, linux-kernel, Tejun Heo [Adding Tejun and lkml to the cc list] On Mon, Jun 23, 2014 at 01:05:54PM -0700, Austin Schuh wrote: > I found 1 bug in XFS which I fixed, and I've uncovered something else that > I'm not completely sure how to fix. > > In xfs_bmapi_allocate, you create a completion, and use that to wait until > the work has finished. Occasionally, I'm seeing a case where I get a > context switch after the completion has been completed, but before the > workqueue has finished doing it's internal book-keeping. This results in > the work being deleted before the workqueue is done using it, corrupting > the internal data structures. I fixed it by waiting using flush_work and > removing the completion entirely. > > --- a/fs/xfs/xfs_bmap_util.c 2014-06-23 12:59:10.008678410 -0700 > +++ b/fs/xfs/xfs_bmap_util.c 2014-06-23 12:59:14.116678239 -0700 > @@ -263,7 +263,6 @@ > current_set_flags_nested(&pflags, PF_FSTRANS); > > args->result = __xfs_bmapi_allocate(args); > - complete(args->done); > > current_restore_flags_nested(&pflags, PF_FSTRANS); > } > @@ -277,16 +276,13 @@ > xfs_bmapi_allocate( > struct xfs_bmalloca *args) > { > - DECLARE_COMPLETION_ONSTACK(done); > - > if (!args->stack_switch) > return __xfs_bmapi_allocate(args); > > > - args->done = &done; > INIT_WORK_ONSTACK(&args->work, xfs_bmapi_allocate_worker); > queue_work(xfs_alloc_wq, &args->work); > - wait_for_completion(&done); > + flush_work(&args->work); > destroy_work_on_stack(&args->work); > return args->result; > } > --- a/fs/xfs/xfs_bmap_util.h 2014-06-23 12:59:10.008678410 -0700 > +++ b/fs/xfs/xfs_bmap_util.h 2014-06-23 12:59:11.708678340 -0700 > @@ -57,7 +57,6 @@ > char conv; /* overwriting unwritten extents */ > char stack_switch; > int flags; > - struct completion *done; > struct work_struct work; > int result; > }; Ok, that's a surprise. However, I can't see how using flush_work() solves that underlying context switch problem, because it's implemented the same way: bool flush_work(struct work_struct *work) { struct wq_barrier barr; lock_map_acquire(&work->lockdep_map); lock_map_release(&work->lockdep_map); if (start_flush_work(work, &barr)) { wait_for_completion(&barr.done); destroy_work_on_stack(&barr.work); return true; } else { return false; } } start_flush_work() is effectively a special queue_work() implementation, so if if it's not safe to call complete() from the workqueue as the above patch implies then this code has the same problem. Tejun - is this "do it yourself completion" a known issue w.r.t. workqueues? I can't find any documentation that says "don't do that" so...? A quick grep also shows up the same queue_work/wait_for_completion pattern in arch/x86/kernel/hpet.c, drivers/md/dm-thin.c, fs/fs-writeback.c, drivers/block/drbd/drbd_main.c.... > I enabled event tracing (and added a new event which lists the number of > workers running in a queue whenever that is changed). > > To me, it looks like work is scheduled from irq/44-ahci-273 that will > acquire an inode lock. scp-3986 then acquires the lock, and then goes and > schedules work. That work is then scheduled behind the work from > irq/44-ahci-273 in the same pool. The first work blocks waiting on the > lock, and scp-3986 won't finish and release that lock until the second work > gets run. IOWs, scp takes an inode lock and queues work to the xfs_alloc_wq, then schedules. Then a kworker runs an xfs-data work item, which tries to take the inode lock and blocks. As I understand it, what then happens is that the workqueue code grabs another kworker thread and runs the next work item in it's queue. IOWs, work items can block, but doing that does not prevent execution of other work items queued on other work queues or even on the same work queue. Tejun, did I get that correct? Hence the work on the xfs-data queue will block until another kworker processes the item on the xfs-alloc-wq which means progress is made and the inode gets unlocked. Then the kworker for the work on the xfs-data queue will get the lock, complete it's work and everything has resolved itself. Cheers, Dave. -- Dave Chinner david@fromorbit.com ^ permalink raw reply [flat|nested] 30+ messages in thread
* On-stack work item completion race? (was Re: XFS crash?) @ 2014-06-24 3:02 ` Dave Chinner 0 siblings, 0 replies; 30+ messages in thread From: Dave Chinner @ 2014-06-24 3:02 UTC (permalink / raw) To: Austin Schuh; +Cc: Tejun Heo, linux-kernel, xfs [Adding Tejun and lkml to the cc list] On Mon, Jun 23, 2014 at 01:05:54PM -0700, Austin Schuh wrote: > I found 1 bug in XFS which I fixed, and I've uncovered something else that > I'm not completely sure how to fix. > > In xfs_bmapi_allocate, you create a completion, and use that to wait until > the work has finished. Occasionally, I'm seeing a case where I get a > context switch after the completion has been completed, but before the > workqueue has finished doing it's internal book-keeping. This results in > the work being deleted before the workqueue is done using it, corrupting > the internal data structures. I fixed it by waiting using flush_work and > removing the completion entirely. > > --- a/fs/xfs/xfs_bmap_util.c 2014-06-23 12:59:10.008678410 -0700 > +++ b/fs/xfs/xfs_bmap_util.c 2014-06-23 12:59:14.116678239 -0700 > @@ -263,7 +263,6 @@ > current_set_flags_nested(&pflags, PF_FSTRANS); > > args->result = __xfs_bmapi_allocate(args); > - complete(args->done); > > current_restore_flags_nested(&pflags, PF_FSTRANS); > } > @@ -277,16 +276,13 @@ > xfs_bmapi_allocate( > struct xfs_bmalloca *args) > { > - DECLARE_COMPLETION_ONSTACK(done); > - > if (!args->stack_switch) > return __xfs_bmapi_allocate(args); > > > - args->done = &done; > INIT_WORK_ONSTACK(&args->work, xfs_bmapi_allocate_worker); > queue_work(xfs_alloc_wq, &args->work); > - wait_for_completion(&done); > + flush_work(&args->work); > destroy_work_on_stack(&args->work); > return args->result; > } > --- a/fs/xfs/xfs_bmap_util.h 2014-06-23 12:59:10.008678410 -0700 > +++ b/fs/xfs/xfs_bmap_util.h 2014-06-23 12:59:11.708678340 -0700 > @@ -57,7 +57,6 @@ > char conv; /* overwriting unwritten extents */ > char stack_switch; > int flags; > - struct completion *done; > struct work_struct work; > int result; > }; Ok, that's a surprise. However, I can't see how using flush_work() solves that underlying context switch problem, because it's implemented the same way: bool flush_work(struct work_struct *work) { struct wq_barrier barr; lock_map_acquire(&work->lockdep_map); lock_map_release(&work->lockdep_map); if (start_flush_work(work, &barr)) { wait_for_completion(&barr.done); destroy_work_on_stack(&barr.work); return true; } else { return false; } } start_flush_work() is effectively a special queue_work() implementation, so if if it's not safe to call complete() from the workqueue as the above patch implies then this code has the same problem. Tejun - is this "do it yourself completion" a known issue w.r.t. workqueues? I can't find any documentation that says "don't do that" so...? A quick grep also shows up the same queue_work/wait_for_completion pattern in arch/x86/kernel/hpet.c, drivers/md/dm-thin.c, fs/fs-writeback.c, drivers/block/drbd/drbd_main.c.... > I enabled event tracing (and added a new event which lists the number of > workers running in a queue whenever that is changed). > > To me, it looks like work is scheduled from irq/44-ahci-273 that will > acquire an inode lock. scp-3986 then acquires the lock, and then goes and > schedules work. That work is then scheduled behind the work from > irq/44-ahci-273 in the same pool. The first work blocks waiting on the > lock, and scp-3986 won't finish and release that lock until the second work > gets run. IOWs, scp takes an inode lock and queues work to the xfs_alloc_wq, then schedules. Then a kworker runs an xfs-data work item, which tries to take the inode lock and blocks. As I understand it, what then happens is that the workqueue code grabs another kworker thread and runs the next work item in it's queue. IOWs, work items can block, but doing that does not prevent execution of other work items queued on other work queues or even on the same work queue. Tejun, did I get that correct? Hence the work on the xfs-data queue will block until another kworker processes the item on the xfs-alloc-wq which means progress is made and the inode gets unlocked. Then the kworker for the work on the xfs-data queue will get the lock, complete it's work and everything has resolved itself. Cheers, Dave. -- Dave Chinner david@fromorbit.com _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) 2014-06-24 3:02 ` Dave Chinner @ 2014-06-24 3:25 ` Tejun Heo -1 siblings, 0 replies; 30+ messages in thread From: Tejun Heo @ 2014-06-24 3:25 UTC (permalink / raw) To: Dave Chinner; +Cc: Austin Schuh, xfs, linux-kernel Hello, On Tue, Jun 24, 2014 at 01:02:40PM +1000, Dave Chinner wrote: > start_flush_work() is effectively a special queue_work() > implementation, so if if it's not safe to call complete() from the > workqueue as the above patch implies then this code has the same > problem. > > Tejun - is this "do it yourself completion" a known issue w.r.t. > workqueues? I can't find any documentation that says "don't do > that" so...? It's more complex than using flush_work() but there's nothing fundamentally wrong with it. A work item is completely unlinked before its execution starts. It's safe to free the work item once its work function started, whether through kfree() or returning. One difference between flush_work() and manual completion would be that if the work item gets requeued, flush_work() would wait for the queued one to finish but given the work item is one-shot this doesn't make any difference. I can see no reason why manual completion would behave differently from flush_work() in this case. > As I understand it, what then happens is that the workqueue code > grabs another kworker thread and runs the next work item in it's > queue. IOWs, work items can block, but doing that does not prevent > execution of other work items queued on other work queues or even on > the same work queue. Tejun, did I get that correct? Yes, as long as the workqueue is under its @max_active limit and has access to an existing kworker or can create a new one, it'll start executing the next work item immediately; however, the guaranteed level of concurrency is 1 even for WQ_RECLAIM workqueues. IOW, the work items queued on a workqueue must be able to make forward progress with single work item if the work items are being depended upon for memory reclaim. > Hence the work on the xfs-data queue will block until another > kworker processes the item on the xfs-alloc-wq which means progress > is made and the inode gets unlocked. Then the kworker for the work > on the xfs-data queue will get the lock, complete it's work and > everything has resolved itself. As long as a WQ_RECLAIM workqueue dosen't depend upon itself, forward-progress is guaranteed. Thanks. -- tejun ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) @ 2014-06-24 3:25 ` Tejun Heo 0 siblings, 0 replies; 30+ messages in thread From: Tejun Heo @ 2014-06-24 3:25 UTC (permalink / raw) To: Dave Chinner; +Cc: linux-kernel, Austin Schuh, xfs Hello, On Tue, Jun 24, 2014 at 01:02:40PM +1000, Dave Chinner wrote: > start_flush_work() is effectively a special queue_work() > implementation, so if if it's not safe to call complete() from the > workqueue as the above patch implies then this code has the same > problem. > > Tejun - is this "do it yourself completion" a known issue w.r.t. > workqueues? I can't find any documentation that says "don't do > that" so...? It's more complex than using flush_work() but there's nothing fundamentally wrong with it. A work item is completely unlinked before its execution starts. It's safe to free the work item once its work function started, whether through kfree() or returning. One difference between flush_work() and manual completion would be that if the work item gets requeued, flush_work() would wait for the queued one to finish but given the work item is one-shot this doesn't make any difference. I can see no reason why manual completion would behave differently from flush_work() in this case. > As I understand it, what then happens is that the workqueue code > grabs another kworker thread and runs the next work item in it's > queue. IOWs, work items can block, but doing that does not prevent > execution of other work items queued on other work queues or even on > the same work queue. Tejun, did I get that correct? Yes, as long as the workqueue is under its @max_active limit and has access to an existing kworker or can create a new one, it'll start executing the next work item immediately; however, the guaranteed level of concurrency is 1 even for WQ_RECLAIM workqueues. IOW, the work items queued on a workqueue must be able to make forward progress with single work item if the work items are being depended upon for memory reclaim. > Hence the work on the xfs-data queue will block until another > kworker processes the item on the xfs-alloc-wq which means progress > is made and the inode gets unlocked. Then the kworker for the work > on the xfs-data queue will get the lock, complete it's work and > everything has resolved itself. As long as a WQ_RECLAIM workqueue dosen't depend upon itself, forward-progress is guaranteed. Thanks. -- tejun _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) 2014-06-24 3:25 ` Tejun Heo (?) @ 2014-06-25 3:05 ` Austin Schuh 2014-06-25 14:00 ` Tejun Heo -1 siblings, 1 reply; 30+ messages in thread From: Austin Schuh @ 2014-06-25 3:05 UTC (permalink / raw) To: Tejun Heo; +Cc: Thomas Gleixner, linux-kernel, xfs [-- Attachment #1.1: Type: text/plain, Size: 5900 bytes --] [Adding tglx to the cc] On Mon, Jun 23, 2014 at 8:25 PM, Tejun Heo <tj@kernel.org> wrote: > Hello, > > On Tue, Jun 24, 2014 at 01:02:40PM +1000, Dave Chinner wrote: > > start_flush_work() is effectively a special queue_work() > > implementation, so if if it's not safe to call complete() from the > > workqueue as the above patch implies then this code has the same > > problem. > > > > Tejun - is this "do it yourself completion" a known issue w.r.t. > > workqueues? I can't find any documentation that says "don't do > > that" so...? > > It's more complex than using flush_work() but there's nothing > fundamentally wrong with it. A work item is completely unlinked > before its execution starts. It's safe to free the work item once its > work function started, whether through kfree() or returning. > > One difference between flush_work() and manual completion would be > that if the work item gets requeued, flush_work() would wait for the > queued one to finish but given the work item is one-shot this doesn't > make any difference. > > I can see no reason why manual completion would behave differently > from flush_work() in this case. > I went looking for a short trace in my original log to show the problem, and instead found evidence of the second problem. I still like the shorter flush_work call, but that's not my call. I did find this comment in the process_one_work function. Sounds like this could be better documented. /* * It is permissible to free the struct work_struct from * inside the function that is called from it, this we need to * take into account for lockdep too. To avoid bogus "held * lock freed" warnings as well as problems when looking into * work->lockdep_map, make a copy and use that here. */ > As I understand it, what then happens is that the workqueue code > > grabs another kworker thread and runs the next work item in it's > > queue. IOWs, work items can block, but doing that does not prevent > > execution of other work items queued on other work queues or even on > > the same work queue. Tejun, did I get that correct? > > Yes, as long as the workqueue is under its @max_active limit and has > access to an existing kworker or can create a new one, it'll start > executing the next work item immediately; however, the guaranteed > level of concurrency is 1 even for WQ_RECLAIM workqueues. IOW, the > work items queued on a workqueue must be able to make forward progress > with single work item if the work items are being depended upon for > memory reclaim. I mentioned this to Dave when I initially started this thread, but I'm running a RT patched kernel. I don't see forwards progress. The workqueue is only used in 1 spot (xfs_alloc_wq), and has WQ_MEM_RECLAIM set. I started with a 10,000,000 line trace and pulled out the entries which referenced the workqueue and pool leading up to the lockup. scp-4110 [001] ....1.3 101.184640: workqueue_queue_work: work struct=ffff8803c782d900 function=xfs_bmapi_allocate_worker workqueue=ffff88040c9f5a00 pool=ffff88042dae3fc0 req_cpu=512 cpu=1 scp-4110 [001] ....1.3 101.184641: workqueue_activate_work: work struct ffff8803c782d900 kworker/1:1-89 [001] ....1.1 101.184883: workqueue_nr_running: pool=ffff88042dae3fc0 nr_running=1 kworker/1:1-89 [001] ....1.. 101.184885: workqueue_execute_start: work struct ffff8803c782d900: function xfs_bmapi_allocate_worker irq/44-ahci-275 [001] ....1.5 101.185086: workqueue_queue_work: work struct=ffff8800ae3f01e0 function=xfs_end_io workqueue=ffff88040b459a00 pool=ffff88042dae3fc0 req_cpu=512 cpu=1 irq/44-ahci-275 [001] ....1.5 101.185088: workqueue_activate_work: work struct ffff8800ae3f01e0 scp-4110 [001] ....1.. 101.187911: xfs_ilock: dev 8:5 ino 0xf9e flags ILOCK_EXCL caller xfs_iomap_write_allocate scp-4110 [001] ....1.3 101.187914: workqueue_queue_work: work struct=ffff8803c782d900 function=xfs_bmapi_allocate_worker workqueue=ffff88040c9f5a00 pool=ffff88042dae3fc0 req_cpu=512 cpu=1 scp-4110 [001] ....1.3 101.187915: workqueue_activate_work: work struct ffff8803c782d900 scp-4110 [001] ....1.4 101.187926: workqueue_queue_work: work struct=ffff88040a6a01c8 function=blk_delay_work workqueue=ffff88040c9f4a00 pool=ffff88042dae44c0 req_cpu=512 cpu=1 scp-4110 [001] ....1.4 101.187926: workqueue_activate_work: work struct ffff88040a6a01c8 kworker/1:1-89 [001] ....1.. 101.187998: workqueue_execute_end: work struct ffff8803c782d900 kworker/1:1-89 [001] ....1.. 101.188000: workqueue_execute_start: work struct ffff8800ae3f01e0: function xfs_end_io kworker/1:1-89 [001] ....1.. 101.188001: xfs_ilock: dev 8:5 ino 0xf9e flags ILOCK_EXCL caller xfs_setfilesize The last work never runs. Hangcheck triggers shortly after. I spent some more time debugging, and I am seeing that tsk_is_pi_blocked is returning 1 in sched_submit_work (kernel/sched/core.c). It looks like sched_submit_work is not detecting that the worker task is blocked on a mutex. This looks very RT related right now. I see 2 problems from my reading (and experimentation). The first is that the second worker isn't getting started because tsk_is_pi_blocked is reporting that the task isn't blocked on a mutex. The second is that even if another worker needs to be scheduled because the original worker is blocked on a mutex, we need the pool lock to schedule another worker. The pool lock can be acquired by any CPU, and is a spin_lock. If we end up on the slow path for the pool lock, we hit BUG_ON(rt_mutex_real_waiter(task->pi_blocked_on)) in task_blocks_on_rt_mutex in rtmutex.c. I'm not sure how to deal with either problem. Hopefully I've got all my facts right... Debugging kernel code is a whole new world from userspace code. Thanks! Austin [-- Attachment #1.2: Type: text/html, Size: 7489 bytes --] [-- Attachment #2: Type: text/plain, Size: 121 bytes --] _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) 2014-06-25 3:05 ` Austin Schuh @ 2014-06-25 14:00 ` Tejun Heo 0 siblings, 0 replies; 30+ messages in thread From: Tejun Heo @ 2014-06-25 14:00 UTC (permalink / raw) To: Austin Schuh; +Cc: Dave Chinner, xfs, Thomas Gleixner, linux-kernel Hello, On Tue, Jun 24, 2014 at 08:05:07PM -0700, Austin Schuh wrote: > > I can see no reason why manual completion would behave differently > > from flush_work() in this case. > > I went looking for a short trace in my original log to show the problem, > and instead found evidence of the second problem. I still like the shorter > flush_work call, but that's not my call. So, are you saying that the original issue you reported isn't actually a problem? But didn't you imply that changing the waiting mechanism fixed a deadlock or was that a false positive? > I did find this comment in the process_one_work function. Sounds like this > could be better documented. Yeah, we prolly should beef up Documentation/workqueue.txt with information on general usage. > I spent some more time debugging, and I am seeing that tsk_is_pi_blocked is > returning 1 in sched_submit_work (kernel/sched/core.c). It looks > like sched_submit_work is not detecting that the worker task is blocked on > a mutex. The function unplugs the block layer and doesn't have much to do with workqueue although it has "_work" in its name. > This looks very RT related right now. I see 2 problems from my reading > (and experimentation). The first is that the second worker isn't getting > started because tsk_is_pi_blocked is reporting that the task isn't blocked > on a mutex. The second is that even if another worker needs to be > scheduled because the original worker is blocked on a mutex, we need the > pool lock to schedule another worker. The pool lock can be acquired by any > CPU, and is a spin_lock. If we end up on the slow path for the pool lock, > we hit BUG_ON(rt_mutex_real_waiter(task->pi_blocked_on)) > in task_blocks_on_rt_mutex in rtmutex.c. I'm not sure how to deal with > either problem. > > Hopefully I've got all my facts right... Debugging kernel code is a whole > new world from userspace code. I don't have much idea how RT kernel works either. Can you reproduce the issues that you see on mainline? Thanks. -- tejun ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) @ 2014-06-25 14:00 ` Tejun Heo 0 siblings, 0 replies; 30+ messages in thread From: Tejun Heo @ 2014-06-25 14:00 UTC (permalink / raw) To: Austin Schuh; +Cc: Thomas Gleixner, linux-kernel, xfs Hello, On Tue, Jun 24, 2014 at 08:05:07PM -0700, Austin Schuh wrote: > > I can see no reason why manual completion would behave differently > > from flush_work() in this case. > > I went looking for a short trace in my original log to show the problem, > and instead found evidence of the second problem. I still like the shorter > flush_work call, but that's not my call. So, are you saying that the original issue you reported isn't actually a problem? But didn't you imply that changing the waiting mechanism fixed a deadlock or was that a false positive? > I did find this comment in the process_one_work function. Sounds like this > could be better documented. Yeah, we prolly should beef up Documentation/workqueue.txt with information on general usage. > I spent some more time debugging, and I am seeing that tsk_is_pi_blocked is > returning 1 in sched_submit_work (kernel/sched/core.c). It looks > like sched_submit_work is not detecting that the worker task is blocked on > a mutex. The function unplugs the block layer and doesn't have much to do with workqueue although it has "_work" in its name. > This looks very RT related right now. I see 2 problems from my reading > (and experimentation). The first is that the second worker isn't getting > started because tsk_is_pi_blocked is reporting that the task isn't blocked > on a mutex. The second is that even if another worker needs to be > scheduled because the original worker is blocked on a mutex, we need the > pool lock to schedule another worker. The pool lock can be acquired by any > CPU, and is a spin_lock. If we end up on the slow path for the pool lock, > we hit BUG_ON(rt_mutex_real_waiter(task->pi_blocked_on)) > in task_blocks_on_rt_mutex in rtmutex.c. I'm not sure how to deal with > either problem. > > Hopefully I've got all my facts right... Debugging kernel code is a whole > new world from userspace code. I don't have much idea how RT kernel works either. Can you reproduce the issues that you see on mainline? Thanks. -- tejun _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) 2014-06-25 14:00 ` Tejun Heo @ 2014-06-25 17:04 ` Austin Schuh -1 siblings, 0 replies; 30+ messages in thread From: Austin Schuh @ 2014-06-25 17:04 UTC (permalink / raw) To: Tejun Heo; +Cc: Dave Chinner, xfs, Thomas Gleixner, linux-kernel On Wed, Jun 25, 2014 at 7:00 AM, Tejun Heo <tj@kernel.org> wrote: > > Hello, > > On Tue, Jun 24, 2014 at 08:05:07PM -0700, Austin Schuh wrote: > > > I can see no reason why manual completion would behave differently > > > from flush_work() in this case. > > > > I went looking for a short trace in my original log to show the problem, > > and instead found evidence of the second problem. I still like the shorter > > flush_work call, but that's not my call. > > So, are you saying that the original issue you reported isn't actually > a problem? But didn't you imply that changing the waiting mechanism > fixed a deadlock or was that a false positive? Correct, that was a false positive. Sorry for the noise. > > I spent some more time debugging, and I am seeing that tsk_is_pi_blocked is > > returning 1 in sched_submit_work (kernel/sched/core.c). It looks > > like sched_submit_work is not detecting that the worker task is blocked on > > a mutex. > > The function unplugs the block layer and doesn't have much to do with > workqueue although it has "_work" in its name. Thomas moved + if (tsk->flags & PF_WQ_WORKER) + wq_worker_sleeping(tsk); into sched_submit_work as part of the RT patchset. > > This looks very RT related right now. I see 2 problems from my reading > > (and experimentation). The first is that the second worker isn't getting > > started because tsk_is_pi_blocked is reporting that the task isn't blocked > > on a mutex. The second is that even if another worker needs to be > > scheduled because the original worker is blocked on a mutex, we need the > > pool lock to schedule another worker. The pool lock can be acquired by any > > CPU, and is a spin_lock. If we end up on the slow path for the pool lock, > > we hit BUG_ON(rt_mutex_real_waiter(task->pi_blocked_on)) > > in task_blocks_on_rt_mutex in rtmutex.c. I'm not sure how to deal with > > either problem. > > > > Hopefully I've got all my facts right... Debugging kernel code is a whole > > new world from userspace code. > > I don't have much idea how RT kernel works either. Can you reproduce > the issues that you see on mainline? > > Thanks. > > -- > tejun I'll see what I can do. Thanks! Austin ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) @ 2014-06-25 17:04 ` Austin Schuh 0 siblings, 0 replies; 30+ messages in thread From: Austin Schuh @ 2014-06-25 17:04 UTC (permalink / raw) To: Tejun Heo; +Cc: Thomas Gleixner, linux-kernel, xfs On Wed, Jun 25, 2014 at 7:00 AM, Tejun Heo <tj@kernel.org> wrote: > > Hello, > > On Tue, Jun 24, 2014 at 08:05:07PM -0700, Austin Schuh wrote: > > > I can see no reason why manual completion would behave differently > > > from flush_work() in this case. > > > > I went looking for a short trace in my original log to show the problem, > > and instead found evidence of the second problem. I still like the shorter > > flush_work call, but that's not my call. > > So, are you saying that the original issue you reported isn't actually > a problem? But didn't you imply that changing the waiting mechanism > fixed a deadlock or was that a false positive? Correct, that was a false positive. Sorry for the noise. > > I spent some more time debugging, and I am seeing that tsk_is_pi_blocked is > > returning 1 in sched_submit_work (kernel/sched/core.c). It looks > > like sched_submit_work is not detecting that the worker task is blocked on > > a mutex. > > The function unplugs the block layer and doesn't have much to do with > workqueue although it has "_work" in its name. Thomas moved + if (tsk->flags & PF_WQ_WORKER) + wq_worker_sleeping(tsk); into sched_submit_work as part of the RT patchset. > > This looks very RT related right now. I see 2 problems from my reading > > (and experimentation). The first is that the second worker isn't getting > > started because tsk_is_pi_blocked is reporting that the task isn't blocked > > on a mutex. The second is that even if another worker needs to be > > scheduled because the original worker is blocked on a mutex, we need the > > pool lock to schedule another worker. The pool lock can be acquired by any > > CPU, and is a spin_lock. If we end up on the slow path for the pool lock, > > we hit BUG_ON(rt_mutex_real_waiter(task->pi_blocked_on)) > > in task_blocks_on_rt_mutex in rtmutex.c. I'm not sure how to deal with > > either problem. > > > > Hopefully I've got all my facts right... Debugging kernel code is a whole > > new world from userspace code. > > I don't have much idea how RT kernel works either. Can you reproduce > the issues that you see on mainline? > > Thanks. > > -- > tejun I'll see what I can do. Thanks! Austin _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) 2014-06-24 3:25 ` Tejun Heo @ 2014-06-25 3:16 ` Austin Schuh -1 siblings, 0 replies; 30+ messages in thread From: Austin Schuh @ 2014-06-25 3:16 UTC (permalink / raw) To: Tejun Heo; +Cc: Dave Chinner, xfs, linux-kernel, Thomas Gleixner [Adding tglx to the cc. Sorry for any double sends] On Mon, Jun 23, 2014 at 8:25 PM, Tejun Heo <tj@kernel.org> wrote: > Hello, > > On Tue, Jun 24, 2014 at 01:02:40PM +1000, Dave Chinner wrote: >> start_flush_work() is effectively a special queue_work() >> implementation, so if if it's not safe to call complete() from the >> workqueue as the above patch implies then this code has the same >> problem. >> >> Tejun - is this "do it yourself completion" a known issue w.r.t. >> workqueues? I can't find any documentation that says "don't do >> that" so...? > > It's more complex than using flush_work() but there's nothing > fundamentally wrong with it. A work item is completely unlinked > before its execution starts. It's safe to free the work item once its > work function started, whether through kfree() or returning. > > One difference between flush_work() and manual completion would be > that if the work item gets requeued, flush_work() would wait for the > queued one to finish but given the work item is one-shot this doesn't > make any difference. > > I can see no reason why manual completion would behave differently > from flush_work() in this case. I went looking for a short trace in my original log to show the problem, and instead found evidence of the second problem. I still like the shorter flush_work call, but that's not my call. I did find this comment in the process_one_work function. Sounds like this could be better documented. /* * It is permissible to free the struct work_struct from * inside the function that is called from it, this we need to * take into account for lockdep too. To avoid bogus "held * lock freed" warnings as well as problems when looking into * work->lockdep_map, make a copy and use that here. */ >> As I understand it, what then happens is that the workqueue code >> grabs another kworker thread and runs the next work item in it's >> queue. IOWs, work items can block, but doing that does not prevent >> execution of other work items queued on other work queues or even on >> the same work queue. Tejun, did I get that correct? > > Yes, as long as the workqueue is under its @max_active limit and has > access to an existing kworker or can create a new one, it'll start > executing the next work item immediately; however, the guaranteed > level of concurrency is 1 even for WQ_RECLAIM workqueues. IOW, the > work items queued on a workqueue must be able to make forward progress > with single work item if the work items are being depended upon for > memory reclaim. I mentioned this to Dave when I initially started this thread, but I'm running a RT patched kernel. I don't see forwards progress. The workqueue is only used in 1 spot (xfs_alloc_wq), and has WQ_MEM_RECLAIM set. I started with a 10,000,000 line trace and pulled out the entries which referenced the workqueue and pool leading up to the lockup. scp-4110 [001] ....1.3 101.184640: workqueue_queue_work: work struct=ffff8803c782d900 function=xfs_bmapi_allocate_worker workqueue=ffff88040c9f5a00 pool=ffff88042dae3fc0 req_cpu=512 cpu=1 scp-4110 [001] ....1.3 101.184641: workqueue_activate_work: work struct ffff8803c782d900 kworker/1:1-89 [001] ....1.1 101.184883: workqueue_nr_running: pool=ffff88042dae3fc0 nr_running=1 kworker/1:1-89 [001] ....1.. 101.184885: workqueue_execute_start: work struct ffff8803c782d900: function xfs_bmapi_allocate_worker irq/44-ahci-275 [001] ....1.5 101.185086: workqueue_queue_work: work struct=ffff8800ae3f01e0 function=xfs_end_io workqueue=ffff88040b459a00 pool=ffff88042dae3fc0 req_cpu=512 cpu=1 irq/44-ahci-275 [001] ....1.5 101.185088: workqueue_activate_work: work struct ffff8800ae3f01e0 scp-4110 [001] ....1.. 101.187911: xfs_ilock: dev 8:5 ino 0xf9e flags ILOCK_EXCL caller xfs_iomap_write_allocate scp-4110 [001] ....1.3 101.187914: workqueue_queue_work: work struct=ffff8803c782d900 function=xfs_bmapi_allocate_worker workqueue=ffff88040c9f5a00 pool=ffff88042dae3fc0 req_cpu=512 cpu=1 scp-4110 [001] ....1.3 101.187915: workqueue_activate_work: work struct ffff8803c782d900 scp-4110 [001] ....1.4 101.187926: workqueue_queue_work: work struct=ffff88040a6a01c8 function=blk_delay_work workqueue=ffff88040c9f4a00 pool=ffff88042dae44c0 req_cpu=512 cpu=1 scp-4110 [001] ....1.4 101.187926: workqueue_activate_work: work struct ffff88040a6a01c8 kworker/1:1-89 [001] ....1.. 101.187998: workqueue_execute_end: work struct ffff8803c782d900 kworker/1:1-89 [001] ....1.. 101.188000: workqueue_execute_start: work struct ffff8800ae3f01e0: function xfs_end_io kworker/1:1-89 [001] ....1.. 101.188001: xfs_ilock: dev 8:5 ino 0xf9e flags ILOCK_EXCL caller xfs_setfilesize The last work never runs. Hangcheck triggers shortly after. I spent some more time debugging, and I am seeing that tsk_is_pi_blocked is returning 1 in sched_submit_work (kernel/sched/core.c). It looks like sched_submit_work is not detecting that the worker task is blocked on a mutex. This looks very RT related right now. I see 2 problems from my reading (and experimentation). The first is that the second worker isn't getting started because tsk_is_pi_blocked is reporting that the task isn't blocked on a mutex. The second is that even if another worker needs to be scheduled because the original worker is blocked on a mutex, we need the pool lock to schedule another worker. The pool lock can be acquired by any CPU, and is a spin_lock. If we end up on the slow path for the pool lock, we hit BUG_ON(rt_mutex_real_waiter(task->pi_blocked_on)) in task_blocks_on_rt_mutex in rtmutex.c. I'm not sure how to deal with either problem. Thomas, any ideas? Hopefully I've got all my facts right... Debugging kernel code is a whole new world from userspace code. Thanks! Austin ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) @ 2014-06-25 3:16 ` Austin Schuh 0 siblings, 0 replies; 30+ messages in thread From: Austin Schuh @ 2014-06-25 3:16 UTC (permalink / raw) To: Tejun Heo; +Cc: Thomas Gleixner, linux-kernel, xfs [Adding tglx to the cc. Sorry for any double sends] On Mon, Jun 23, 2014 at 8:25 PM, Tejun Heo <tj@kernel.org> wrote: > Hello, > > On Tue, Jun 24, 2014 at 01:02:40PM +1000, Dave Chinner wrote: >> start_flush_work() is effectively a special queue_work() >> implementation, so if if it's not safe to call complete() from the >> workqueue as the above patch implies then this code has the same >> problem. >> >> Tejun - is this "do it yourself completion" a known issue w.r.t. >> workqueues? I can't find any documentation that says "don't do >> that" so...? > > It's more complex than using flush_work() but there's nothing > fundamentally wrong with it. A work item is completely unlinked > before its execution starts. It's safe to free the work item once its > work function started, whether through kfree() or returning. > > One difference between flush_work() and manual completion would be > that if the work item gets requeued, flush_work() would wait for the > queued one to finish but given the work item is one-shot this doesn't > make any difference. > > I can see no reason why manual completion would behave differently > from flush_work() in this case. I went looking for a short trace in my original log to show the problem, and instead found evidence of the second problem. I still like the shorter flush_work call, but that's not my call. I did find this comment in the process_one_work function. Sounds like this could be better documented. /* * It is permissible to free the struct work_struct from * inside the function that is called from it, this we need to * take into account for lockdep too. To avoid bogus "held * lock freed" warnings as well as problems when looking into * work->lockdep_map, make a copy and use that here. */ >> As I understand it, what then happens is that the workqueue code >> grabs another kworker thread and runs the next work item in it's >> queue. IOWs, work items can block, but doing that does not prevent >> execution of other work items queued on other work queues or even on >> the same work queue. Tejun, did I get that correct? > > Yes, as long as the workqueue is under its @max_active limit and has > access to an existing kworker or can create a new one, it'll start > executing the next work item immediately; however, the guaranteed > level of concurrency is 1 even for WQ_RECLAIM workqueues. IOW, the > work items queued on a workqueue must be able to make forward progress > with single work item if the work items are being depended upon for > memory reclaim. I mentioned this to Dave when I initially started this thread, but I'm running a RT patched kernel. I don't see forwards progress. The workqueue is only used in 1 spot (xfs_alloc_wq), and has WQ_MEM_RECLAIM set. I started with a 10,000,000 line trace and pulled out the entries which referenced the workqueue and pool leading up to the lockup. scp-4110 [001] ....1.3 101.184640: workqueue_queue_work: work struct=ffff8803c782d900 function=xfs_bmapi_allocate_worker workqueue=ffff88040c9f5a00 pool=ffff88042dae3fc0 req_cpu=512 cpu=1 scp-4110 [001] ....1.3 101.184641: workqueue_activate_work: work struct ffff8803c782d900 kworker/1:1-89 [001] ....1.1 101.184883: workqueue_nr_running: pool=ffff88042dae3fc0 nr_running=1 kworker/1:1-89 [001] ....1.. 101.184885: workqueue_execute_start: work struct ffff8803c782d900: function xfs_bmapi_allocate_worker irq/44-ahci-275 [001] ....1.5 101.185086: workqueue_queue_work: work struct=ffff8800ae3f01e0 function=xfs_end_io workqueue=ffff88040b459a00 pool=ffff88042dae3fc0 req_cpu=512 cpu=1 irq/44-ahci-275 [001] ....1.5 101.185088: workqueue_activate_work: work struct ffff8800ae3f01e0 scp-4110 [001] ....1.. 101.187911: xfs_ilock: dev 8:5 ino 0xf9e flags ILOCK_EXCL caller xfs_iomap_write_allocate scp-4110 [001] ....1.3 101.187914: workqueue_queue_work: work struct=ffff8803c782d900 function=xfs_bmapi_allocate_worker workqueue=ffff88040c9f5a00 pool=ffff88042dae3fc0 req_cpu=512 cpu=1 scp-4110 [001] ....1.3 101.187915: workqueue_activate_work: work struct ffff8803c782d900 scp-4110 [001] ....1.4 101.187926: workqueue_queue_work: work struct=ffff88040a6a01c8 function=blk_delay_work workqueue=ffff88040c9f4a00 pool=ffff88042dae44c0 req_cpu=512 cpu=1 scp-4110 [001] ....1.4 101.187926: workqueue_activate_work: work struct ffff88040a6a01c8 kworker/1:1-89 [001] ....1.. 101.187998: workqueue_execute_end: work struct ffff8803c782d900 kworker/1:1-89 [001] ....1.. 101.188000: workqueue_execute_start: work struct ffff8800ae3f01e0: function xfs_end_io kworker/1:1-89 [001] ....1.. 101.188001: xfs_ilock: dev 8:5 ino 0xf9e flags ILOCK_EXCL caller xfs_setfilesize The last work never runs. Hangcheck triggers shortly after. I spent some more time debugging, and I am seeing that tsk_is_pi_blocked is returning 1 in sched_submit_work (kernel/sched/core.c). It looks like sched_submit_work is not detecting that the worker task is blocked on a mutex. This looks very RT related right now. I see 2 problems from my reading (and experimentation). The first is that the second worker isn't getting started because tsk_is_pi_blocked is reporting that the task isn't blocked on a mutex. The second is that even if another worker needs to be scheduled because the original worker is blocked on a mutex, we need the pool lock to schedule another worker. The pool lock can be acquired by any CPU, and is a spin_lock. If we end up on the slow path for the pool lock, we hit BUG_ON(rt_mutex_real_waiter(task->pi_blocked_on)) in task_blocks_on_rt_mutex in rtmutex.c. I'm not sure how to deal with either problem. Thomas, any ideas? Hopefully I've got all my facts right... Debugging kernel code is a whole new world from userspace code. Thanks! Austin _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) 2014-06-24 3:25 ` Tejun Heo @ 2014-06-25 5:56 ` Dave Chinner -1 siblings, 0 replies; 30+ messages in thread From: Dave Chinner @ 2014-06-25 5:56 UTC (permalink / raw) To: Tejun Heo; +Cc: Austin Schuh, xfs, linux-kernel On Mon, Jun 23, 2014 at 11:25:21PM -0400, Tejun Heo wrote: > Hello, > > On Tue, Jun 24, 2014 at 01:02:40PM +1000, Dave Chinner wrote: > > As I understand it, what then happens is that the workqueue code > > grabs another kworker thread and runs the next work item in it's > > queue. IOWs, work items can block, but doing that does not prevent > > execution of other work items queued on other work queues or even on > > the same work queue. Tejun, did I get that correct? > > Yes, as long as the workqueue is under its @max_active limit and has > access to an existing kworker or can create a new one, it'll start > executing the next work item immediately; however, the guaranteed > level of concurrency is 1 even for WQ_RECLAIM workqueues. IOW, the > work items queued on a workqueue must be able to make forward progress > with single work item if the work items are being depended upon for > memory reclaim. Hmmm - that's different from my understanding of what the original behaviour WQ_MEM_RECLAIM gave us. i.e. that WQ_MEM_RECLAIM workqueues had a rescuer thread created to guarantee that the *workqueue* could make forward progress executing work in a reclaim context. The concept that the *work being executed* needs to guarantee forwards progress is something I've never heard stated before. That worries me a lot, especially with all the memory reclaim problems that have surfaced in the past couple of months.... > As long as a WQ_RECLAIM workqueue dosen't depend upon itself, > forward-progress is guaranteed. I can't find any documentation that actually defines what WQ_MEM_RECLAIM means, so I can't tell when or how this requirement came about. If it's true, then I suspect most of the WQ_MEM_RECLAIM workqueues in filesystems violate it. Can you point me at documentation/commits/code describing the constraints of WQ_MEM_RECLAIM and the reasons for it? Cheers, Dave. -- Dave Chinner david@fromorbit.com ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) @ 2014-06-25 5:56 ` Dave Chinner 0 siblings, 0 replies; 30+ messages in thread From: Dave Chinner @ 2014-06-25 5:56 UTC (permalink / raw) To: Tejun Heo; +Cc: linux-kernel, Austin Schuh, xfs On Mon, Jun 23, 2014 at 11:25:21PM -0400, Tejun Heo wrote: > Hello, > > On Tue, Jun 24, 2014 at 01:02:40PM +1000, Dave Chinner wrote: > > As I understand it, what then happens is that the workqueue code > > grabs another kworker thread and runs the next work item in it's > > queue. IOWs, work items can block, but doing that does not prevent > > execution of other work items queued on other work queues or even on > > the same work queue. Tejun, did I get that correct? > > Yes, as long as the workqueue is under its @max_active limit and has > access to an existing kworker or can create a new one, it'll start > executing the next work item immediately; however, the guaranteed > level of concurrency is 1 even for WQ_RECLAIM workqueues. IOW, the > work items queued on a workqueue must be able to make forward progress > with single work item if the work items are being depended upon for > memory reclaim. Hmmm - that's different from my understanding of what the original behaviour WQ_MEM_RECLAIM gave us. i.e. that WQ_MEM_RECLAIM workqueues had a rescuer thread created to guarantee that the *workqueue* could make forward progress executing work in a reclaim context. The concept that the *work being executed* needs to guarantee forwards progress is something I've never heard stated before. That worries me a lot, especially with all the memory reclaim problems that have surfaced in the past couple of months.... > As long as a WQ_RECLAIM workqueue dosen't depend upon itself, > forward-progress is guaranteed. I can't find any documentation that actually defines what WQ_MEM_RECLAIM means, so I can't tell when or how this requirement came about. If it's true, then I suspect most of the WQ_MEM_RECLAIM workqueues in filesystems violate it. Can you point me at documentation/commits/code describing the constraints of WQ_MEM_RECLAIM and the reasons for it? Cheers, Dave. -- Dave Chinner david@fromorbit.com _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) 2014-06-25 5:56 ` Dave Chinner @ 2014-06-25 14:18 ` Tejun Heo -1 siblings, 0 replies; 30+ messages in thread From: Tejun Heo @ 2014-06-25 14:18 UTC (permalink / raw) To: Dave Chinner; +Cc: Austin Schuh, xfs, linux-kernel Hello, Dave. On Wed, Jun 25, 2014 at 03:56:41PM +1000, Dave Chinner wrote: > Hmmm - that's different from my understanding of what the original > behaviour WQ_MEM_RECLAIM gave us. i.e. that WQ_MEM_RECLAIM > workqueues had a rescuer thread created to guarantee that the > *workqueue* could make forward progress executing work in a > reclaim context. >From Documentation/workqueue.txt WQ_MEM_RECLAIM All wq which might be used in the memory reclaim paths _MUST_ have this flag set. The wq is guaranteed to have at least one execution context regardless of memory pressure. So, all that's guaranteed is that the workqueue has at least one worker executing its work items. If that one worker is serving a work item which can't make forward progress, the workqueue is not guaranteed to make forward progress. > The concept that the *work being executed* needs to guarantee > forwards progress is something I've never heard stated before. > That worries me a lot, especially with all the memory reclaim > problems that have surfaced in the past couple of months.... I'd love to provide that but guaranteeing that at least one work is always being executed requires unlimited task allocation (the ones which get blocked gotta store their context somewhere). > > As long as a WQ_RECLAIM workqueue dosen't depend upon itself, > > forward-progress is guaranteed. > > I can't find any documentation that actually defines what > WQ_MEM_RECLAIM means, so I can't tell when or how this requirement > came about. If it's true, then I suspect most of the WQ_MEM_RECLAIM > workqueues in filesystems violate it. Can you point me at > documentation/commits/code describing the constraints of > WQ_MEM_RECLAIM and the reasons for it? Documentation/workqueue.txt should be it but maybe we should be more explicit. The behavior is maintaining what the pre-concurrency-management workqueue provided with static per-workqueue workers. Each workqueue reserved its workers (either one per cpu or one globally) and it only supported single level of concurrency on each CPU. WQ_MEM_RECLAIM is providing equivalent amount of forward progress guarantee and all the existing users shouldn't have issues on this front. If we have grown incorrect usages from then on, we need to fix them. Thanks. -- tejun ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) @ 2014-06-25 14:18 ` Tejun Heo 0 siblings, 0 replies; 30+ messages in thread From: Tejun Heo @ 2014-06-25 14:18 UTC (permalink / raw) To: Dave Chinner; +Cc: linux-kernel, Austin Schuh, xfs Hello, Dave. On Wed, Jun 25, 2014 at 03:56:41PM +1000, Dave Chinner wrote: > Hmmm - that's different from my understanding of what the original > behaviour WQ_MEM_RECLAIM gave us. i.e. that WQ_MEM_RECLAIM > workqueues had a rescuer thread created to guarantee that the > *workqueue* could make forward progress executing work in a > reclaim context. >From Documentation/workqueue.txt WQ_MEM_RECLAIM All wq which might be used in the memory reclaim paths _MUST_ have this flag set. The wq is guaranteed to have at least one execution context regardless of memory pressure. So, all that's guaranteed is that the workqueue has at least one worker executing its work items. If that one worker is serving a work item which can't make forward progress, the workqueue is not guaranteed to make forward progress. > The concept that the *work being executed* needs to guarantee > forwards progress is something I've never heard stated before. > That worries me a lot, especially with all the memory reclaim > problems that have surfaced in the past couple of months.... I'd love to provide that but guaranteeing that at least one work is always being executed requires unlimited task allocation (the ones which get blocked gotta store their context somewhere). > > As long as a WQ_RECLAIM workqueue dosen't depend upon itself, > > forward-progress is guaranteed. > > I can't find any documentation that actually defines what > WQ_MEM_RECLAIM means, so I can't tell when or how this requirement > came about. If it's true, then I suspect most of the WQ_MEM_RECLAIM > workqueues in filesystems violate it. Can you point me at > documentation/commits/code describing the constraints of > WQ_MEM_RECLAIM and the reasons for it? Documentation/workqueue.txt should be it but maybe we should be more explicit. The behavior is maintaining what the pre-concurrency-management workqueue provided with static per-workqueue workers. Each workqueue reserved its workers (either one per cpu or one globally) and it only supported single level of concurrency on each CPU. WQ_MEM_RECLAIM is providing equivalent amount of forward progress guarantee and all the existing users shouldn't have issues on this front. If we have grown incorrect usages from then on, we need to fix them. Thanks. -- tejun _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) 2014-06-25 14:18 ` Tejun Heo @ 2014-06-25 22:08 ` Dave Chinner -1 siblings, 0 replies; 30+ messages in thread From: Dave Chinner @ 2014-06-25 22:08 UTC (permalink / raw) To: Tejun Heo; +Cc: Austin Schuh, xfs, linux-kernel On Wed, Jun 25, 2014 at 10:18:36AM -0400, Tejun Heo wrote: > Hello, Dave. > > On Wed, Jun 25, 2014 at 03:56:41PM +1000, Dave Chinner wrote: > > Hmmm - that's different from my understanding of what the original > > behaviour WQ_MEM_RECLAIM gave us. i.e. that WQ_MEM_RECLAIM > > workqueues had a rescuer thread created to guarantee that the > > *workqueue* could make forward progress executing work in a > > reclaim context. > > From Documentation/workqueue.txt > > WQ_MEM_RECLAIM > > All wq which might be used in the memory reclaim paths _MUST_ > have this flag set. The wq is guaranteed to have at least one > execution context regardless of memory pressure. > > So, all that's guaranteed is that the workqueue has at least one > worker executing its work items. If that one worker is serving a work > item which can't make forward progress, the workqueue is not > guaranteed to make forward progress. Adding that to the docco might be useful ;) > > > As long as a WQ_RECLAIM workqueue dosen't depend upon itself, > > > forward-progress is guaranteed. > > > > I can't find any documentation that actually defines what > > WQ_MEM_RECLAIM means, so I can't tell when or how this requirement > > came about. If it's true, then I suspect most of the WQ_MEM_RECLAIM > > workqueues in filesystems violate it. Can you point me at > > documentation/commits/code describing the constraints of > > WQ_MEM_RECLAIM and the reasons for it? > > Documentation/workqueue.txt should be it but maybe we should be more > explicit. The behavior is maintaining what the > pre-concurrency-management workqueue provided with static > per-workqueue workers. Each workqueue reserved its workers (either > one per cpu or one globally) and it only supported single level of > concurrency on each CPU. WQ_MEM_RECLAIM is providing equivalent > amount of forward progress guarantee and all the existing users > shouldn't have issues on this front. If we have grown incorrect > usages from then on, we need to fix them. Ok, so it hasn't changed. We're still usingthem like we used the original workqueues, and we never, ever provided a guarantee of forwards progress for them, either. So if the workqueues haven't changed, and we haven't changed how we use workqueues, then something else is causing all our recent problems.... Thanks for the clarification, Tejun! Cheers, Dave. -- Dave Chinner david@fromorbit.com ^ permalink raw reply [flat|nested] 30+ messages in thread
* Re: On-stack work item completion race? (was Re: XFS crash?) @ 2014-06-25 22:08 ` Dave Chinner 0 siblings, 0 replies; 30+ messages in thread From: Dave Chinner @ 2014-06-25 22:08 UTC (permalink / raw) To: Tejun Heo; +Cc: linux-kernel, Austin Schuh, xfs On Wed, Jun 25, 2014 at 10:18:36AM -0400, Tejun Heo wrote: > Hello, Dave. > > On Wed, Jun 25, 2014 at 03:56:41PM +1000, Dave Chinner wrote: > > Hmmm - that's different from my understanding of what the original > > behaviour WQ_MEM_RECLAIM gave us. i.e. that WQ_MEM_RECLAIM > > workqueues had a rescuer thread created to guarantee that the > > *workqueue* could make forward progress executing work in a > > reclaim context. > > From Documentation/workqueue.txt > > WQ_MEM_RECLAIM > > All wq which might be used in the memory reclaim paths _MUST_ > have this flag set. The wq is guaranteed to have at least one > execution context regardless of memory pressure. > > So, all that's guaranteed is that the workqueue has at least one > worker executing its work items. If that one worker is serving a work > item which can't make forward progress, the workqueue is not > guaranteed to make forward progress. Adding that to the docco might be useful ;) > > > As long as a WQ_RECLAIM workqueue dosen't depend upon itself, > > > forward-progress is guaranteed. > > > > I can't find any documentation that actually defines what > > WQ_MEM_RECLAIM means, so I can't tell when or how this requirement > > came about. If it's true, then I suspect most of the WQ_MEM_RECLAIM > > workqueues in filesystems violate it. Can you point me at > > documentation/commits/code describing the constraints of > > WQ_MEM_RECLAIM and the reasons for it? > > Documentation/workqueue.txt should be it but maybe we should be more > explicit. The behavior is maintaining what the > pre-concurrency-management workqueue provided with static > per-workqueue workers. Each workqueue reserved its workers (either > one per cpu or one globally) and it only supported single level of > concurrency on each CPU. WQ_MEM_RECLAIM is providing equivalent > amount of forward progress guarantee and all the existing users > shouldn't have issues on this front. If we have grown incorrect > usages from then on, we need to fix them. Ok, so it hasn't changed. We're still usingthem like we used the original workqueues, and we never, ever provided a guarantee of forwards progress for them, either. So if the workqueues haven't changed, and we haven't changed how we use workqueues, then something else is causing all our recent problems.... Thanks for the clarification, Tejun! Cheers, Dave. -- Dave Chinner david@fromorbit.com _______________________________________________ xfs mailing list xfs@oss.sgi.com http://oss.sgi.com/mailman/listinfo/xfs ^ permalink raw reply [flat|nested] 30+ messages in thread
end of thread, other threads:[~2014-06-25 22:09 UTC | newest] Thread overview: 30+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2014-03-05 23:08 XFS crash? Austin Schuh 2014-03-05 23:35 ` Dave Chinner 2014-03-06 0:53 ` Austin Schuh 2014-05-13 1:29 ` Austin Schuh 2014-05-13 3:10 ` Austin Schuh 2014-05-13 3:33 ` Austin Schuh 2014-05-13 3:46 ` Dave Chinner 2014-05-13 4:03 ` Austin Schuh 2014-05-13 6:39 ` Dave Chinner 2014-05-13 7:02 ` Austin Schuh 2014-05-13 9:03 ` Dave Chinner 2014-05-13 17:11 ` Austin Schuh 2014-06-23 20:05 ` Austin Schuh 2014-06-24 3:02 ` On-stack work item completion race? (was Re: XFS crash?) Dave Chinner 2014-06-24 3:02 ` Dave Chinner 2014-06-24 3:25 ` Tejun Heo 2014-06-24 3:25 ` Tejun Heo 2014-06-25 3:05 ` Austin Schuh 2014-06-25 14:00 ` Tejun Heo 2014-06-25 14:00 ` Tejun Heo 2014-06-25 17:04 ` Austin Schuh 2014-06-25 17:04 ` Austin Schuh 2014-06-25 3:16 ` Austin Schuh 2014-06-25 3:16 ` Austin Schuh 2014-06-25 5:56 ` Dave Chinner 2014-06-25 5:56 ` Dave Chinner 2014-06-25 14:18 ` Tejun Heo 2014-06-25 14:18 ` Tejun Heo 2014-06-25 22:08 ` Dave Chinner 2014-06-25 22:08 ` Dave Chinner
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.