Hung task failure in recent Crostini tests |
||||
Issue descriptionStarting with 11121.0.0 I'm seeing some tests failing with hung tasks that I have not seen before..this may be related to recent filesystem changes. Please look into this so we can get the tree green. Below are the examples I found. Case #1 https://stainless.corp.google.com/browse/chromeos-autotest-results/244523017-chromeos-test/ 2018-10-03T00:59:20.015080+00:00 INFO VM(3)[22672]: [ 246.715459] INFO: task kworker/u4:0:5 blocked for more than 120 seconds.#015 2018-10-03T00:59:20.017716+00:00 INFO VM(3)[22672]: [ 246.718078] Tainted: G W 4.14.71-07583-g022708b4bb18 #1#015 2018-10-03T00:59:20.020720+00:00 INFO VM(3)[22672]: [ 246.720806] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.#015 2018-10-03T00:59:20.022628+00:00 INFO VM(3)[22672]: [ 246.723870] kworker/u4:0 D 0 5 2 0x80000000#015 2018-10-03T00:59:20.030406+00:00 INFO VM(3)[22672]: [ 246.730921] Workqueue: events_unbound btrfs_async_reclaim_metadata_space#015 2018-10-03T00:59:20.031402+00:00 INFO VM(3)[22672]: [ 246.733693] Call Trace:#015 2018-10-03T00:59:20.036767+00:00 INFO VM(3)[22672]: [ 246.734637] ? __schedule+0x393/0x435#015 2018-10-03T00:59:20.037640+00:00 INFO VM(3)[22672]: [ 246.739852] ? schedule+0x59/0x78#015 2018-10-03T00:59:20.039133+00:00 INFO VM(3)[22672]: [ 246.740890] ? schedule_timeout+0x1e/0xba#015 2018-10-03T00:59:20.040851+00:00 INFO VM(3)[22672]: [ 246.742370] ? _raw_spin_unlock_irqrestore+0x12/0x33#015 2018-10-03T00:59:20.042163+00:00 INFO VM(3)[22672]: [ 246.744091] ? try_to_wake_up+0x1bf/0x24e#015 2018-10-03T00:59:20.043075+00:00 INFO VM(3)[22672]: [ 246.745256] ? __switch_to_asm+0x24/0x60#015 2018-10-03T00:59:20.044053+00:00 INFO VM(3)[22672]: [ 246.746170] ? do_wait_for_common+0xc3/0x120#015 2018-10-03T00:59:20.049822+00:00 INFO VM(3)[22672]: [ 246.747148] ? console_conditional_schedule+0x1e/0x1e#015 2018-10-03T00:59:20.051404+00:00 INFO VM(3)[22672]: [ 246.753118] ? arch_local_irq_disable+0x8/0x8#015 2018-10-03T00:59:20.052881+00:00 INFO VM(3)[22672]: [ 246.754633] ? console_conditional_schedule+0x1e/0x1e#015 2018-10-03T00:59:20.053820+00:00 INFO VM(3)[22672]: [ 246.755974] ? __wait_for_common+0x42/0x59#015 2018-10-03T00:59:20.059817+00:00 INFO VM(3)[22672]: [ 246.756926] ? btrfs_wait_ordered_extents+0x21c/0x25d#015 2018-10-03T00:59:20.060924+00:00 INFO VM(3)[22672]: [ 246.762914] ? btrfs_wait_ordered_roots+0xf7/0x178#015 2018-10-03T00:59:20.066127+00:00 INFO VM(3)[22672]: [ 246.764020] ? flush_space+0x294/0x477#015 2018-10-03T00:59:20.067829+00:00 INFO VM(3)[22672]: [ 246.769391] ? __btrfs_end_transaction+0x21d/0x25b#015 2018-10-03T00:59:20.069764+00:00 INFO VM(3)[22672]: [ 246.771064] ? btrfs_async_reclaim_metadata_space+0x7e/0x17d#015 2018-10-03T00:59:20.071337+00:00 INFO VM(3)[22672]: [ 246.773036] ? process_one_work+0x10b/0x209#015 2018-10-03T00:59:20.072907+00:00 INFO VM(3)[22672]: [ 246.774592] ? worker_thread+0x197/0x25e#015 2018-10-03T00:59:20.074221+00:00 INFO VM(3)[22672]: [ 246.776157] ? pr_cont_work+0x4d/0x4d#015 2018-10-03T00:59:20.083894+00:00 INFO VM(3)[22672]: [ 246.777437] ? kthread+0xe6/0xf6#015 2018-10-03T00:59:20.085248+00:00 INFO VM(3)[22672]: [ 246.787155] ? pr_cont_work+0x4d/0x4d#015 2018-10-03T00:59:20.086789+00:00 INFO VM(3)[22672]: [ 246.788484] ? kthread_destroy_worker+0x3e/0x3e#015 2018-10-03T00:59:20.088208+00:00 INFO VM(3)[22672]: [ 246.790394] ? ret_from_fork+0x35/0x40#015 2018-10-03T00:59:20.089954+00:00 INFO VM(3)[22672]: [ 246.791286] task PC stack pid father#015 2018-10-03T00:59:20.091704+00:00 INFO VM(3)[22672]: [ 246.793095] kworker/u4:0 D 0 5 2 0x80000000#015 2018-10-03T00:59:20.093877+00:00 INFO VM(3)[22672]: [ 246.794857] Workqueue: events_unbound btrfs_async_reclaim_metadata_space#015 2018-10-03T00:59:20.094692+00:00 INFO VM(3)[22672]: [ 246.797014] Call Trace:#015 2018-10-03T00:59:20.095872+00:00 INFO VM(3)[22672]: [ 246.797822] ? __schedule+0x393/0x435#015 2018-10-03T00:59:20.096978+00:00 INFO VM(3)[22672]: [ 246.799001] ? schedule+0x59/0x78#015 2018-10-03T00:59:20.098315+00:00 INFO VM(3)[22672]: [ 246.800116] ? schedule_timeout+0x1e/0xba#015 2018-10-03T00:59:20.099930+00:00 INFO VM(3)[22672]: [ 246.801454] ? _raw_spin_unlock_irqrestore+0x12/0x33#015 2018-10-03T00:59:20.101216+00:00 INFO VM(3)[22672]: [ 246.803060] ? try_to_wake_up+0x1bf/0x24e#015 2018-10-03T00:59:20.102490+00:00 INFO VM(3)[22672]: [ 246.804354] ? __switch_to_asm+0x24/0x60#015 2018-10-03T00:59:20.103911+00:00 INFO VM(3)[22672]: [ 246.805628] ? do_wait_for_common+0xc3/0x120#015 2018-10-03T00:59:20.105502+00:00 INFO VM(3)[22672]: [ 246.807052] ? console_conditional_schedule+0x1e/0x1e#015 2018-10-03T00:59:20.106553+00:00 INFO VM(3)[22672]: [ 246.808593] ? arch_local_irq_disable+0x8/0x8#015 2018-10-03T00:59:20.107756+00:00 INFO VM(3)[22672]: [ 246.809647] ? console_conditional_schedule+0x1e/0x1e#015 2018-10-03T00:59:20.108695+00:00 INFO VM(3)[22672]: [ 246.810839] ? __wait_for_common+0x42/0x59#015 2018-10-03T00:59:20.109872+00:00 INFO VM(3)[22672]: [ 246.811793] ? btrfs_wait_ordered_extents+0x21c/0x25d#015 2018-10-03T00:59:20.110983+00:00 INFO VM(3)[22672]: [ 246.812969] ? btrfs_wait_ordered_roots+0xf7/0x178#015 2018-10-03T00:59:20.112030+00:00 INFO VM(3)[22672]: [ 246.814081] ? flush_space+0x294/0x477#015 2018-10-03T00:59:20.113565+00:00 INFO VM(3)[22672]: [ 246.815171] ? __btrfs_end_transaction+0x21d/0x25b#015 2018-10-03T00:59:20.115378+00:00 INFO VM(3)[22672]: [ 246.816703] ? btrfs_async_reclaim_metadata_space+0x7e/0x17d#015 2018-10-03T00:59:20.116734+00:00 INFO VM(3)[22672]: [ 246.818518] ? process_one_work+0x10b/0x209#015 2018-10-03T00:59:20.118012+00:00 INFO VM(3)[22672]: [ 246.819878] ? worker_thread+0x197/0x25e#015 2018-10-03T00:59:20.119200+00:00 INFO VM(3)[22672]: [ 246.821150] ? pr_cont_work+0x4d/0x4d#015 2018-10-03T00:59:20.120266+00:00 INFO VM(3)[22672]: [ 246.822337] ? kthread+0xe6/0xf6#015 2018-10-03T00:59:20.121459+00:00 INFO VM(3)[22672]: [ 246.823402] ? pr_cont_work+0x4d/0x4d#015 2018-10-03T00:59:20.122941+00:00 INFO VM(3)[22672]: [ 246.824597] ? kthread_destroy_worker+0x3e/0x3e#015 2018-10-03T00:59:20.124048+00:00 INFO VM(3)[22672]: [ 246.826082] ? ret_from_fork+0x35/0x40#015 2018-10-03T00:59:20.125361+00:00 INFO VM(3)[22672]: [ 246.827160] btrfs-transacti D 0 117 2 0x80000000#015 2018-10-03T00:59:20.126000+00:00 INFO VM(3)[22672]: [ 246.828453] Call Trace:#015 2018-10-03T00:59:20.127193+00:00 INFO VM(3)[22672]: [ 246.829133] ? __schedule+0x393/0x435#015 2018-10-03T00:59:20.128303+00:00 INFO VM(3)[22672]: [ 246.830333] ? schedule+0x59/0x78#015 2018-10-03T00:59:20.129462+00:00 INFO VM(3)[22672]: [ 246.831444] ? io_schedule+0xd/0x15#015 2018-10-03T00:59:20.130742+00:00 INFO VM(3)[22672]: [ 246.832600] ? blk_mq_get_tag+0xe9/0x1db#015 2018-10-03T00:59:20.132016+00:00 INFO VM(3)[22672]: [ 246.833888] ? init_wait_entry+0x24/0x24#015 2018-10-03T00:59:20.133405+00:00 INFO VM(3)[22672]: [ 246.835156] ? blk_mq_get_request+0xe5/0x356#015 2018-10-03T00:59:20.135173+00:00 INFO VM(3)[22672]: [ 246.836543] ? blk_mq_make_request+0xe2/0x349#015 2018-10-03T00:59:20.143250+00:00 INFO VM(3)[22672]: [ 246.838437] ? generic_make_request+0xd0/0x213#015 2018-10-03T00:59:20.144575+00:00 INFO VM(3)[22672]: [ 246.846527] ? submit_bio+0x8f/0x104#015 2018-10-03T00:59:20.146554+00:00 INFO VM(3)[22672]: [ 246.847812] ? btrfs_bio_counter_inc_blocked+0x90/0xaa#015 2018-10-03T00:59:20.148108+00:00 INFO VM(3)[22672]: [ 246.849814] ? __unlock_for_delalloc+0x24/0x24#015 2018-10-03T00:59:20.149143+00:00 INFO VM(3)[22672]: [ 246.851199] ? btrfs_map_bio+0x28e/0x2e9#015 2018-10-03T00:59:20.150299+00:00 INFO VM(3)[22672]: [ 246.852289] ? btrfs_submit_bio_hook+0xc3/0x113#015 2018-10-03T00:59:20.151259+00:00 INFO VM(3)[22672]: [ 246.853388] ? submit_one_bio+0x58/0x79#015 2018-10-03T00:59:20.152384+00:00 INFO VM(3)[22672]: [ 246.854436] ? flush_epd_write_bio+0x17/0x25#015 2018-10-03T00:59:20.153490+00:00 INFO VM(3)[22672]: [ 246.855562] ? extent_writepages+0x2d5/0x2e9#015 2018-10-03T00:59:20.154611+00:00 INFO VM(3)[22672]: [ 246.856684] ? btrfs_cont_expand+0x48c/0x48c#015 2018-10-03T00:59:20.155666+00:00 INFO VM(3)[22672]: [ 246.857795] ? _raw_spin_lock_bh+0xa/0x11#015 2018-10-03T00:59:20.156685+00:00 INFO VM(3)[22672]: [ 246.858873] ? do_writepages+0x59/0x74#015 2018-10-03T00:59:20.157926+00:00 INFO VM(3)[22672]: [ 246.859879] ? __filemap_fdatawrite_range+0xa8/0xbe#015 2018-10-03T00:59:20.161935+00:00 INFO VM(3)[22672]: [ 246.861112] ? btrfs_fdatawrite_range+0x17/0x43#015 2018-10-03T00:59:20.161951+00:00 INFO VM(3)[22672]: [ 246.862196] ? __btrfs_write_out_cache+0x35b/0x378#015 2018-10-03T00:59:20.161962+00:00 INFO VM(3)[22672]: [ 246.863242] ? btrfs_write_out_cache+0x86/0xce#015 2018-10-03T00:59:20.163166+00:00 INFO VM(3)[22672]: [ 246.864214] ? btrfs_start_dirty_block_groups+0x199/0x368#015 2018-10-03T00:59:20.163680+00:00 INFO VM(3)[22672]: [ 246.865585] ? btrfs_commit_transaction+0x3f2/0x9ce#015 2018-10-03T00:59:20.164719+00:00 INFO VM(3)[22672]: [ 246.866870] ? _raw_spin_unlock+0x6/0x23#015 2018-10-03T00:59:20.165808+00:00 INFO VM(3)[22672]: [ 246.867906] ? join_transaction+0x370/0x37c#015 2018-10-03T00:59:20.171431+00:00 INFO VM(3)[22672]: [ 246.868993] ? start_transaction+0x83/0x31b#015 2018-10-03T00:59:20.172602+00:00 INFO VM(3)[22672]: [ 246.874645] ? transaction_kthread+0xce/0x17d#015 2018-10-03T00:59:20.173777+00:00 INFO VM(3)[22672]: [ 246.875788] ? cleaner_kthread+0x151/0x151#015 2018-10-03T00:59:20.174617+00:00 INFO VM(3)[22672]: [ 246.876848] ? kthread+0xe6/0xf6#015 2018-10-03T00:59:20.175677+00:00 INFO VM(3)[22672]: [ 246.877797] ? cleaner_kthread+0x151/0x151#015 2018-10-03T00:59:20.176849+00:00 INFO VM(3)[22672]: [ 246.878871] ? kthread_destroy_worker+0x3e/0x3e#015 2018-10-03T00:59:20.177798+00:00 INFO VM(3)[22672]: [ 246.880000] ? ret_from_fork+0x35/0x40#015 2018-10-03T00:59:20.179111+00:00 INFO VM(3)[22672]: [ 246.880949] unsquashfs D 0 203 135 0x00000000#015 2018-10-03T00:59:20.181247+00:00 INFO VM(3)[22672]: [ 246.882253] Call Trace:#015 2018-10-03T00:59:20.182523+00:00 INFO VM(3)[22672]: [ 246.884452] ? __schedule+0x393/0x435#015 2018-10-03T00:59:20.183642+00:00 INFO VM(3)[22672]: [ 246.885658] ? schedule+0x59/0x78#015 2018-10-03T00:59:20.189389+00:00 INFO VM(3)[22672]: [ 246.886781] ? reserve_metadata_bytes+0x232/0x349#015 2018-10-03T00:59:20.191586+00:00 INFO VM(3)[22672]: [ 246.892538] ? init_wait_entry+0x24/0x24#015 2018-10-03T00:59:20.194917+00:00 INFO VM(3)[22672]: [ 246.894729] ? btrfs_block_rsv_add+0x1b/0x33#015 2018-10-03T00:59:20.196725+00:00 INFO VM(3)[22672]: [ 246.898064] ? btrfs_delalloc_reserve_metadata+0x19d/0x2ec#015 2018-10-03T00:59:20.198353+00:00 INFO VM(3)[22672]: [ 246.899913] ? __btrfs_buffered_write+0x228/0x66d#015 2018-10-03T00:59:20.199954+00:00 INFO VM(3)[22672]: [ 246.901509] ? dentry_needs_remove_privs+0x23/0x39#015 2018-10-03T00:59:20.205907+00:00 INFO VM(3)[22672]: [ 246.903093] ? btrfs_file_write_iter+0x285/0x436#015 2018-10-03T00:59:20.207153+00:00 INFO VM(3)[22672]: [ 246.909059] ? __vfs_write+0x96/0xc3#015 2018-10-03T00:59:20.208323+00:00 INFO VM(3)[22672]: [ 246.910294] ? vfs_write+0xa1/0xcd#015 2018-10-03T00:59:20.210649+00:00 INFO VM(3)[22672]: [ 246.911461] ? SyS_write+0x38/0x69#015 2018-10-03T00:59:20.211672+00:00 INFO VM(3)[22672]: [ 246.913874] ? do_syscall_64+0x6a/0x7b#015 2018-10-03T00:59:20.213042+00:00 INFO VM(3)[22672]: [ 246.914900] ? entry_SYSCALL_64_after_hwframe+0x3d/0xa2#015 2018-10-03T00:59:20.214447+00:00 INFO VM(3)[22672]: [ 246.916236] kworker/u4:8 D 0 210 2 0x80000000#015 2018-10-03T00:59:20.215852+00:00 INFO VM(3)[22672]: [ 246.917699] Workqueue: btrfs-submit btrfs_submit_helper#015 2018-10-03T00:59:20.216508+00:00 INFO VM(3)[22672]: [ 246.918997] Call Trace:#015 2018-10-03T00:59:20.217421+00:00 INFO VM(3)[22672]: [ 246.919655] ? __schedule+0x393/0x435#015 2018-10-03T00:59:20.218281+00:00 INFO VM(3)[22672]: [ 246.920569] ? schedule+0x59/0x78#015 2018-10-03T00:59:20.219137+00:00 INFO VM(3)[22672]: [ 246.921361] ? io_schedule+0xd/0x15#015 2018-10-03T00:59:20.220095+00:00 INFO VM(3)[22672]: [ 246.922272] ? blk_mq_get_tag+0xe9/0x1db#015 2018-10-03T00:59:20.221055+00:00 INFO VM(3)[22672]: [ 246.923241] ? init_wait_entry+0x24/0x24#015 2018-10-03T00:59:20.222101+00:00 INFO VM(3)[22672]: [ 246.924201] ? blk_mq_get_request+0xe5/0x356#015 2018-10-03T00:59:20.227621+00:00 INFO VM(3)[22672]: [ 246.925245] ? _raw_spin_unlock+0x6/0x23#015 2018-10-03T00:59:20.229468+00:00 INFO VM(3)[22672]: [ 246.930786] ? blk_mq_make_request+0xe2/0x349#015 2018-10-03T00:59:20.231350+00:00 INFO VM(3)[22672]: [ 246.931922] ? generic_make_request+0xd0/0x213#015 2018-10-03T00:59:20.232030+00:00 INFO VM(3)[22672]: [ 246.933203] ? blk_mq_flush_plug_list+0xd0/0xe1#015 2018-10-03T00:59:20.232996+00:00 INFO VM(3)[22672]: [ 246.935224] ? submit_bio+0x8f/0x104#015 2018-10-03T00:59:20.234124+00:00 INFO VM(3)[22672]: [ 246.936178] ? blk_flush_plug_list+0x97/0x1a8#015 2018-10-03T00:59:20.235287+00:00 INFO VM(3)[22672]: [ 246.937317] ? run_scheduled_bios+0x1b7/0x43a#015 2018-10-03T00:59:20.236964+00:00 INFO VM(3)[22672]: [ 246.938359] ? normal_work_helper+0xc6/0x188#015 2018-10-03T00:59:20.244788+00:00 INFO VM(3)[22672]: [ 246.939415] ? process_one_work+0x10b/0x209#015 2018-10-03T00:59:20.244804+00:00 INFO VM(3)[22672]: [ 246.945401] ? worker_thread+0x197/0x25e#015 2018-10-03T00:59:20.244814+00:00 INFO VM(3)[22672]: [ 246.946413] ? pr_cont_work+0x4d/0x4d#015 2018-10-03T00:59:20.247259+00:00 INFO VM(3)[22672]: [ 246.947350] ? kthread+0xe6/0xf6#015 2018-10-03T00:59:20.247272+00:00 INFO VM(3)[22672]: [ 246.948404] ? pr_cont_work+0x4d/0x4d#015 2018-10-03T00:59:20.253511+00:00 INFO VM(3)[22672]: [ 246.949432] ? kthread_destroy_worker+0x3e/0x3e#015 2018-10-03T00:59:20.254802+00:00 INFO VM(3)[22672]: [ 246.956742] ? ret_from_fork+0x35/0x40#015 2018-10-03T00:59:20.256888+00:00 INFO VM(3)[22672]: [ 246.957875] kworker/u4:10 D 0 212 2 0x80000000#015 2018-10-03T00:59:20.258456+00:00 INFO VM(3)[22672]: [ 246.960046] Workqueue: btrfs-flush_delalloc btrfs_flush_delalloc_helper#015 2018-10-03T00:59:20.259098+00:00 INFO VM(3)[22672]: [ 246.961600] Call Trace:#015 2018-10-03T00:59:20.260003+00:00 INFO VM(3)[22672]: [ 246.962239] ? __schedule+0x393/0x435#015 2018-10-03T00:59:20.260840+00:00 INFO VM(3)[22672]: [ 246.963150] ? schedule+0x59/0x78#015 2018-10-03T00:59:20.262018+00:00 INFO VM(3)[22672]: [ 246.963987] ? btrfs_start_ordered_extent+0x6d/0x98#015 2018-10-03T00:59:20.262978+00:00 INFO VM(3)[22672]: [ 246.965162] ? init_wait_entry+0x24/0x24#015 2018-10-03T00:59:20.264231+00:00 INFO VM(3)[22672]: [ 246.966123] ? btrfs_run_ordered_extent_work+0x1a/0x27#015 2018-10-03T00:59:20.265312+00:00 INFO VM(3)[22672]: [ 246.967373] ? normal_work_helper+0xc6/0x188#015 2018-10-03T00:59:20.266372+00:00 INFO VM(3)[22672]: [ 246.968455] ? process_one_work+0x10b/0x209#015 2018-10-03T00:59:20.267388+00:00 INFO VM(3)[22672]: [ 246.969459] ? worker_thread+0x197/0x25e#015 2018-10-03T00:59:20.268297+00:00 INFO VM(3)[22672]: [ 246.970449] ? pr_cont_work+0x4d/0x4d#015 2018-10-03T00:59:20.269080+00:00 INFO VM(3)[22672]: [ 246.971338] ? kthread+0xe6/0xf6#015 2018-10-03T00:59:20.269923+00:00 INFO VM(3)[22672]: [ 246.972136] ? pr_cont_work+0x4d/0x4d#015 2018-10-03T00:59:20.271110+00:00 INFO VM(3)[22672]: [ 246.973130] ? kthread_destroy_worker+0x3e/0x3e#015 2018-10-03T00:59:20.272103+00:00 INFO VM(3)[22672]: [ 246.974299] ? ret_from_fork+0x35/0x40#015 Case #2 https://stainless.corp.google.com/browse/chromeos-autotest-results/244521428-chromeos-test/ 2018-10-03T00:15:34.105522+00:00 INFO VM(3)[22927]: [ 246.719026] INFO: task btrfs-transacti:117 blocked for more than 120 seconds.#015 2018-10-03T00:15:34.106983+00:00 INFO VM(3)[22927]: [ 246.720577] Tainted: G W 4.14.71-07583-g022708b4bb18 #1#015 2018-10-03T00:15:34.109111+00:00 INFO VM(3)[22927]: [ 246.722072] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.#015 2018-10-03T00:15:34.110861+00:00 INFO VM(3)[22927]: [ 246.724252] btrfs-transacti D 0 117 2 0x80000000#015 2018-10-03T00:15:34.111687+00:00 INFO VM(3)[22927]: [ 246.726022] Call Trace:#015 2018-10-03T00:15:34.112869+00:00 INFO VM(3)[22927]: [ 246.726836] ? __schedule+0x393/0x435#015 2018-10-03T00:15:34.118526+00:00 INFO VM(3)[22927]: [ 246.731231] ? schedule+0x59/0x78#015 2018-10-03T00:15:34.121442+00:00 INFO VM(3)[22927]: [ 246.733878] ? io_schedule+0xd/0x15#015 2018-10-03T00:15:34.123352+00:00 INFO VM(3)[22927]: [ 246.736611] ? blk_mq_get_tag+0xe9/0x1db#015 2018-10-03T00:15:34.124893+00:00 INFO VM(3)[22927]: [ 246.738518] ? init_wait_entry+0x24/0x24#015 2018-10-03T00:15:34.126725+00:00 INFO VM(3)[22927]: [ 246.740126] ? blk_mq_get_request+0xe5/0x356#015 2018-10-03T00:15:34.128201+00:00 INFO VM(3)[22927]: [ 246.741947] ? blk_mq_make_request+0xe2/0x349#015 2018-10-03T00:15:34.129610+00:00 INFO VM(3)[22927]: [ 246.743339] ? generic_make_request+0xd0/0x213#015 2018-10-03T00:15:34.133630+00:00 INFO VM(3)[22927]: [ 246.744747] ? submit_bio+0x8f/0x104#015 2018-10-03T00:15:34.135290+00:00 INFO VM(3)[22927]: [ 246.748941] ? btrfs_bio_counter_inc_blocked+0x90/0xaa#015 2018-10-03T00:15:34.136437+00:00 INFO VM(3)[22927]: [ 246.750384] ? __unlock_for_delalloc+0x24/0x24#015 2018-10-03T00:15:34.137454+00:00 INFO VM(3)[22927]: [ 246.751581] ? btrfs_map_bio+0x28e/0x2e9#015 2018-10-03T00:15:34.138893+00:00 INFO VM(3)[22927]: [ 246.752611] ? btrfs_submit_bio_hook+0xc3/0x113#015 2018-10-03T00:15:34.140123+00:00 INFO VM(3)[22927]: [ 246.754070] ? submit_one_bio+0x58/0x79#015 2018-10-03T00:15:34.141428+00:00 INFO VM(3)[22927]: [ 246.755300] ? flush_epd_write_bio+0x17/0x25#015 2018-10-03T00:15:34.142546+00:00 INFO VM(3)[22927]: [ 246.756585] ? extent_writepages+0x2d5/0x2e9#015 2018-10-03T00:15:34.148321+00:00 INFO VM(3)[22927]: [ 246.762201] ? btrfs_cont_expand+0x48c/0x48c#015 2018-10-03T00:15:34.149396+00:00 INFO VM(3)[22927]: [ 246.763491] ? _raw_spin_lock_bh+0xa/0x11#015 2018-10-03T00:15:34.150400+00:00 INFO VM(3)[22927]: [ 246.764554] ? do_writepages+0x59/0x74#015 2018-10-03T00:15:34.151727+00:00 INFO VM(3)[22927]: [ 246.765549] ? __filemap_fdatawrite_range+0xa8/0xbe#015 2018-10-03T00:15:34.154658+00:00 INFO VM(3)[22927]: [ 246.766908] ? btrfs_fdatawrite_range+0x17/0x43#015 2018-10-03T00:15:34.154672+00:00 INFO VM(3)[22927]: [ 246.767920] ? __btrfs_write_out_cache+0x35b/0x378#015 2018-10-03T00:15:34.155752+00:00 INFO VM(3)[22927]: [ 246.768952] ? btrfs_write_out_cache+0x86/0xce#015 2018-10-03T00:15:34.156187+00:00 INFO VM(3)[22927]: [ 246.770077] ? btrfs_start_dirty_block_groups+0x199/0x368#015 2018-10-03T00:15:34.157373+00:00 INFO VM(3)[22927]: [ 246.771288] ? btrfs_commit_transaction+0x3f2/0x9ce#015 2018-10-03T00:15:34.158360+00:00 INFO VM(3)[22927]: [ 246.772473] ? _raw_spin_unlock+0x6/0x23#015 2018-10-03T00:15:34.159391+00:00 INFO VM(3)[22927]: [ 246.773459] ? join_transaction+0x370/0x37c#015 2018-10-03T00:15:34.160430+00:00 INFO VM(3)[22927]: [ 246.774492] ? start_transaction+0x83/0x31b#015 2018-10-03T00:15:34.161486+00:00 INFO VM(3)[22927]: [ 246.775531] ? transaction_kthread+0xce/0x17d#015 2018-10-03T00:15:34.162481+00:00 INFO VM(3)[22927]: [ 246.776586] ? cleaner_kthread+0x151/0x151#015 2018-10-03T00:15:34.163285+00:00 INFO VM(3)[22927]: [ 246.777583] ? kthread+0xe6/0xf6#015 2018-10-03T00:15:34.164303+00:00 INFO VM(3)[22927]: [ 246.778385] ? cleaner_kthread+0x151/0x151#015 2018-10-03T00:15:34.165388+00:00 INFO VM(3)[22927]: [ 246.779404] ? kthread_destroy_worker+0x3e/0x3e#015 2018-10-03T00:15:34.166377+00:00 INFO VM(3)[22927]: [ 246.780536] ? ret_from_fork+0x35/0x40#015 2018-10-03T00:15:34.167824+00:00 INFO VM(3)[22927]: [ 246.781476] task PC stack pid father#015 2018-10-03T00:15:34.169181+00:00 INFO VM(3)[22927]: [ 246.782960] btrfs-transacti D 0 117 2 0x80000000#015 2018-10-03T00:15:34.169806+00:00 INFO VM(3)[22927]: [ 246.784279] Call Trace:#015 2018-10-03T00:15:34.170679+00:00 INFO VM(3)[22927]: [ 246.784910] ? __schedule+0x393/0x435#015 2018-10-03T00:15:34.171489+00:00 INFO VM(3)[22927]: [ 246.785776] ? schedule+0x59/0x78#015 2018-10-03T00:15:34.172419+00:00 INFO VM(3)[22927]: [ 246.786639] ? io_schedule+0xd/0x15#015 2018-10-03T00:15:34.173372+00:00 INFO VM(3)[22927]: [ 246.787520] ? blk_mq_get_tag+0xe9/0x1db#015 2018-10-03T00:15:34.178691+00:00 INFO VM(3)[22927]: [ 246.788472] ? init_wait_entry+0x24/0x24#015 2018-10-03T00:15:34.178826+00:00 INFO VM(3)[22927]: [ 246.789375] ? blk_mq_get_request+0xe5/0x356#015 2018-10-03T00:15:34.178914+00:00 INFO VM(3)[22927]: [ 246.790277] ? blk_mq_make_request+0xe2/0x349#015 2018-10-03T00:15:34.178999+00:00 INFO VM(3)[22927]: [ 246.791216] ? generic_make_request+0xd0/0x213#015 2018-10-03T00:15:34.179082+00:00 INFO VM(3)[22927]: [ 246.792285] ? submit_bio+0x8f/0x104#015 2018-10-03T00:15:34.179169+00:00 INFO VM(3)[22927]: [ 246.793088] ? btrfs_bio_counter_inc_blocked+0x90/0xaa#015 2018-10-03T00:15:34.180754+00:00 INFO VM(3)[22927]: [ 246.794222] ? __unlock_for_delalloc+0x24/0x24#015 2018-10-03T00:15:34.184756+00:00 INFO VM(3)[22927]: [ 246.795260] ? btrfs_map_bio+0x28e/0x2e9#015 2018-10-03T00:15:34.184877+00:00 INFO VM(3)[22927]: [ 246.797028] ? btrfs_submit_bio_hook+0xc3/0x113#015 2018-10-03T00:15:34.184963+00:00 INFO VM(3)[22927]: [ 246.797985] ? submit_one_bio+0x58/0x79#015 2018-10-03T00:15:34.185046+00:00 INFO VM(3)[22927]: [ 246.798909] ? flush_epd_write_bio+0x17/0x25#015 2018-10-03T00:15:34.185762+00:00 INFO VM(3)[22927]: [ 246.799839] ? extent_writepages+0x2d5/0x2e9#015 2018-10-03T00:15:34.186675+00:00 INFO VM(3)[22927]: [ 246.800762] ? btrfs_cont_expand+0x48c/0x48c#015 2018-10-03T00:15:34.187748+00:00 INFO VM(3)[22927]: [ 246.801749] ? _raw_spin_lock_bh+0xa/0x11#015 2018-10-03T00:15:34.188748+00:00 INFO VM(3)[22927]: [ 246.802675] ? do_writepages+0x59/0x74#015 2018-10-03T00:15:34.189744+00:00 INFO VM(3)[22927]: [ 246.803549] ? __filemap_fdatawrite_range+0xa8/0xbe#015 2018-10-03T00:15:34.190619+00:00 INFO VM(3)[22927]: [ 246.804640] ? btrfs_fdatawrite_range+0x17/0x43#015 2018-10-03T00:15:34.191793+00:00 INFO VM(3)[22927]: [ 246.805717] ? __btrfs_write_out_cache+0x35b/0x378#015 2018-10-03T00:15:34.192865+00:00 INFO VM(3)[22927]: [ 246.806894] ? btrfs_write_out_cache+0x86/0xce#015 2018-10-03T00:15:34.194171+00:00 INFO VM(3)[22927]: [ 246.807964] ? btrfs_start_dirty_block_groups+0x199/0x368#015 2018-10-03T00:15:34.195419+00:00 INFO VM(3)[22927]: [ 246.809274] ? btrfs_commit_transaction+0x3f2/0x9ce#015 2018-10-03T00:15:34.196392+00:00 INFO VM(3)[22927]: [ 246.810520] ? _raw_spin_unlock+0x6/0x23#015 2018-10-03T00:15:34.197407+00:00 INFO VM(3)[22927]: [ 246.811494] ? join_transaction+0x370/0x37c#015 2018-10-03T00:15:34.198414+00:00 INFO VM(3)[22927]: [ 246.812506] ? start_transaction+0x83/0x31b#015 2018-10-03T00:15:34.199464+00:00 INFO VM(3)[22927]: [ 246.813514] ? transaction_kthread+0xce/0x17d#015 2018-10-03T00:15:34.200456+00:00 INFO VM(3)[22927]: [ 246.814565] ? cleaner_kthread+0x151/0x151#015 2018-10-03T00:15:34.201258+00:00 INFO VM(3)[22927]: [ 246.815558] ? kthread+0xe6/0xf6#015 2018-10-03T00:15:34.202247+00:00 INFO VM(3)[22927]: [ 246.816359] ? cleaner_kthread+0x151/0x151#015 2018-10-03T00:15:34.203343+00:00 INFO VM(3)[22927]: [ 246.817349] ? kthread_destroy_worker+0x3e/0x3e#015 2018-10-03T00:15:34.204293+00:00 INFO VM(3)[22927]: [ 246.818444] ? ret_from_fork+0x35/0x40#015 2018-10-03T00:15:34.205618+00:00 INFO VM(3)[22927]: [ 246.819402] kworker/u4:4 D 0 195 2 0x80000000#015 2018-10-03T00:15:34.206987+00:00 INFO VM(3)[22927]: [ 246.820732] Workqueue: writeback wb_workfn (flush-btrfs-2)#015 2018-10-03T00:15:34.210749+00:00 INFO VM(3)[22927]: [ 246.822084] Call Trace:#015 2018-10-03T00:15:34.210865+00:00 INFO VM(3)[22927]: [ 246.822659] ? __schedule+0x393/0x435#015 2018-10-03T00:15:34.211743+00:00 INFO VM(3)[22927]: [ 246.823455] ? schedule+0x59/0x78#015 2018-10-03T00:15:34.211838+00:00 INFO VM(3)[22927]: [ 246.824172] ? io_schedule+0xd/0x15#015 2018-10-03T00:15:34.211927+00:00 INFO VM(3)[22927]: [ 246.825016] ? blk_mq_get_tag+0xe9/0x1db#015 2018-10-03T00:15:34.212010+00:00 INFO VM(3)[22927]: [ 246.825892] ? init_wait_entry+0x24/0x24#015 2018-10-03T00:15:34.212742+00:00 INFO VM(3)[22927]: [ 246.826770] ? blk_mq_get_request+0xe5/0x356#015 2018-10-03T00:15:34.213742+00:00 INFO VM(3)[22927]: [ 246.827752] ? blk_mq_make_request+0xe2/0x349#015 2018-10-03T00:15:34.214735+00:00 INFO VM(3)[22927]: [ 246.828740] ? generic_make_request+0xd0/0x213#015 2018-10-03T00:15:34.215601+00:00 INFO VM(3)[22927]: [ 246.829864] ? submit_bio+0x8f/0x104#015 2018-10-03T00:15:34.216552+00:00 INFO VM(3)[22927]: [ 246.830696] ? btrfs_map_bio+0x28e/0x2e9#015 2018-10-03T00:15:34.217630+00:00 INFO VM(3)[22927]: [ 246.831654] ? btree_submit_bio_hook+0x8d/0xac#015 2018-10-03T00:15:34.218558+00:00 INFO VM(3)[22927]: [ 246.832732] ? submit_one_bio+0x58/0x79#015 2018-10-03T00:15:34.219613+00:00 INFO VM(3)[22927]: [ 246.833661] ? submit_extent_page+0x118/0x20f#015 2018-10-03T00:15:34.220649+00:00 INFO VM(3)[22927]: [ 246.834720] ? wbc_to_write_flags+0x19/0x19#015 2018-10-03T00:15:34.221740+00:00 INFO VM(3)[22927]: [ 246.835732] ? write_one_eb+0x199/0x25e#015 2018-10-03T00:15:34.223215+00:00 INFO VM(3)[22927]: [ 246.836589] ? wbc_to_write_flags+0x19/0x19#015 2018-10-03T00:15:34.223516+00:00 INFO VM(3)[22927]: [ 246.837526] ? btree_write_cache_pages+0x214/0x2e1#015 2018-10-03T00:15:34.224465+00:00 INFO VM(3)[22927]: [ 246.838621] ? do_writepages+0x59/0x74#015 2018-10-03T00:15:34.225637+00:00 INFO VM(3)[22927]: [ 246.839577] ? __writeback_single_inode+0x2c/0x16b#015 2018-10-03T00:15:34.226839+00:00 INFO VM(3)[22927]: [ 246.840738] ? writeback_sb_inodes+0x212/0x3f3#015 2018-10-03T00:15:34.228743+00:00 INFO VM(3)[22927]: [ 246.841935] ? wb_writeback+0xec/0x178#015 2018-10-03T00:15:34.228847+00:00 INFO VM(3)[22927]: [ 246.842767] ? wb_workfn+0x95/0x296#015 2018-10-03T00:15:34.229738+00:00 INFO VM(3)[22927]: [ 246.843551] ? __switch_to_asm+0x24/0x60#015 2018-10-03T00:15:34.230738+00:00 INFO VM(3)[22927]: [ 246.844442] ? __switch_to_asm+0x30/0x60#015 2018-10-03T00:15:34.231739+00:00 INFO VM(3)[22927]: [ 246.845329] ? __switch_to_asm+0x24/0x60#015 2018-10-03T00:15:34.232031+00:00 INFO VM(3)[22927]: [ 246.846221] ? __switch_to_asm+0x30/0x60#015 2018-10-03T00:15:34.233016+00:00 INFO VM(3)[22927]: [ 246.847132] ? __switch_to_asm+0x24/0x60#015 2018-10-03T00:15:34.234085+00:00 INFO VM(3)[22927]: [ 246.848116] ? _raw_spin_unlock_irq+0xb/0x28#015 2018-10-03T00:15:34.235126+00:00 INFO VM(3)[22927]: [ 246.849188] ? process_one_work+0x10b/0x209#015 2018-10-03T00:15:34.236119+00:00 INFO VM(3)[22927]: [ 246.850226] ? worker_thread+0x197/0x25e#015 2018-10-03T00:15:34.237032+00:00 INFO VM(3)[22927]: [ 246.851217] ? pr_cont_work+0x4d/0x4d#015 2018-10-03T00:15:34.237829+00:00 INFO VM(3)[22927]: [ 246.852133] ? kthread+0xe6/0xf6#015 2018-10-03T00:15:34.238694+00:00 INFO VM(3)[22927]: [ 246.852928] ? pr_cont_work+0x4d/0x4d#015 2018-10-03T00:15:34.239821+00:00 INFO VM(3)[22927]: [ 246.853790] ? kthread_destroy_worker+0x3e/0x3e#015 2018-10-03T00:15:34.240719+00:00 INFO VM(3)[22927]: [ 246.854923] ? ret_from_fork+0x35/0x40#015 2018-10-03T00:15:34.242055+00:00 INFO VM(3)[22927]: [ 246.855840] kworker/u4:5 D 0 196 2 0x80000000#015 2018-10-03T00:15:34.243673+00:00 INFO VM(3)[22927]: [ 246.857159] Workqueue: events_unbound btrfs_async_reclaim_metadata_space#015 2018-10-03T00:15:34.244323+00:00 INFO VM(3)[22927]: [ 246.858773] Call Trace:#015 2018-10-03T00:15:34.245227+00:00 INFO VM(3)[22927]: [ 246.859428] ? __schedule+0x393/0x435#015 2018-10-03T00:15:34.246057+00:00 INFO VM(3)[22927]: [ 246.860329] ? schedule+0x59/0x78#015 2018-10-03T00:15:34.247150+00:00 INFO VM(3)[22927]: [ 246.861157] ? wb_wait_for_completion+0x49/0x71#015 2018-10-03T00:15:34.248117+00:00 INFO VM(3)[22927]: [ 246.862251] ? init_wait_entry+0x24/0x24#015 2018-10-03T00:15:34.249241+00:00 INFO VM(3)[22927]: [ 246.863218] ? __writeback_inodes_sb_nr+0x7e/0x8f#015 2018-10-03T00:15:34.250167+00:00 INFO VM(3)[22927]: [ 246.864343] ? flush_space+0x17f/0x477#015 2018-10-03T00:15:34.251335+00:00 INFO VM(3)[22927]: [ 246.865270] ? __btrfs_end_transaction+0x21d/0x25b#015 2018-10-03T00:15:34.255717+00:00 INFO VM(3)[22927]: [ 246.866436] ? btrfs_async_reclaim_metadata_space+0x7e/0x17d#015 2018-10-03T00:15:34.255834+00:00 INFO VM(3)[22927]: [ 246.867804] ? process_one_work+0x10b/0x209#015 2018-10-03T00:15:34.256738+00:00 INFO VM(3)[22927]: [ 246.868690] ? worker_thread+0x197/0x25e#015 2018-10-03T00:15:34.256835+00:00 INFO VM(3)[22927]: [ 246.869543] ? pr_cont_work+0x4d/0x4d#015 2018-10-03T00:15:34.256923+00:00 INFO VM(3)[22927]: [ 246.870326] ? kthread+0xe6/0xf6#015 2018-10-03T00:15:34.257007+00:00 INFO VM(3)[22927]: [ 246.871150] ? pr_cont_work+0x4d/0x4d#015 2018-10-03T00:15:34.258718+00:00 INFO VM(3)[22927]: [ 246.871987] ? kthread_destroy_worker+0x3e/0x3e#015 2018-10-03T00:15:34.258821+00:00 INFO VM(3)[22927]: [ 246.873028] ? ret_from_fork+0x35/0x40#015 2018-10-03T00:15:34.260106+00:00 INFO VM(3)[22927]: [ 246.873869] unsquashfs D 0 204 144 0x00000000#015 2018-10-03T00:15:34.260720+00:00 INFO VM(3)[22927]: [ 246.875205] Call Trace:#015 2018-10-03T00:15:34.261632+00:00 INFO VM(3)[22927]: [ 246.875849] ? __schedule+0x393/0x435#015 2018-10-03T00:15:34.262432+00:00 INFO VM(3)[22927]: [ 246.876721] ? schedule+0x59/0x78#015 2018-10-03T00:15:34.263570+00:00 INFO VM(3)[22927]: [ 246.877536] ? reserve_metadata_bytes+0x232/0x349#015 2018-10-03T00:15:34.264551+00:00 INFO VM(3)[22927]: [ 246.878673] ? init_wait_entry+0x24/0x24#015 2018-10-03T00:15:34.265599+00:00 INFO VM(3)[22927]: [ 246.879654] ? btrfs_block_rsv_add+0x1b/0x33#015 2018-10-03T00:15:34.266967+00:00 INFO VM(3)[22927]: [ 246.880713] ? btrfs_delalloc_reserve_metadata+0x19d/0x2ec#015 2018-10-03T00:15:34.268105+00:00 INFO VM(3)[22927]: [ 246.882068] ? __btrfs_buffered_write+0x228/0x66d#015 2018-10-03T00:15:34.269263+00:00 INFO VM(3)[22927]: [ 246.883208] ? dentry_needs_remove_privs+0x23/0x39#015 2018-10-03T00:15:34.272718+00:00 INFO VM(3)[22927]: [ 246.884365] ? btrfs_file_write_iter+0x285/0x436#015 2018-10-03T00:15:34.272853+00:00 INFO VM(3)[22927]: [ 246.885438] ? __vfs_write+0x96/0xc3#015 2018-10-03T00:15:34.272943+00:00 INFO VM(3)[22927]: [ 246.886309] ? vfs_write+0xa1/0xcd#015 2018-10-03T00:15:34.273030+00:00 INFO VM(3)[22927]: [ 246.887214] ? SyS_write+0x38/0x69#015 2018-10-03T00:15:34.273919+00:00 INFO VM(3)[22927]: [ 246.888090] ? do_syscall_64+0x6a/0x7b#015 2018-10-03T00:15:34.275220+00:00 INFO VM(3)[22927]: [ 246.889020] ? entry_SYSCALL_64_after_hwframe+0x3d/0xa2#015 Case #3 https://stainless.corp.google.com/browse/chromeos-autotest-results/244516408-chromeos-test/ 2018-10-02T23:22:34.225327+00:00 INFO VM(4)[24248]: [ 369.631174] INFO: task kworker/u4:0:5 blocked for more than 120 seconds.#015 2018-10-02T23:22:34.230364+00:00 INFO VM(4)[24248]: [ 369.632419] Tainted: G W 4.14.71-07583-g022708b4bb18 #1#015 2018-10-02T23:22:34.230377+00:00 INFO VM(4)[24248]: [ 369.635345] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.#015 2018-10-02T23:22:34.230731+00:00 INFO VM(4)[24248]: [ 369.636639] kworker/u4:0 D 0 5 2 0x80000000#015 2018-10-02T23:22:34.235587+00:00 INFO VM(4)[24248]: [ 369.641360] Workqueue: btrfs-submit btrfs_submit_helper#015 2018-10-02T23:22:34.238384+00:00 INFO VM(4)[24248]: [ 369.642690] Call Trace:#015 2018-10-02T23:22:34.239092+00:00 INFO VM(4)[24248]: [ 369.645502] ? __schedule+0x393/0x435#015 2018-10-02T23:22:34.239801+00:00 INFO VM(4)[24248]: [ 369.646187] ? schedule+0x59/0x78#015 2018-10-02T23:22:34.241284+00:00 INFO VM(4)[24248]: [ 369.646901] ? io_schedule+0xd/0x15#015 2018-10-02T23:22:34.241295+00:00 INFO VM(4)[24248]: [ 369.647571] ? blk_mq_get_tag+0xe9/0x1db#015 2018-10-02T23:22:34.245119+00:00 INFO VM(4)[24248]: [ 369.648255] ? init_wait_entry+0x24/0x24#015 2018-10-02T23:22:34.245796+00:00 INFO VM(4)[24248]: [ 369.652217] ? blk_mq_get_request+0xe5/0x356#015 2018-10-02T23:22:34.246475+00:00 INFO VM(4)[24248]: [ 369.652883] ? _raw_spin_unlock+0x6/0x23#015 2018-10-02T23:22:34.247169+00:00 INFO VM(4)[24248]: [ 369.653573] ? blk_mq_make_request+0xe2/0x349#015 2018-10-02T23:22:34.247879+00:00 INFO VM(4)[24248]: [ 369.654265] ? generic_make_request+0xd0/0x213#015 2018-10-02T23:22:34.248453+00:00 INFO VM(4)[24248]: [ 369.654969] ? submit_bio+0x8f/0x104#015 2018-10-02T23:22:34.249147+00:00 INFO VM(4)[24248]: [ 369.655552] ? run_scheduled_bios+0x1b7/0x43a#015 2018-10-02T23:22:34.249829+00:00 INFO VM(4)[24248]: [ 369.656243] ? normal_work_helper+0xc6/0x188#015 2018-10-02T23:22:34.250490+00:00 INFO VM(4)[24248]: [ 369.656918] ? process_one_work+0x10b/0x209#015 2018-10-02T23:22:34.251118+00:00 INFO VM(4)[24248]: [ 369.657588] ? worker_thread+0x197/0x25e#015 2018-10-02T23:22:34.251709+00:00 INFO VM(4)[24248]: [ 369.658214] ? pr_cont_work+0x4d/0x4d#015 2018-10-02T23:22:34.252232+00:00 INFO VM(4)[24248]: [ 369.658799] ? kthread+0xe6/0xf6#015 2018-10-02T23:22:34.252823+00:00 INFO VM(4)[24248]: [ 369.659328] ? pr_cont_work+0x4d/0x4d#015 2018-10-02T23:22:34.256110+00:00 INFO VM(4)[24248]: [ 369.659907] ? kthread_destroy_worker+0x3e/0x3e#015 2018-10-02T23:22:34.256120+00:00 INFO VM(4)[24248]: [ 369.660643] ? ret_from_fork+0x35/0x40#015 2018-10-02T23:22:34.256127+00:00 INFO VM(4)[24248]: [ 369.661193] task PC stack pid father#015 2018-10-02T23:22:34.256134+00:00 INFO VM(4)[24248]: [ 369.662069] kworker/u4:0 D 0 5 2 0x80000000#015 2018-10-02T23:22:34.259477+00:00 INFO VM(4)[24248]: [ 369.662865] Workqueue: btrfs-submit btrfs_submit_helper#015 2018-10-02T23:22:34.259890+00:00 INFO VM(4)[24248]: [ 369.666582] Call Trace:#015 2018-10-02T23:22:34.260484+00:00 INFO VM(4)[24248]: [ 369.666982] ? __schedule+0x393/0x435#015 2018-10-02T23:22:34.261021+00:00 INFO VM(4)[24248]: [ 369.667582] ? schedule+0x59/0x78#015 2018-10-02T23:22:34.261593+00:00 INFO VM(4)[24248]: [ 369.668118] ? io_schedule+0xd/0x15#015 2018-10-02T23:22:34.262282+00:00 INFO VM(4)[24248]: [ 369.668682] ? blk_mq_get_tag+0xe9/0x1db#015 2018-10-02T23:22:34.262912+00:00 INFO VM(4)[24248]: [ 369.669385] ? init_wait_entry+0x24/0x24#015 2018-10-02T23:22:34.263597+00:00 INFO VM(4)[24248]: [ 369.670005] ? blk_mq_get_request+0xe5/0x356#015 2018-10-02T23:22:34.267021+00:00 INFO VM(4)[24248]: [ 369.670686] ? _raw_spin_unlock+0x6/0x23#015 2018-10-02T23:22:34.267725+00:00 INFO VM(4)[24248]: [ 369.674122] ? blk_mq_make_request+0xe2/0x349#015 2018-10-02T23:22:34.268665+00:00 INFO VM(4)[24248]: [ 369.674811] ? generic_make_request+0xd0/0x213#015 2018-10-02T23:22:34.273736+00:00 INFO VM(4)[24248]: [ 369.675792] ? submit_bio+0x8f/0x104#015 2018-10-02T23:22:34.274467+00:00 INFO VM(4)[24248]: [ 369.680835] ? run_scheduled_bios+0x1b7/0x43a#015 2018-10-02T23:22:34.275142+00:00 INFO VM(4)[24248]: [ 369.681563] ? normal_work_helper+0xc6/0x188#015 2018-10-02T23:22:34.275807+00:00 INFO VM(4)[24248]: [ 369.682240] ? process_one_work+0x10b/0x209#015 2018-10-02T23:22:34.276433+00:00 INFO VM(4)[24248]: [ 369.682896] ? worker_thread+0x197/0x25e#015 2018-10-02T23:22:34.277203+00:00 INFO VM(4)[24248]: [ 369.683530] ? pr_cont_work+0x4d/0x4d#015 2018-10-02T23:22:34.277924+00:00 INFO VM(4)[24248]: [ 369.684331] ? kthread+0xe6/0xf6#015 2018-10-02T23:22:34.278787+00:00 INFO VM(4)[24248]: [ 369.685049] ? pr_cont_work+0x4d/0x4d#015 2018-10-02T23:22:34.279754+00:00 INFO VM(4)[24248]: [ 369.685901] ? kthread_destroy_worker+0x3e/0x3e#015 2018-10-02T23:22:34.280444+00:00 INFO VM(4)[24248]: [ 369.686880] ? ret_from_fork+0x35/0x40#015 2018-10-02T23:22:34.281369+00:00 INFO VM(4)[24248]: [ 369.687553] btrfs-transacti D 0 117 2 0x80000000#015 2018-10-02T23:22:34.281768+00:00 INFO VM(4)[24248]: [ 369.688464] Call Trace:#015 2018-10-02T23:22:34.282349+00:00 INFO VM(4)[24248]: [ 369.688859] ? __schedule+0x393/0x435#015 2018-10-02T23:22:34.282869+00:00 INFO VM(4)[24248]: [ 369.689446] ? schedule+0x59/0x78#015 2018-10-02T23:22:34.283429+00:00 INFO VM(4)[24248]: [ 369.689958] ? io_schedule+0xd/0x15#015 2018-10-02T23:22:34.284051+00:00 INFO VM(4)[24248]: [ 369.690527] ? blk_mq_get_tag+0xe9/0x1db#015 2018-10-02T23:22:34.284841+00:00 INFO VM(4)[24248]: [ 369.691146] ? init_wait_entry+0x24/0x24#015 2018-10-02T23:22:34.285768+00:00 INFO VM(4)[24248]: [ 369.691958] ? blk_mq_get_request+0xe5/0x356#015 2018-10-02T23:22:34.286717+00:00 INFO VM(4)[24248]: [ 369.692893] ? blk_mq_make_request+0xe2/0x349#015 2018-10-02T23:22:34.287677+00:00 INFO VM(4)[24248]: [ 369.693841] ? generic_make_request+0xd0/0x213#015 2018-10-02T23:22:34.288464+00:00 INFO VM(4)[24248]: [ 369.694798] ? submit_bio+0x8f/0x104#015 2018-10-02T23:22:34.289592+00:00 INFO VM(4)[24248]: [ 369.695600] ? btrfs_bio_counter_inc_blocked+0x90/0xaa#015 2018-10-02T23:22:34.290571+00:00 INFO VM(4)[24248]: [ 369.696719] ? __unlock_for_delalloc+0x24/0x24#015 2018-10-02T23:22:34.291431+00:00 INFO VM(4)[24248]: [ 369.697697] ? btrfs_map_bio+0x28e/0x2e9#015 2018-10-02T23:22:34.292424+00:00 INFO VM(4)[24248]: [ 369.698557] ? btrfs_submit_bio_hook+0xc3/0x113#015 2018-10-02T23:22:34.293272+00:00 INFO VM(4)[24248]: [ 369.699545] ? submit_one_bio+0x58/0x79#015 2018-10-02T23:22:34.294211+00:00 INFO VM(4)[24248]: [ 369.700396] ? flush_epd_write_bio+0x17/0x25#015 2018-10-02T23:22:34.295153+00:00 INFO VM(4)[24248]: [ 369.701339] ? extent_writepages+0x2d5/0x2e9#015 2018-10-02T23:22:34.296082+00:00 INFO VM(4)[24248]: [ 369.702278] ? btrfs_cont_expand+0x48c/0x48c#015 2018-10-02T23:22:34.296947+00:00 INFO VM(4)[24248]: [ 369.703203] ? _raw_spin_lock_bh+0xa/0x11#015 2018-10-02T23:22:34.297798+00:00 INFO VM(4)[24248]: [ 369.704082] ? do_writepages+0x59/0x74#015 2018-10-02T23:22:34.298854+00:00 INFO VM(4)[24248]: [ 369.704915] ? __filemap_fdatawrite_range+0xa8/0xbe#015 2018-10-02T23:22:34.299845+00:00 INFO VM(4)[24248]: [ 369.705979] ? btrfs_fdatawrite_range+0x17/0x43#015 2018-10-02T23:22:34.300893+00:00 INFO VM(4)[24248]: [ 369.706971] ? __btrfs_write_out_cache+0x35b/0x378#015 2018-10-02T23:22:34.301861+00:00 INFO VM(4)[24248]: [ 369.708019] ? btrfs_write_out_cache+0x86/0xce#015 2018-10-02T23:22:34.303019+00:00 INFO VM(4)[24248]: [ 369.708981] ? btrfs_start_dirty_block_groups+0x199/0x368#015 2018-10-02T23:22:34.304084+00:00 INFO VM(4)[24248]: [ 369.710148] ? btrfs_commit_transaction+0x3f2/0x9ce#015 2018-10-02T23:22:34.304806+00:00 INFO VM(4)[24248]: [ 369.711210] ? _raw_spin_unlock+0x6/0x23#015 2018-10-02T23:22:34.305491+00:00 INFO VM(4)[24248]: [ 369.711899] ? join_transaction+0x370/0x37c#015 2018-10-02T23:22:34.306152+00:00 INFO VM(4)[24248]: [ 369.712588] ? start_transaction+0x83/0x31b#015 2018-10-02T23:22:34.306840+00:00 INFO VM(4)[24248]: [ 369.713248] ? transaction_kthread+0xce/0x17d#015 2018-10-02T23:22:34.307558+00:00 INFO VM(4)[24248]: [ 369.713929] ? cleaner_kthread+0x151/0x151#015 2018-10-02T23:22:34.308079+00:00 INFO VM(4)[24248]: [ 369.714658] ? kthread+0xe6/0xf6#015 2018-10-02T23:22:34.308734+00:00 INFO VM(4)[24248]: [ 369.715176] ? cleaner_kthread+0x151/0x151#015 2018-10-02T23:22:34.309475+00:00 INFO VM(4)[24248]: [ 369.715823] ? kthread_destroy_worker+0x3e/0x3e#015 2018-10-02T23:22:34.310084+00:00 INFO VM(4)[24248]: [ 369.716573] ? ret_from_fork+0x35/0x40#015 2018-10-02T23:22:34.310952+00:00 INFO VM(4)[24248]: [ 369.717196] dpkg D 0 699 694 0x00000100#015 2018-10-02T23:22:34.311354+00:00 INFO VM(4)[24248]: [ 369.718046] Call Trace:#015 2018-10-02T23:22:34.311925+00:00 INFO VM(4)[24248]: [ 369.718445] ? __schedule+0x393/0x435#015 2018-10-02T23:22:34.312458+00:00 INFO VM(4)[24248]: [ 369.719024] ? schedule+0x59/0x78#015 2018-10-02T23:22:34.312995+00:00 INFO VM(4)[24248]: [ 369.719548] ? io_schedule+0xd/0x15#015 2018-10-02T23:22:34.313604+00:00 INFO VM(4)[24248]: [ 369.720091] ? blk_mq_get_tag+0xe9/0x1db#015 2018-10-02T23:22:34.314209+00:00 INFO VM(4)[24248]: [ 369.720693] ? init_wait_entry+0x24/0x24#015 2018-10-02T23:22:34.314867+00:00 INFO VM(4)[24248]: [ 369.721306] ? blk_mq_get_request+0xe5/0x356#015 2018-10-02T23:22:34.315477+00:00 INFO VM(4)[24248]: [ 369.721957] ? _raw_spin_unlock+0x6/0x23#015 2018-10-02T23:22:34.316182+00:00 INFO VM(4)[24248]: [ 369.722574] ? blk_mq_make_request+0xe2/0x349#015 2018-10-02T23:22:34.317103+00:00 INFO VM(4)[24248]: [ 369.723277] ? generic_make_request+0xd0/0x213#015 2018-10-02T23:22:34.317882+00:00 INFO VM(4)[24248]: [ 369.724227] ? submit_bio+0x8f/0x104#015 2018-10-02T23:22:34.318726+00:00 INFO VM(4)[24248]: [ 369.724996] ? btrfs_map_bio+0x28e/0x2e9#015 2018-10-02T23:22:34.319621+00:00 INFO VM(4)[24248]: [ 369.725851] ? btree_submit_bio_hook+0x8d/0xac#015 2018-10-02T23:22:34.320240+00:00 INFO VM(4)[24248]: [ 369.726719] ? submit_one_bio+0x58/0x79#015 2018-10-02T23:22:34.320925+00:00 INFO VM(4)[24248]: [ 369.727337] ? submit_extent_page+0x118/0x20f#015 2018-10-02T23:22:34.321597+00:00 INFO VM(4)[24248]: [ 369.728020] ? wbc_to_write_flags+0x19/0x19#015 2018-10-02T23:22:34.322203+00:00 INFO VM(4)[24248]: [ 369.728686] ? write_one_eb+0x199/0x25e#015 2018-10-02T23:22:34.322861+00:00 INFO VM(4)[24248]: [ 369.729301] ? wbc_to_write_flags+0x19/0x19#015 2018-10-02T23:22:34.323605+00:00 INFO VM(4)[24248]: [ 369.729951] ? btree_write_cache_pages+0x214/0x2e1#015 2018-10-02T23:22:34.324379+00:00 INFO VM(4)[24248]: [ 369.730703] ? syscall_return_via_sysret+0x1c/0x7a#015 2018-10-02T23:22:34.324993+00:00 INFO VM(4)[24248]: [ 369.731476] ? do_writepages+0x59/0x74#015 2018-10-02T23:22:34.326032+00:00 INFO VM(4)[24248]: [ 369.732090] ? __filemap_fdatawrite_range+0xa8/0xbe#015 2018-10-02T23:22:34.327103+00:00 INFO VM(4)[24248]: [ 369.733158] ? btrfs_write_marked_extents+0x73/0x101#015 2018-10-02T23:22:34.328268+00:00 INFO VM(4)[24248]: [ 369.734228] ? btrfs_write_and_wait_transaction+0x33/0x6b#015 2018-10-02T23:22:34.329341+00:00 INFO VM(4)[24248]: [ 369.735394] ? btrfs_commit_transaction+0x870/0x9ce#015 2018-10-02T23:22:34.330295+00:00 INFO VM(4)[24248]: [ 369.736467] ? _raw_spin_unlock_irq+0xb/0x28#015 2018-10-02T23:22:34.331464+00:00 INFO VM(4)[24248]: [ 369.737421] ? btrfs_lookup_first_ordered_extent+0x49/0x50#015 2018-10-02T23:22:34.332495+00:00 INFO VM(4)[24248]: [ 369.738585] ? btrfs_wait_ordered_range+0x63/0xea#015 2018-10-02T23:22:34.333400+00:00 INFO VM(4)[24248]: [ 369.739620] ? btrfs_sync_file+0x2fe/0x34c#015 2018-10-02T23:22:34.334134+00:00 INFO VM(4)[24248]: [ 369.740531] ? do_fsync+0x21/0x3b#015 2018-10-02T23:22:34.334933+00:00 INFO VM(4)[24248]: [ 369.741257] ? SyS_fsync+0x7/0xa#015 2018-10-02T23:22:34.335661+00:00 INFO VM(4)[24248]: [ 369.742068] ? do_syscall_64+0x6a/0x7b#015 2018-10-02T23:22:34.336458+00:00 INFO VM(4)[24248]: [ 369.742748] ? entry_SYSCALL_64_after_hwframe+0x3d/0xa2#015
,
Oct 4
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/platform/crosvm/+/c8986f14a8dd9f256d6faed55996d955b50ff923 commit c8986f14a8dd9f256d6faed55996d955b50ff923 Author: Daniel Verkamp <dverkamp@chromium.org> Date: Thu Oct 04 07:37:22 2018 Revert "linux: Convert all virtio devices to PCI" This reverts commit d635acbaf348c0863bc05b8f889b2fa5f8156aaa. This commit seems to be responsible for introducing hung tasks in tests, so let's revert it for now to get the tests green and debug it offline. BUG= chromium:891806 TEST=None Change-Id: I83504058baeae00909d9fb4f4bb704a144a0dfaf Signed-off-by: Daniel Verkamp <dverkamp@chromium.org> Reviewed-on: https://chromium-review.googlesource.com/1259408 Reviewed-by: Dylan Reid <dgreid@chromium.org> [modify] https://crrev.com/c8986f14a8dd9f256d6faed55996d955b50ff923/x86_64/Cargo.toml [modify] https://crrev.com/c8986f14a8dd9f256d6faed55996d955b50ff923/arch/src/lib.rs [modify] https://crrev.com/c8986f14a8dd9f256d6faed55996d955b50ff923/src/linux.rs [modify] https://crrev.com/c8986f14a8dd9f256d6faed55996d955b50ff923/Cargo.lock [modify] https://crrev.com/c8986f14a8dd9f256d6faed55996d955b50ff923/x86_64/src/lib.rs [modify] https://crrev.com/c8986f14a8dd9f256d6faed55996d955b50ff923/aarch64/src/lib.rs [modify] https://crrev.com/c8986f14a8dd9f256d6faed55996d955b50ff923/aarch64/Cargo.toml
,
Oct 10
I believe this was resolved by the virtio PCI revert - jkardatzke@, can we close this bug? (If it reoccurs when we re-land PCI, we can reopen it.)
,
Oct 10
,
Oct 18
I hate to be the bearer of bad news, but... R71-11151.6.0 - nami - vm.CrostiniStartEverything https://stainless.corp.google.com/browse/chromeos-autotest-results/249720163-chromeos-test/ 71 is running with mmio virtio devices though. So I'm not sure what the cause is.
,
Oct 18
The attached ramoops looks like it's from the host kernel (4.4.x), not the VM guest kernel, right? This might be a different issue than the original virtio PCI/BTRFS task hangs in the guest kernel.
,
Oct 18
Darn, got the wrong bug. I'll repost in the correct one once I find it. |
||||
►
Sign in to add a comment |
||||
Comment 1 by dverkamp@google.com
, Oct 3