Created attachment 253251 [details] capture of timeout backtrace messages Note: this could be a btrfs filesystem, but in a online discussion, someone suggested starting here. It appears that the common function in the hangs is blk_flush_plug_list (in the different times that I can reproduce the problem). Linux kernel: 4.9.5 (gentoo-sources) btrfs-progs: 4.5 Xen guest (xen-blkfront) - which uses blk_mq 15 Luns in the filesystem. Initially had a lockup on a 4.4.21 system during heavy IO (was performing a system backup). The 120 second blocked task occurred. I was able to set up a test environment and recreate the problem using the btrfs scrub command. The problem seems to occur when multiple luns are involved). I've turned on several "kernel hacking" settings to try to gather more information. Partial backtrace =============================== INFO: task btrfs:3268 blocked for more than 120 seconds. Tainted: G W 4.9.5-gentoo #2 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. btrfs D 0 3268 1 0x00000000 ffff88045d840000 000000000000dacd ffff8804644381c0 ffff88045612d3c0 ffff8804663d8218 ffffc90001b7f5d8 ffffffff8178c976 0000000000000246 ffffe8ff00000002 ffff8804663d8218 0000000000000000 ffff88045612d3c0 Call Trace: [<ffffffff8178c976>] ? __schedule+0x2f6/0x830 [<ffffffff8178cee1>] schedule+0x31/0x80 [<ffffffff81791156>] schedule_timeout+0x1f6/0x340 [<ffffffff814368e0>] ? blk_mq_flush_plug_list+0x120/0x130 [<ffffffff8142b4d9>] ? blk_flush_plug_list+0xc9/0x280 [<ffffffff8178c645>] io_schedule_timeout+0x65/0xa0 [<ffffffff81436ff7>] bt_get.isra.13+0x107/0x1a0 [<ffffffff810c9434>] ? sched_clock_cpu+0x84/0xa0 [<ffffffff810dd5b0>] ? wake_up_bit+0x30/0x30 [<ffffffff81437162>] blk_mq_get_tag+0x22/0x90 [<ffffffff81432edb>] __blk_mq_alloc_request+0x1b/0x220 [<ffffffff8143341b>] blk_mq_map_request+0x10b/0x1b0 [<ffffffff81433310>] ? blk_mq_stop_hw_queues+0x40/0x40 [<ffffffff81435f05>] blk_sq_make_request+0x95/0x280 [<ffffffff814294fc>] ? blk_queue_enter+0x9c/0x280 [<ffffffff8142947c>] ? blk_queue_enter+0x1c/0x280 [<ffffffff814298ab>] generic_make_request+0xcb/0x180 [<ffffffff814299b7>] submit_bio+0x57/0x110 [<ffffffff813c3d2d>] scrub_submit+0x2d/0x40 [<ffffffff813c3f8e>] scrub_add_page_to_rd_bio+0x24e/0x270 [<ffffffff810e988d>] ? trace_hardirqs_on+0xd/0x10 [<ffffffff813c54d7>] scrub_pages+0x1e7/0x400 [<ffffffff810e988d>] ? trace_hardirqs_on+0xd/0x10 [<ffffffff813c2768>] ? scrub_find_csum+0x138/0x150 [<ffffffff813c6d4b>] scrub_stripe+0x7fb/0x1170 [<ffffffff810c9434>] ? sched_clock_cpu+0x84/0xa0 [<ffffffff813c77cd>] scrub_chunk+0x10d/0x160 [<ffffffff813c7ac4>] scrub_enumerate_chunks+0x2a4/0x640 [<ffffffff813c99d5>] btrfs_scrub_dev+0x205/0x630 [<ffffffff810fd7fd>] ? rcu_read_lock_sched_held+0x5d/0x70 [<ffffffff811b8d03>] ? mnt_want_write_file+0x23/0x50 [<ffffffff813a2a63>] btrfs_ioctl+0x1b43/0x2700 [<ffffffff810c9434>] ? sched_clock_cpu+0x84/0xa0 [<ffffffff810c9347>] ? sched_clock_local+0x17/0x80 [<ffffffff810e5f52>] ? __lock_is_held+0x52/0x70 [<ffffffff811a890c>] do_vfs_ioctl+0x8c/0x6a0 [<ffffffff811b5371>] ? __fget+0x101/0x1f0 [<ffffffff811b5270>] ? expand_files+0x2a0/0x2a0 [<ffffffff811a8f5c>] SyS_ioctl+0x3c/0x70 [<ffffffff817928c1>] entry_SYSCALL_64_fastpath+0x1f/0xc2 Showing all locks held in the system: 3 locks held by kworker/u128:0/6: #0: ("%s-%s""btrfs", name){.+.+.+}, at: [<ffffffff810b4021>] process_one_work+0x141/0x410 #1: ((&work->normal_work)){+.+.+.}, at: [<ffffffff810b4021>] process_one_work+0x141/0x410 #2: (&fs_devs->device_list_mutex){+.+.+.}, at: [<ffffffff813cb2ff>] reada_start_machine_worker+0xaf/0x3a0 3 locks held by kworker/dying/29: #0: (&acct->lock#2){+.+.+.}, at: [<ffffffff8111fffc>] acct_process+0xfc/0x2b0 #1: (sb_writers#3){.+.+.+}, at: [<ffffffff8111f7dc>] do_acct_process+0x4bc/0x540 #2: (&sb->s_type->i_mutex_key#6){+.+.+.}, at: [<ffffffff8137dfa0>] btrfs_file_write_iter+0x60/0x5f0 3 locks held by kworker/u128:1/33: #0: ("%s-%s""btrfs", name){.+.+.+}, at: [<ffffffff810b4021>] process_one_work+0x141/0x410 #1: ((&work->normal_work)){+.+.+.}, at: [<ffffffff810b4021>] process_one_work+0x141/0x410 #2: (&fs_devs->device_list_mutex){+.+.+.}, at: [<ffffffff813cb2ff>] reada_start_machine_worker+0xaf/0x3a0 3 locks held by kworker/u128:3/127: #0: ("%s-%s""btrfs", name){.+.+.+}, at: [<ffffffff810b4021>] process_one_work+0x141/0x410 #1: ((&work->normal_work)){+.+.+.}, at: [<ffffffff810b4021>] process_one_work+0x141/0x410 #2: (&fs_devs->device_list_mutex){+.+.+.}, at: [<ffffffff813cb2ff>] reada_start_machine_worker+0xaf/0x3a0 2 locks held by khungtaskd/303: #0: (rcu_read_lock){......}, at: [<ffffffff81133d80>] watchdog+0xa0/0x470 #1: (tasklist_lock){.+.+..}, at: [<ffffffff810e77cf>] debug_show_all_locks+0x3f/0x1b0 3 locks held by btrfs-transacti/1164: #0: (&fs_info->transaction_kthread_mutex){+.+...}, at: [<ffffffff813609d4>] transaction_kthread+0x54/0x1e0 #1: (&fs_info->reloc_mutex){+.+...}, at: [<ffffffff81366172>] btrfs_commit_transaction.part.25+0x352/0xa00 #2: (&fs_info->tree_log_mutex){+.+...}, at: [<ffffffff81366203>] btrfs_commit_transaction.part.25+0x3e3/0xa00 1 lock held by btrfs-transacti/1740: #0: (&fs_info->transaction_kthread_mutex){+.+...}, at: [<ffffffff813609d4>] transaction_kthread+0x54/0x1e0 3 locks held by kworker/u128:5/2842: #0: ("%s-%s""btrfs", name){.+.+.+}, at: [<ffffffff810b4021>] process_one_work+0x141/0x410 #1: ((&work->normal_work)){+.+.+.}, at: [<ffffffff810b4021>] process_one_work+0x141/0x410 #2: (&fs_devs->device_list_mutex){+.+.+.}, at: [<ffffffff813cb2ff>] reada_start_machine_worker+0xaf/0x3a0 1 lock held by btrfs/3268: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3269: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3270: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3271: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3272: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3273: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3274: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3275: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3276: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3277: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3278: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3279: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3280: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3281: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3282: #0: (sb_writers#3){.+.+.+}, at: [<ffffffff811b8d03>] mnt_want_write_file+0x23/0x50 1 lock held by btrfs/3283: #0: (&fs_devs->device_list_mutex){+.+.+.}, at: [<ffffffff813ca0db>] btrfs_scrub_progress+0x2b/0x150 3 locks held by kworker/u128:6/3284: #0: ("%s-%s""btrfs", name){.+.+.+}, at: [<ffffffff810b4021>] process_one_work+0x141/0x410 #1: ((&work->normal_work)){+.+.+.}, at: [<ffffffff810b4021>] process_one_work+0x141/0x410 #2: (&fs_devs->device_list_mutex){+.+.+.}, at: [<ffffffff813cb2ff>] reada_start_machine_worker+0xaf/0x3a0 3 locks held by kworker/u128:10/3288: #0: ("%s-%s""btrfs", name){.+.+.+}, at: [<ffffffff810b4021>] process_one_work+0x141/0x410 #1: ((&work->normal_work)){+.+.+.}, at: [<ffffffff810b4021>] process_one_work+0x141/0x410 #2: (&fs_devs->device_list_mutex){+.+.+.}, at: [<ffffffff813cb2ff>] reada_start_machine_worker+0xaf/0x3a0 1 lock held by ps/3303: #0: (&acct->lock#2){+.+.+.}, at: [<ffffffff8111fffc>] acct_process+0xfc/0x2b0 1 lock held by grep/3304: #0: (&acct->lock#2){+.+.+.}, at: [<ffffffff8111fffc>] acct_process+0xfc/0x2b0 =============================== # cat /proc/cpuinfo (4 processors, only showing first) processor : 0 vendor_id : GenuineIntel cpu family : 6 model : 63 model name : Intel(R) Xeon(R) CPU E5-2637 v3 @ 3.50GHz stepping : 2 microcode : 0x36 cpu MHz : 3500.077 cache size : 15360 KB physical id : 0 siblings : 4 core id : 0 cpu cores : 4 apicid : 0 initial apicid : 0 fpu : yes fpu_exception : yes cpuid level : 13 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx pdpe1gb rdtscp lm constant_tsc nopl eagerfpu pni pclmulqdq ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand hypervisor lahf_lm abm fsgsbase tsc_adjust bmi1 avx2 smep bmi2 invpcid xsaveopt bugs : bogomips : 7000.07 clflush size : 64 cache_alignment : 64 address sizes : 46 bits physical, 48 bits virtual power management: ---------- # btrfs fi show Label: 'ROOT' uuid: ec1fab3a-3d9c-4d09-89a8-e8ad6b5bf4e4 Total devices 1 FS bytes used 9.20GiB devid 1 size 28.98GiB used 9.78GiB path /dev/xvda3 Label: 'FTP' uuid: 7ecefe63-37f1-43d7-8bb1-a111d46c43f7 Total devices 15 FS bytes used 4.04TiB devid 2 size 250.00GiB used 247.00GiB path /dev/xvdk devid 3 size 250.00GiB used 247.00GiB path /dev/xvdl devid 4 size 500.00GiB used 496.03GiB path /dev/xvde devid 5 size 500.00GiB used 496.94GiB path /dev/xvdb devid 6 size 100.00GiB used 98.00GiB path /dev/xvdd devid 7 size 100.00GiB used 97.00GiB path /dev/xvdg devid 9 size 250.00GiB used 247.00GiB path /dev/xvdi devid 10 size 250.00GiB used 247.00GiB path /dev/xvdj devid 11 size 500.00GiB used 496.00GiB path /dev/xvdm devid 12 size 250.00GiB used 247.00GiB path /dev/xvdf devid 13 size 500.00GiB used 497.00GiB path /dev/xvdc devid 14 size 100.00GiB used 97.00GiB path /dev/xvdh devid 15 size 250.00GiB used 247.00GiB path /dev/xvdn devid 16 size 500.00GiB used 490.03GiB path /dev/xvdo devid 17 size 500.00GiB used 452.06GiB path /dev/xvdp penguint ~ # btrfs fi usage /media/FTP Overall: Device size: 4.69TiB Device unallocated: 97.94GiB Device missing: 0.00B Used: 4.05TiB Free (estimated): 647.80GiB (min: 598.83GiB) Data ratio: 1.00 Metadata ratio: 2.00 Global reserve: 512.00MiB (used: 0.00B) Data,single: Size:4.58TiB, Used:4.04TiB /dev/xvdb 494.94GiB /dev/xvdc 496.00GiB /dev/xvdd 98.00GiB /dev/xvde 495.00GiB /dev/xvdf 247.00GiB /dev/xvdg 97.00GiB /dev/xvdh 96.00GiB /dev/xvdi 247.00GiB /dev/xvdj 247.00GiB /dev/xvdk 246.00GiB /dev/xvdl 247.00GiB /dev/xvdm 496.00GiB /dev/xvdn 246.00GiB /dev/xvdo 489.00GiB /dev/xvdp 444.00GiB Metadata,RAID1: Size:8.00GiB, Used:6.76GiB /dev/xvdb 2.00GiB /dev/xvdc 1023.00MiB /dev/xvde 1.00GiB /dev/xvdh 1.00GiB /dev/xvdk 1.00GiB /dev/xvdn 1023.00MiB /dev/xvdo 1.00GiB /dev/xvdp 8.00GiB System,RAID1: Size:64.00MiB, Used:604.00KiB /dev/xvde 32.00MiB /dev/xvdo 32.00MiB /dev/xvdp 64.00MiB Unallocated: /dev/xvdb 3.06GiB /dev/xvdc 3.00GiB /dev/xvdd 2.00GiB /dev/xvde 3.97GiB /dev/xvdf 3.00GiB /dev/xvdg 3.00GiB /dev/xvdh 3.00GiB /dev/xvdi 3.00GiB /dev/xvdj 3.00GiB /dev/xvdk 3.00GiB /dev/xvdl 3.00GiB /dev/xvdm 4.00GiB /dev/xvdn 3.00GiB /dev/xvdo 9.97GiB /dev/xvdp 47.94GiB # uname -a Linux penguint 4.9.5-gentoo #2 SMP Thu Jan 26 09:40:42 MST 2017 x86_64 Intel(R) Xeon(R) CPU E5-2637 v3 @ 3.50GHz GenuineIntel GNU/Linux # equery list btrfs-progs * Searching for btrfs-progs ... [I-O] [ ] sys-fs/btrfs-progs-4.9:0/0 ==== Attached is the output of the kernel messages following the 120 second timeout. Please let me know if you need additional information. I can recreate the problem at will by performing a btrfs scrub against the FTP filesystem.
Additional information. I dropped back to a 4.0.5-gentoo kernel level and the problem doesn't seem to happen. Also I had another production lockup (this is a ftp server, and had a high load at time of the lockup). 4.4.21-gentoo kernel =========== Feb 2 15:18:03 INFO: task python2.7:31587 blocked for more than 120 seconds. Feb 2 15:18:03 Tainted: G W 4.4.21-gentoo #2 Feb 2 15:18:03 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 2 15:18:03 python2.7 D ffff88020e675000 0 31587 30085 0x00000000 Feb 2 15:18:03 ffff88020e342f00 0000000300000000 ffff88007fe44000 ffff88007fe436d0 Feb 2 15:18:03 7fffffffffffffff ffff8800ea3904c8 ffffe8ffff671080 ffff880205ffa178 Feb 2 15:18:03 ffffffff81595ed5 7fffffffffffffff ffffffff81597d29 ffffffff8131803a Feb 2 15:18:03 Call Trace: Feb 2 15:18:03 [<ffffffff81595ed5>] ? schedule+0x6c/0x79 Feb 2 15:18:03 [<ffffffff81597d29>] ? schedule_timeout+0x35/0x1b8 Feb 2 15:18:03 [<ffffffff8131803a>] ? blk_mq_flush_plug_list+0xde/0xeb Feb 2 15:18:03 [<ffffffff8130fc76>] ? blk_flush_plug_list+0xab/0x1c1 Feb 2 15:18:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:18:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:18:03 [<ffffffff813188c1>] ? bt_get+0xe9/0x17e Feb 2 15:18:03 [<ffffffff810a6192>] ? wait_woken+0x66/0x66 Feb 2 15:18:03 [<ffffffff81318a7f>] ? blk_mq_get_tag+0x2a/0x98 Feb 2 15:18:03 [<ffffffff81315606>] ? __blk_mq_alloc_request+0x10/0x1ba Feb 2 15:18:03 [<ffffffff81316c3e>] ? blk_mq_map_request.isra.48+0xf2/0x12a Feb 2 15:18:03 [<ffffffff813177e7>] ? blk_sq_make_request+0x67/0x1fe Feb 2 15:18:03 [<ffffffff8130eaa9>] ? generic_make_request+0xb4/0x153 Feb 2 15:18:03 [<ffffffff8130ec2c>] ? submit_bio+0xe4/0xed Feb 2 15:18:03 [<ffffffff8129e47f>] ? btrfs_map_bio+0x22b/0x2a8 Feb 2 15:18:03 [<ffffffff8127c33b>] ? btrfs_submit_bio_hook+0xc0/0x14b Feb 2 15:18:03 [<ffffffff8127db14>] ? btrfs_direct_IO+0x27a/0x27a Feb 2 15:18:03 [<ffffffff81291376>] ? submit_one_bio+0x65/0x84 Feb 2 15:18:03 [<ffffffff812960f0>] ? extent_readpages+0x165/0x177 Feb 2 15:18:03 [<ffffffff810efdfc>] ? __do_page_cache_readahead+0x147/0x1e7 Feb 2 15:18:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:18:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:18:03 [<ffffffff8113c66a>] ? __generic_file_splice_read+0x2cf/0x4db Feb 2 15:18:03 [<ffffffff8113b713>] ? page_cache_pipe_buf_release+0x12/0x12 Feb 2 15:18:03 [<ffffffff810079d1>] ? xen_clocksource_read+0x11/0x12 Feb 2 15:18:03 [<ffffffff8109a1fb>] ? sched_clock_local+0xc/0x6e Feb 2 15:18:03 [<ffffffff8109ed05>] ? put_prev_entity+0x60/0x59a Feb 2 15:18:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:18:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:18:03 [<ffffffff8152c0ea>] ? tcp_poll+0x15d/0x1eb Feb 2 15:18:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:18:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:18:03 [<ffffffff8113bab8>] ? splice_direct_to_actor+0xb7/0x18c Feb 2 15:18:03 [<ffffffff8113c0bb>] ? iter_file_splice_write+0x2aa/0x2aa Feb 2 15:18:03 [<ffffffff8113bc0b>] ? do_splice_direct+0x7e/0x99 Feb 2 15:18:03 [<ffffffff8111cbbf>] ? do_sendfile+0x176/0x2d2 Feb 2 15:18:03 [<ffffffff8111d3d1>] ? SyS_sendfile64+0x50/0x7c Feb 2 15:18:03 [<ffffffff8159886e>] ? entry_SYSCALL_64_fastpath+0x12/0x71 Feb 2 15:20:03 INFO: task python2.7:31587 blocked for more than 120 seconds. Feb 2 15:20:03 Tainted: G W 4.4.21-gentoo #2 Feb 2 15:20:03 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 2 15:20:03 python2.7 D ffff88020e675000 0 31587 30085 0x00000000 Feb 2 15:20:03 ffff88020e342f00 0000000300000000 ffff88007fe44000 ffff88007fe436d0 Feb 2 15:20:03 7fffffffffffffff ffff8800ea3904c8 ffffe8ffff671080 ffff880205ffa178 Feb 2 15:20:03 ffffffff81595ed5 7fffffffffffffff ffffffff81597d29 ffffffff8131803a Feb 2 15:20:03 Call Trace: Feb 2 15:20:03 [<ffffffff81595ed5>] ? schedule+0x6c/0x79 Feb 2 15:20:03 [<ffffffff81597d29>] ? schedule_timeout+0x35/0x1b8 Feb 2 15:20:03 [<ffffffff8131803a>] ? blk_mq_flush_plug_list+0xde/0xeb Feb 2 15:20:03 [<ffffffff8130fc76>] ? blk_flush_plug_list+0xab/0x1c1 Feb 2 15:20:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:20:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:20:03 [<ffffffff813188c1>] ? bt_get+0xe9/0x17e Feb 2 15:20:03 [<ffffffff810a6192>] ? wait_woken+0x66/0x66 Feb 2 15:20:03 [<ffffffff81318a7f>] ? blk_mq_get_tag+0x2a/0x98 Feb 2 15:20:03 [<ffffffff81315606>] ? __blk_mq_alloc_request+0x10/0x1ba Feb 2 15:20:03 [<ffffffff81316c3e>] ? blk_mq_map_request.isra.48+0xf2/0x12a Feb 2 15:20:03 [<ffffffff813177e7>] ? blk_sq_make_request+0x67/0x1fe Feb 2 15:20:03 [<ffffffff8130eaa9>] ? generic_make_request+0xb4/0x153 Feb 2 15:20:03 [<ffffffff8130ec2c>] ? submit_bio+0xe4/0xed Feb 2 15:20:03 [<ffffffff8129e47f>] ? btrfs_map_bio+0x22b/0x2a8 Feb 2 15:20:03 [<ffffffff8127c33b>] ? btrfs_submit_bio_hook+0xc0/0x14b Feb 2 15:20:03 [<ffffffff8127db14>] ? btrfs_direct_IO+0x27a/0x27a Feb 2 15:20:03 [<ffffffff81291376>] ? submit_one_bio+0x65/0x84 Feb 2 15:20:03 [<ffffffff812960f0>] ? extent_readpages+0x165/0x177 Feb 2 15:20:03 [<ffffffff810efdfc>] ? __do_page_cache_readahead+0x147/0x1e7 Feb 2 15:20:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:20:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:20:03 [<ffffffff8113c66a>] ? __generic_file_splice_read+0x2cf/0x4db Feb 2 15:20:03 [<ffffffff8113b713>] ? page_cache_pipe_buf_release+0x12/0x12 Feb 2 15:20:03 [<ffffffff810079d1>] ? xen_clocksource_read+0x11/0x12 Feb 2 15:20:03 [<ffffffff8109a1fb>] ? sched_clock_local+0xc/0x6e Feb 2 15:20:03 [<ffffffff8109ed05>] ? put_prev_entity+0x60/0x59a Feb 2 15:20:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:20:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:20:03 [<ffffffff8152c0ea>] ? tcp_poll+0x15d/0x1eb Feb 2 15:20:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:20:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:20:03 [<ffffffff8113bab8>] ? splice_direct_to_actor+0xb7/0x18c Feb 2 15:20:03 [<ffffffff8113c0bb>] ? iter_file_splice_write+0x2aa/0x2aa Feb 2 15:20:03 [<ffffffff8113bc0b>] ? do_splice_direct+0x7e/0x99 Feb 2 15:20:03 [<ffffffff8111cbbf>] ? do_sendfile+0x176/0x2d2 Feb 2 15:20:03 [<ffffffff8111d3d1>] ? SyS_sendfile64+0x50/0x7c Feb 2 15:20:03 [<ffffffff8159886e>] ? entry_SYSCALL_64_fastpath+0x12/0x71 Feb 2 15:22:03 INFO: task python2.7:31587 blocked for more than 120 seconds. Feb 2 15:22:03 Tainted: G W 4.4.21-gentoo #2 Feb 2 15:22:03 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 2 15:22:03 python2.7 D ffff88020e675000 0 31587 30085 0x00000000 Feb 2 15:22:03 ffff88020e342f00 0000000300000000 ffff88007fe44000 ffff88007fe436d0 Feb 2 15:22:03 7fffffffffffffff ffff8800ea3904c8 ffffe8ffff671080 ffff880205ffa178 Feb 2 15:22:03 ffffffff81595ed5 7fffffffffffffff ffffffff81597d29 ffffffff8131803a Feb 2 15:22:03 Call Trace: Feb 2 15:22:03 [<ffffffff81595ed5>] ? schedule+0x6c/0x79 Feb 2 15:22:03 [<ffffffff81597d29>] ? schedule_timeout+0x35/0x1b8 Feb 2 15:22:03 [<ffffffff8131803a>] ? blk_mq_flush_plug_list+0xde/0xeb Feb 2 15:22:03 [<ffffffff8130fc76>] ? blk_flush_plug_list+0xab/0x1c1 Feb 2 15:22:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:22:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:22:03 [<ffffffff813188c1>] ? bt_get+0xe9/0x17e Feb 2 15:22:03 [<ffffffff810a6192>] ? wait_woken+0x66/0x66 Feb 2 15:22:03 [<ffffffff81318a7f>] ? blk_mq_get_tag+0x2a/0x98 Feb 2 15:22:03 [<ffffffff81315606>] ? __blk_mq_alloc_request+0x10/0x1ba Feb 2 15:22:03 [<ffffffff81316c3e>] ? blk_mq_map_request.isra.48+0xf2/0x12a Feb 2 15:22:03 [<ffffffff813177e7>] ? blk_sq_make_request+0x67/0x1fe Feb 2 15:22:03 [<ffffffff8130eaa9>] ? generic_make_request+0xb4/0x153 Feb 2 15:22:03 [<ffffffff8130ec2c>] ? submit_bio+0xe4/0xed Feb 2 15:22:03 [<ffffffff8129e47f>] ? btrfs_map_bio+0x22b/0x2a8 Feb 2 15:22:03 [<ffffffff8127c33b>] ? btrfs_submit_bio_hook+0xc0/0x14b Feb 2 15:22:03 [<ffffffff8127db14>] ? btrfs_direct_IO+0x27a/0x27a Feb 2 15:22:03 [<ffffffff81291376>] ? submit_one_bio+0x65/0x84 Feb 2 15:22:03 [<ffffffff812960f0>] ? extent_readpages+0x165/0x177 Feb 2 15:22:03 [<ffffffff810efdfc>] ? __do_page_cache_readahead+0x147/0x1e7 Feb 2 15:22:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:22:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:22:03 [<ffffffff8113c66a>] ? __generic_file_splice_read+0x2cf/0x4db Feb 2 15:22:03 [<ffffffff8113b713>] ? page_cache_pipe_buf_release+0x12/0x12 Feb 2 15:22:03 [<ffffffff810079d1>] ? xen_clocksource_read+0x11/0x12 Feb 2 15:22:03 [<ffffffff8109a1fb>] ? sched_clock_local+0xc/0x6e Feb 2 15:22:03 [<ffffffff8109ed05>] ? put_prev_entity+0x60/0x59a Feb 2 15:22:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:22:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:22:03 [<ffffffff8152c0ea>] ? tcp_poll+0x15d/0x1eb Feb 2 15:22:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:22:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:22:03 [<ffffffff8113bab8>] ? splice_direct_to_actor+0xb7/0x18c Feb 2 15:22:03 [<ffffffff8113c0bb>] ? iter_file_splice_write+0x2aa/0x2aa Feb 2 15:22:03 [<ffffffff8113bc0b>] ? do_splice_direct+0x7e/0x99 Feb 2 15:22:03 [<ffffffff8111cbbf>] ? do_sendfile+0x176/0x2d2 Feb 2 15:22:03 [<ffffffff8111d3d1>] ? SyS_sendfile64+0x50/0x7c Feb 2 15:22:03 [<ffffffff8159886e>] ? entry_SYSCALL_64_fastpath+0x12/0x71 Feb 2 15:24:03 INFO: task python2.7:31587 blocked for more than 120 seconds. Feb 2 15:24:03 Tainted: G W 4.4.21-gentoo #2 Feb 2 15:24:03 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 2 15:24:03 python2.7 D ffff88020e675000 0 31587 30085 0x00000000 Feb 2 15:24:03 ffff88020e342f00 0000000300000000 ffff88007fe44000 ffff88007fe436d0 Feb 2 15:24:03 7fffffffffffffff ffff8800ea3904c8 ffffe8ffff671080 ffff880205ffa178 Feb 2 15:24:03 ffffffff81595ed5 7fffffffffffffff ffffffff81597d29 ffffffff8131803a Feb 2 15:24:03 Call Trace: Feb 2 15:24:03 [<ffffffff81595ed5>] ? schedule+0x6c/0x79 Feb 2 15:24:03 [<ffffffff81597d29>] ? schedule_timeout+0x35/0x1b8 Feb 2 15:24:03 [<ffffffff8131803a>] ? blk_mq_flush_plug_list+0xde/0xeb Feb 2 15:24:03 [<ffffffff8130fc76>] ? blk_flush_plug_list+0xab/0x1c1 Feb 2 15:24:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:24:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:24:03 [<ffffffff813188c1>] ? bt_get+0xe9/0x17e Feb 2 15:24:03 [<ffffffff810a6192>] ? wait_woken+0x66/0x66 Feb 2 15:24:03 [<ffffffff81318a7f>] ? blk_mq_get_tag+0x2a/0x98 Feb 2 15:24:03 [<ffffffff81315606>] ? __blk_mq_alloc_request+0x10/0x1ba Feb 2 15:24:03 [<ffffffff81316c3e>] ? blk_mq_map_request.isra.48+0xf2/0x12a Feb 2 15:24:03 [<ffffffff813177e7>] ? blk_sq_make_request+0x67/0x1fe Feb 2 15:24:03 [<ffffffff8130eaa9>] ? generic_make_request+0xb4/0x153 Feb 2 15:24:03 [<ffffffff8130ec2c>] ? submit_bio+0xe4/0xed Feb 2 15:24:03 [<ffffffff8129e47f>] ? btrfs_map_bio+0x22b/0x2a8 Feb 2 15:24:03 [<ffffffff8127c33b>] ? btrfs_submit_bio_hook+0xc0/0x14b Feb 2 15:24:03 [<ffffffff8127db14>] ? btrfs_direct_IO+0x27a/0x27a Feb 2 15:24:03 [<ffffffff81291376>] ? submit_one_bio+0x65/0x84 Feb 2 15:24:03 [<ffffffff812960f0>] ? extent_readpages+0x165/0x177 Feb 2 15:24:03 [<ffffffff810efdfc>] ? __do_page_cache_readahead+0x147/0x1e7 Feb 2 15:24:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:24:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:24:03 [<ffffffff8113c66a>] ? __generic_file_splice_read+0x2cf/0x4db Feb 2 15:24:03 [<ffffffff8113b713>] ? page_cache_pipe_buf_release+0x12/0x12 Feb 2 15:24:03 [<ffffffff810079d1>] ? xen_clocksource_read+0x11/0x12 Feb 2 15:24:03 [<ffffffff8109a1fb>] ? sched_clock_local+0xc/0x6e Feb 2 15:24:03 [<ffffffff8109ed05>] ? put_prev_entity+0x60/0x59a Feb 2 15:24:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:24:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:24:03 [<ffffffff8152c0ea>] ? tcp_poll+0x15d/0x1eb Feb 2 15:24:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:24:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:24:03 [<ffffffff8113bab8>] ? splice_direct_to_actor+0xb7/0x18c Feb 2 15:24:03 [<ffffffff8113c0bb>] ? iter_file_splice_write+0x2aa/0x2aa Feb 2 15:24:03 [<ffffffff8113bc0b>] ? do_splice_direct+0x7e/0x99 Feb 2 15:24:03 [<ffffffff8111cbbf>] ? do_sendfile+0x176/0x2d2 Feb 2 15:24:03 [<ffffffff8111d3d1>] ? SyS_sendfile64+0x50/0x7c Feb 2 15:24:03 [<ffffffff8159886e>] ? entry_SYSCALL_64_fastpath+0x12/0x71 Feb 2 15:26:03 INFO: task python2.7:31587 blocked for more than 120 seconds. Feb 2 15:26:03 Tainted: G W 4.4.21-gentoo #2 Feb 2 15:26:03 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 2 15:26:03 python2.7 D ffff88020e675000 0 31587 30085 0x00000000 Feb 2 15:26:03 ffff88020e342f00 0000000300000000 ffff88007fe44000 ffff88007fe436d0 Feb 2 15:26:03 7fffffffffffffff ffff8800ea3904c8 ffffe8ffff671080 ffff880205ffa178 Feb 2 15:26:03 ffffffff81595ed5 7fffffffffffffff ffffffff81597d29 ffffffff8131803a Feb 2 15:26:03 Call Trace: Feb 2 15:26:03 [<ffffffff81595ed5>] ? schedule+0x6c/0x79 Feb 2 15:26:03 [<ffffffff81597d29>] ? schedule_timeout+0x35/0x1b8 Feb 2 15:26:03 [<ffffffff8131803a>] ? blk_mq_flush_plug_list+0xde/0xeb Feb 2 15:26:03 [<ffffffff8130fc76>] ? blk_flush_plug_list+0xab/0x1c1 Feb 2 15:26:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:26:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:26:03 [<ffffffff813188c1>] ? bt_get+0xe9/0x17e Feb 2 15:26:03 [<ffffffff810a6192>] ? wait_woken+0x66/0x66 Feb 2 15:26:03 [<ffffffff81318a7f>] ? blk_mq_get_tag+0x2a/0x98 Feb 2 15:26:03 [<ffffffff81315606>] ? __blk_mq_alloc_request+0x10/0x1ba Feb 2 15:26:03 [<ffffffff81316c3e>] ? blk_mq_map_request.isra.48+0xf2/0x12a Feb 2 15:26:03 [<ffffffff813177e7>] ? blk_sq_make_request+0x67/0x1fe Feb 2 15:26:03 [<ffffffff8130eaa9>] ? generic_make_request+0xb4/0x153 Feb 2 15:26:03 [<ffffffff8130ec2c>] ? submit_bio+0xe4/0xed Feb 2 15:26:03 [<ffffffff8129e47f>] ? btrfs_map_bio+0x22b/0x2a8 Feb 2 15:26:03 [<ffffffff8127c33b>] ? btrfs_submit_bio_hook+0xc0/0x14b Feb 2 15:26:03 [<ffffffff8127db14>] ? btrfs_direct_IO+0x27a/0x27a Feb 2 15:26:03 [<ffffffff81291376>] ? submit_one_bio+0x65/0x84 Feb 2 15:26:03 [<ffffffff812960f0>] ? extent_readpages+0x165/0x177 Feb 2 15:26:03 [<ffffffff810efdfc>] ? __do_page_cache_readahead+0x147/0x1e7 Feb 2 15:26:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:26:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:26:03 [<ffffffff8113c66a>] ? __generic_file_splice_read+0x2cf/0x4db Feb 2 15:26:03 [<ffffffff8113b713>] ? page_cache_pipe_buf_release+0x12/0x12 Feb 2 15:26:03 [<ffffffff810079d1>] ? xen_clocksource_read+0x11/0x12 Feb 2 15:26:03 [<ffffffff8109a1fb>] ? sched_clock_local+0xc/0x6e Feb 2 15:26:03 [<ffffffff8109ed05>] ? put_prev_entity+0x60/0x59a Feb 2 15:26:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:26:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:26:03 [<ffffffff8152c0ea>] ? tcp_poll+0x15d/0x1eb Feb 2 15:26:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:26:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:26:03 [<ffffffff8113bab8>] ? splice_direct_to_actor+0xb7/0x18c Feb 2 15:26:03 [<ffffffff8113c0bb>] ? iter_file_splice_write+0x2aa/0x2aa Feb 2 15:26:03 [<ffffffff8113bc0b>] ? do_splice_direct+0x7e/0x99 Feb 2 15:26:03 [<ffffffff8111cbbf>] ? do_sendfile+0x176/0x2d2 Feb 2 15:26:03 [<ffffffff8111d3d1>] ? SyS_sendfile64+0x50/0x7c Feb 2 15:26:03 [<ffffffff8159886e>] ? entry_SYSCALL_64_fastpath+0x12/0x71 Feb 2 15:26:03 INFO: task python2.7:31679 blocked for more than 120 seconds. Feb 2 15:26:03 Tainted: G W 4.4.21-gentoo #2 Feb 2 15:26:03 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 2 15:26:03 python2.7 D ffff88020e635000 0 31679 30085 0x00000000 Feb 2 15:26:03 ffff8801fd75a700 00000001fd75a700 ffff88012d018000 ffff88012d017ae0 Feb 2 15:26:03 7fffffffffffffff ffff88012d017b80 0000000000000002 ffffffff81596462 Feb 2 15:26:03 ffffffff81595ed5 7fffffffffffffff ffffffff81597d29 ffff8800ea598880 Feb 2 15:26:03 Call Trace: Feb 2 15:26:03 [<ffffffff81596462>] ? bit_wait+0x4b/0x4b Feb 2 15:26:03 [<ffffffff81595ed5>] ? schedule+0x6c/0x79 Feb 2 15:26:03 [<ffffffff81597d29>] ? schedule_timeout+0x35/0x1b8 Feb 2 15:26:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:26:03 [<ffffffff815390c2>] ? tcp_write_xmit+0x503/0xbfb Feb 2 15:26:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:26:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:26:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:26:03 [<ffffffff81596474>] ? bit_wait_io+0x12/0x55 Feb 2 15:26:03 [<ffffffff815962fd>] ? __wait_on_bit_lock+0x42/0x83 Feb 2 15:26:03 [<ffffffff810e6aea>] ? __lock_page+0x5c/0x61 Feb 2 15:26:03 [<ffffffff810a61bc>] ? autoremove_wake_function+0x2a/0x2a Feb 2 15:26:03 [<ffffffff8113c819>] ? __generic_file_splice_read+0x47e/0x4db Feb 2 15:26:03 [<ffffffff8113b713>] ? page_cache_pipe_buf_release+0x12/0x12 Feb 2 15:26:03 [<ffffffff8109dcca>] ? dequeue_entity+0x731/0x770 Feb 2 15:26:03 [<ffffffff8109ed05>] ? put_prev_entity+0x60/0x59a Feb 2 15:26:03 [<ffffffff810079d1>] ? xen_clocksource_read+0x11/0x12 Feb 2 15:26:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:26:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:26:03 [<ffffffff8152c0ea>] ? tcp_poll+0x15d/0x1eb Feb 2 15:26:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:26:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:26:03 [<ffffffff8113bab8>] ? splice_direct_to_actor+0xb7/0x18c Feb 2 15:26:03 [<ffffffff8113c0bb>] ? iter_file_splice_write+0x2aa/0x2aa Feb 2 15:26:03 [<ffffffff8113bc0b>] ? do_splice_direct+0x7e/0x99 Feb 2 15:26:03 [<ffffffff8111cbbf>] ? do_sendfile+0x176/0x2d2 Feb 2 15:26:03 [<ffffffff8111d3d1>] ? SyS_sendfile64+0x50/0x7c Feb 2 15:26:03 [<ffffffff8159886e>] ? entry_SYSCALL_64_fastpath+0x12/0x71 Feb 2 15:28:03 INFO: task python2.7:31587 blocked for more than 120 seconds. Feb 2 15:28:03 Tainted: G W 4.4.21-gentoo #2 Feb 2 15:28:03 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 2 15:28:03 python2.7 D ffff88020e675000 0 31587 30085 0x00000000 Feb 2 15:28:03 ffff88020e342f00 0000000300000000 ffff88007fe44000 ffff88007fe436d0 Feb 2 15:28:03 7fffffffffffffff ffff8800ea3904c8 ffffe8ffff671080 ffff880205ffa178 Feb 2 15:28:03 ffffffff81595ed5 7fffffffffffffff ffffffff81597d29 ffffffff8131803a Feb 2 15:28:03 Call Trace: Feb 2 15:28:03 [<ffffffff81595ed5>] ? schedule+0x6c/0x79 Feb 2 15:28:03 [<ffffffff81597d29>] ? schedule_timeout+0x35/0x1b8 Feb 2 15:28:03 [<ffffffff8131803a>] ? blk_mq_flush_plug_list+0xde/0xeb Feb 2 15:28:03 [<ffffffff8130fc76>] ? blk_flush_plug_list+0xab/0x1c1 Feb 2 15:28:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:28:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:28:03 [<ffffffff813188c1>] ? bt_get+0xe9/0x17e Feb 2 15:28:03 [<ffffffff810a6192>] ? wait_woken+0x66/0x66 Feb 2 15:28:03 [<ffffffff81318a7f>] ? blk_mq_get_tag+0x2a/0x98 Feb 2 15:28:03 [<ffffffff81315606>] ? __blk_mq_alloc_request+0x10/0x1ba Feb 2 15:28:03 [<ffffffff81316c3e>] ? blk_mq_map_request.isra.48+0xf2/0x12a Feb 2 15:28:03 [<ffffffff813177e7>] ? blk_sq_make_request+0x67/0x1fe Feb 2 15:28:03 [<ffffffff8130eaa9>] ? generic_make_request+0xb4/0x153 Feb 2 15:28:03 [<ffffffff8130ec2c>] ? submit_bio+0xe4/0xed Feb 2 15:28:03 [<ffffffff8129e47f>] ? btrfs_map_bio+0x22b/0x2a8 Feb 2 15:28:03 [<ffffffff8127c33b>] ? btrfs_submit_bio_hook+0xc0/0x14b Feb 2 15:28:03 [<ffffffff8127db14>] ? btrfs_direct_IO+0x27a/0x27a Feb 2 15:28:03 [<ffffffff81291376>] ? submit_one_bio+0x65/0x84 Feb 2 15:28:03 [<ffffffff812960f0>] ? extent_readpages+0x165/0x177 Feb 2 15:28:03 [<ffffffff810efdfc>] ? __do_page_cache_readahead+0x147/0x1e7 Feb 2 15:28:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:28:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:28:03 [<ffffffff8113c66a>] ? __generic_file_splice_read+0x2cf/0x4db Feb 2 15:28:03 [<ffffffff8113b713>] ? page_cache_pipe_buf_release+0x12/0x12 Feb 2 15:28:03 [<ffffffff810079d1>] ? xen_clocksource_read+0x11/0x12 Feb 2 15:28:03 [<ffffffff8109a1fb>] ? sched_clock_local+0xc/0x6e Feb 2 15:28:03 [<ffffffff8109ed05>] ? put_prev_entity+0x60/0x59a Feb 2 15:28:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:28:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:28:03 [<ffffffff8152c0ea>] ? tcp_poll+0x15d/0x1eb Feb 2 15:28:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:28:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:28:03 [<ffffffff8113bab8>] ? splice_direct_to_actor+0xb7/0x18c Feb 2 15:28:03 [<ffffffff8113c0bb>] ? iter_file_splice_write+0x2aa/0x2aa Feb 2 15:28:03 [<ffffffff8113bc0b>] ? do_splice_direct+0x7e/0x99 Feb 2 15:28:03 [<ffffffff8111cbbf>] ? do_sendfile+0x176/0x2d2 Feb 2 15:28:03 [<ffffffff8111d3d1>] ? SyS_sendfile64+0x50/0x7c Feb 2 15:28:03 [<ffffffff8159886e>] ? entry_SYSCALL_64_fastpath+0x12/0x71 Feb 2 15:28:03 INFO: task python2.7:31679 blocked for more than 120 seconds. Feb 2 15:28:03 Tainted: G W 4.4.21-gentoo #2 Feb 2 15:28:03 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 2 15:28:03 python2.7 D ffff88020e635000 0 31679 30085 0x00000000 Feb 2 15:28:03 ffff8801fd75a700 00000001fd75a700 ffff88012d018000 ffff88012d017ae0 Feb 2 15:28:03 7fffffffffffffff ffff88012d017b80 0000000000000002 ffffffff81596462 Feb 2 15:28:03 ffffffff81595ed5 7fffffffffffffff ffffffff81597d29 ffff8800ea598880 Feb 2 15:28:03 Call Trace: Feb 2 15:28:03 [<ffffffff81596462>] ? bit_wait+0x4b/0x4b Feb 2 15:28:03 [<ffffffff81595ed5>] ? schedule+0x6c/0x79 Feb 2 15:28:03 [<ffffffff81597d29>] ? schedule_timeout+0x35/0x1b8 Feb 2 15:28:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:28:03 [<ffffffff815390c2>] ? tcp_write_xmit+0x503/0xbfb Feb 2 15:28:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:28:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:28:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:28:03 [<ffffffff81596474>] ? bit_wait_io+0x12/0x55 Feb 2 15:28:03 [<ffffffff815962fd>] ? __wait_on_bit_lock+0x42/0x83 Feb 2 15:28:03 [<ffffffff810e6aea>] ? __lock_page+0x5c/0x61 Feb 2 15:28:03 [<ffffffff810a61bc>] ? autoremove_wake_function+0x2a/0x2a Feb 2 15:28:03 [<ffffffff8113c819>] ? __generic_file_splice_read+0x47e/0x4db Feb 2 15:28:03 [<ffffffff8113b713>] ? page_cache_pipe_buf_release+0x12/0x12 Feb 2 15:28:03 [<ffffffff8109dcca>] ? dequeue_entity+0x731/0x770 Feb 2 15:28:03 [<ffffffff8109ed05>] ? put_prev_entity+0x60/0x59a Feb 2 15:28:03 [<ffffffff810079d1>] ? xen_clocksource_read+0x11/0x12 Feb 2 15:28:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:28:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:28:03 [<ffffffff8152c0ea>] ? tcp_poll+0x15d/0x1eb Feb 2 15:28:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:28:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:28:03 [<ffffffff8113bab8>] ? splice_direct_to_actor+0xb7/0x18c Feb 2 15:28:03 [<ffffffff8113c0bb>] ? iter_file_splice_write+0x2aa/0x2aa Feb 2 15:28:03 [<ffffffff8113bc0b>] ? do_splice_direct+0x7e/0x99 Feb 2 15:28:03 [<ffffffff8111cbbf>] ? do_sendfile+0x176/0x2d2 Feb 2 15:28:03 [<ffffffff8111d3d1>] ? SyS_sendfile64+0x50/0x7c Feb 2 15:28:03 [<ffffffff8159886e>] ? entry_SYSCALL_64_fastpath+0x12/0x71 Feb 2 15:30:03 INFO: task python2.7:31587 blocked for more than 120 seconds. Feb 2 15:30:03 Tainted: G W 4.4.21-gentoo #2 Feb 2 15:30:03 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 2 15:30:03 python2.7 D ffff88020e675000 0 31587 30085 0x00000000 Feb 2 15:30:03 ffff88020e342f00 0000000300000000 ffff88007fe44000 ffff88007fe436d0 Feb 2 15:30:03 7fffffffffffffff ffff8800ea3904c8 ffffe8ffff671080 ffff880205ffa178 Feb 2 15:30:03 ffffffff81595ed5 7fffffffffffffff ffffffff81597d29 ffffffff8131803a Feb 2 15:30:03 Call Trace: Feb 2 15:30:03 [<ffffffff81595ed5>] ? schedule+0x6c/0x79 Feb 2 15:30:03 [<ffffffff81597d29>] ? schedule_timeout+0x35/0x1b8 Feb 2 15:30:03 [<ffffffff8131803a>] ? blk_mq_flush_plug_list+0xde/0xeb Feb 2 15:30:03 [<ffffffff8130fc76>] ? blk_flush_plug_list+0xab/0x1c1 Feb 2 15:30:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:30:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:30:03 [<ffffffff813188c1>] ? bt_get+0xe9/0x17e Feb 2 15:30:03 [<ffffffff810a6192>] ? wait_woken+0x66/0x66 Feb 2 15:30:03 [<ffffffff81318a7f>] ? blk_mq_get_tag+0x2a/0x98 Feb 2 15:30:03 [<ffffffff81315606>] ? __blk_mq_alloc_request+0x10/0x1ba Feb 2 15:30:03 [<ffffffff81316c3e>] ? blk_mq_map_request.isra.48+0xf2/0x12a Feb 2 15:30:03 [<ffffffff813177e7>] ? blk_sq_make_request+0x67/0x1fe Feb 2 15:30:03 [<ffffffff8130eaa9>] ? generic_make_request+0xb4/0x153 Feb 2 15:30:03 [<ffffffff8130ec2c>] ? submit_bio+0xe4/0xed Feb 2 15:30:03 [<ffffffff8129e47f>] ? btrfs_map_bio+0x22b/0x2a8 Feb 2 15:30:03 [<ffffffff8127c33b>] ? btrfs_submit_bio_hook+0xc0/0x14b Feb 2 15:30:03 [<ffffffff8127db14>] ? btrfs_direct_IO+0x27a/0x27a Feb 2 15:30:03 [<ffffffff81291376>] ? submit_one_bio+0x65/0x84 Feb 2 15:30:03 [<ffffffff812960f0>] ? extent_readpages+0x165/0x177 Feb 2 15:30:03 [<ffffffff810efdfc>] ? __do_page_cache_readahead+0x147/0x1e7 Feb 2 15:30:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:30:03 [<ffffffff810f005d>] ? ondemand_readahead+0x1c1/0x1cf Feb 2 15:30:03 [<ffffffff8113c66a>] ? __generic_file_splice_read+0x2cf/0x4db Feb 2 15:30:03 [<ffffffff8113b713>] ? page_cache_pipe_buf_release+0x12/0x12 Feb 2 15:30:03 [<ffffffff810079d1>] ? xen_clocksource_read+0x11/0x12 Feb 2 15:30:03 [<ffffffff8109a1fb>] ? sched_clock_local+0xc/0x6e Feb 2 15:30:03 [<ffffffff8109ed05>] ? put_prev_entity+0x60/0x59a Feb 2 15:30:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:30:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:30:03 [<ffffffff8152c0ea>] ? tcp_poll+0x15d/0x1eb Feb 2 15:30:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:30:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:30:03 [<ffffffff8113bab8>] ? splice_direct_to_actor+0xb7/0x18c Feb 2 15:30:03 [<ffffffff8113c0bb>] ? iter_file_splice_write+0x2aa/0x2aa Feb 2 15:30:03 [<ffffffff8113bc0b>] ? do_splice_direct+0x7e/0x99 Feb 2 15:30:03 [<ffffffff8111cbbf>] ? do_sendfile+0x176/0x2d2 Feb 2 15:30:03 [<ffffffff8111d3d1>] ? SyS_sendfile64+0x50/0x7c Feb 2 15:30:03 [<ffffffff8159886e>] ? entry_SYSCALL_64_fastpath+0x12/0x71 Feb 2 15:30:03 INFO: task python2.7:31679 blocked for more than 120 seconds. Feb 2 15:30:03 Tainted: G W 4.4.21-gentoo #2 Feb 2 15:30:03 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 2 15:30:03 python2.7 D ffff88020e635000 0 31679 30085 0x00000000 Feb 2 15:30:03 ffff8801fd75a700 00000001fd75a700 ffff88012d018000 ffff88012d017ae0 Feb 2 15:30:03 7fffffffffffffff ffff88012d017b80 0000000000000002 ffffffff81596462 Feb 2 15:30:03 ffffffff81595ed5 7fffffffffffffff ffffffff81597d29 ffff8800ea598880 Feb 2 15:30:03 Call Trace: Feb 2 15:30:03 [<ffffffff81596462>] ? bit_wait+0x4b/0x4b Feb 2 15:30:03 [<ffffffff81595ed5>] ? schedule+0x6c/0x79 Feb 2 15:30:03 [<ffffffff81597d29>] ? schedule_timeout+0x35/0x1b8 Feb 2 15:30:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:30:03 [<ffffffff815390c2>] ? tcp_write_xmit+0x503/0xbfb Feb 2 15:30:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:30:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:30:03 [<ffffffff815957a5>] ? io_schedule_timeout+0x5d/0x85 Feb 2 15:30:03 [<ffffffff81596474>] ? bit_wait_io+0x12/0x55 Feb 2 15:30:03 [<ffffffff815962fd>] ? __wait_on_bit_lock+0x42/0x83 Feb 2 15:30:03 [<ffffffff810e6aea>] ? __lock_page+0x5c/0x61 Feb 2 15:30:03 [<ffffffff810a61bc>] ? autoremove_wake_function+0x2a/0x2a Feb 2 15:30:03 [<ffffffff8113c819>] ? __generic_file_splice_read+0x47e/0x4db Feb 2 15:30:03 [<ffffffff8113b713>] ? page_cache_pipe_buf_release+0x12/0x12 Feb 2 15:30:03 [<ffffffff8109dcca>] ? dequeue_entity+0x731/0x770 Feb 2 15:30:03 [<ffffffff8109ed05>] ? put_prev_entity+0x60/0x59a Feb 2 15:30:03 [<ffffffff810079d1>] ? xen_clocksource_read+0x11/0x12 Feb 2 15:30:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:30:03 [<ffffffff810aac61>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x1e Feb 2 15:30:03 [<ffffffff8152c0ea>] ? tcp_poll+0x15d/0x1eb Feb 2 15:30:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:30:03 [<ffffffff8113c8aa>] ? generic_file_splice_read+0x34/0x56 Feb 2 15:30:03 [<ffffffff8113bab8>] ? splice_direct_to_actor+0xb7/0x18c Feb 2 15:30:03 [<ffffffff8113c0bb>] ? iter_file_splice_write+0x2aa/0x2aa Feb 2 15:30:03 [<ffffffff8113bc0b>] ? do_splice_direct+0x7e/0x99 Feb 2 15:30:03 [<ffffffff8111cbbf>] ? do_sendfile+0x176/0x2d2 Feb 2 15:30:03 [<ffffffff8111d3d1>] ? SyS_sendfile64+0x50/0x7c Feb 2 15:30:03 [<ffffffff8159886e>] ? entry_SYSCALL_64_fastpath+0x12/0x71
Just tried a 4.10.1 kernel. Still getting same hang (attaching console backtrace) If this is the wrong component, could someone suggest a better place to report this?
Created attachment 255119 [details] console backtrace from 4.10.1 system
Kernel 4.9.18-rt-rt14 (PREEMPT_RT), same problem [57681.201181] ============================================= [58008.905418] INFO: task btrfs-transacti:4943 blocked for more than 300 seconds. [58008.905422] Not tainted 4.9.18-rt-rt14-xeon #4 [58008.905423] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [58008.905425] btrfs-transacti D 0 4943 2 0x00080000 [58008.905430] ffff8807f741d780 ffff8807fd2a2f00 000000000000489c ffff8807f9725e00 [58008.905436] ffff88082f319458 ffffc9001f66fd70 ffffffff8174c892 ffff88082f319458 [58008.905441] ffff8807f9725e00 ffff8807f9725e00 ffffc9001f66fda0 ffff8807f93b1980 [58008.905446] Call Trace: [58008.905453] [<ffffffff8174c892>] ? __schedule+0x1d2/0x550 [58008.905456] [<ffffffff8174cc57>] schedule+0x47/0xd0 [58008.905461] [<ffffffff812fd88f>] btrfs_commit_transaction.part.25+0x90f/0xa00 [58008.905464] [<ffffffff8109fd90>] ? wake_up_bit+0x30/0x30 [58008.905466] [<ffffffff812fd9b5>] btrfs_commit_transaction+0x35/0x60 [58008.905468] [<ffffffff812f76e9>] transaction_kthread+0x1a9/0x1e0 [58008.905470] [<ffffffff812f7540>] ? btrfs_cleanup_transaction+0x520/0x520 [58008.905472] [<ffffffff810026a5>] ? do_syscall_64+0x75/0x190 [58008.905475] [<ffffffff8107b1ef>] kthread+0xef/0x110 [58008.905478] [<ffffffff8107b100>] ? kthread_create_on_node+0x60/0x60 [58008.905481] [<ffffffff817508d2>] ret_from_fork+0x22/0x30 [58008.905482] Showing all locks held in the system: [58008.905486] 2 locks held by khungtaskd/304: [58008.905487] #0: (rcu_read_lock){......}, at: [<ffffffff81100a0d>] watchdog+0x9d/0x380 [58008.905493] #1: (tasklist_lock){......}, at: [<ffffffff810a483f>] debug_show_all_locks+0x3f/0x1b0 [58008.905503] 2 locks held by btrfs-cleaner/4942: [58008.905504] #0: (&fs_info->cleaner_mutex){......}, at: [<ffffffff812f2fef>] cleaner_kthread+0x8f/0x1b0 [58008.905511] #1: (sb_internal){......}, at: [<ffffffff812fdcae>] start_transaction+0x2ce/0x430 [58008.905517] 1 lock held by btrfs-transacti/4943: [58008.905518] #0: (&fs_info->transaction_kthread_mutex){......}, at: [<ffffffff812f7595>] transaction_kthread+0x55/0x1e0 [58008.905529] 1 lock held by qemu-system-x86/6886: [58008.905530] #0: (&vcpu->mutex){......}, at: [<ffffffffa0379115>] vcpu_load+0x15/0x90 [kvm] [58008.905550] 1 lock held by qemu-system-x86/6889: [58008.905551] #0: (&vcpu->mutex){......}, at: [<ffffffffa0379115>] vcpu_load+0x15/0x90 [kvm] [58008.905569] 1 lock held by qemu-system-x86/6892: [58008.905570] #0: (&vcpu->mutex){......}, at: [<ffffffffa0379115>] vcpu_load+0x15/0x90 [kvm] [58008.905584] 1 lock held by qemu-system-x86/6893: [58008.905584] #0: (&vcpu->mutex){......}, at: [<ffffffffa0379115>] vcpu_load+0x15/0x90 [kvm] [58008.905604] 1 lock held by qemu-system-x86/6912: [58008.905604] #0: (&vcpu->mutex){......}, at: [<ffffffffa0379115>] vcpu_load+0x15/0x90 [kvm] [58008.905613] 1 lock held by qemu-system-x86/6913: [58008.905614] #0: (&vcpu->mutex){......}, at: [<ffffffffa0379115>] vcpu_load+0x15/0x90 [kvm] [58008.905626] 1 lock held by qemu-system-x86/6914: [58008.905627] #0: (&vcpu->mutex){......}, at: [<ffffffffa0379115>] vcpu_load+0x15/0x90 [kvm] [58008.905640] 1 lock held by qemu-system-x86/6915: [58008.905641] #0: (&vcpu->mutex){......}, at: [<ffffffffa0379115>] vcpu_load+0x15/0x90 [kvm] [58008.905655] 1 lock held by qemu-system-x86/6916: [58008.905656] #0: (&vcpu->mutex){......}, at: [<ffffffffa0379115>] vcpu_load+0x15/0x90 [kvm] [58008.905670] 1 lock held by qemu-system-x86/6917: [58008.905670] #0: (&vcpu->mutex){......}, at: [<ffffffffa0379115>] vcpu_load+0x15/0x90 [kvm] [58008.905686] 1 lock held by qemu-system-x86/7275: [58008.905687] #0: (&vcpu->mutex){......}, at: [<ffffffffa0379115>] vcpu_load+0x15/0x90 [kvm] [58008.905701] 1 lock held by qemu-system-x86/7277: [58008.905702] #0: (&vcpu->mutex){......}, at: [<ffffffffa0379115>] vcpu_load+0x15/0x90 [kvm] [58008.905717] 2 locks held by bash/26312: [58008.905718] #0: (&tty->ldisc_sem){......}, at: [<ffffffff8174f4de>] ldsem_down_read+0xe/0x10 [58008.905724] #1: (&ldata->atomic_read_lock){......}, at: [<ffffffff814ac95d>] n_tty_read+0xbd/0x920 [58008.905733] 2 locks held by bash/32506: [58008.905733] #0: (&tty->ldisc_sem){......}, at: [<ffffffff8174f4de>] ldsem_down_read+0xe/0x10 [58008.905737] #1: (&ldata->atomic_read_lock){......}, at: [<ffffffff814ac95d>] n_tty_read+0xbd/0x920 [58008.905741] 2 locks held by bash/548: [58008.905741] #0: (&tty->ldisc_sem){......}, at: [<ffffffff8174f4de>] ldsem_down_read+0xe/0x10 [58008.905745] #1: (&ldata->atomic_read_lock){......}, at: [<ffffffff814ac95d>] n_tty_read+0xbd/0x920 [58008.905750] 3 locks held by rsync/3388: [58008.905751] #0: (sb_writers#8){......}, at: [<ffffffff8119ba81>] do_sys_ftruncate.constprop.17+0xb1/0xe0 [58008.905758] #1: (&sb->s_type->i_mutex_key#9){......}, at: [<ffffffff8119b752>] do_truncate+0x62/0xc0 [58008.905764] #2: (sb_internal){......}, at: [<ffffffff812fdcae>] start_transaction+0x2ce/0x430 [58008.905772] 3 locks held by rsync/5224: [58008.905773] #0: (sb_writers#8){......}, at: [<ffffffff8119ba81>] do_sys_ftruncate.constprop.17+0xb1/0xe0 [58008.905779] #1: (&sb->s_type->i_mutex_key#9){......}, at: [<ffffffff8119b752>] do_truncate+0x62/0xc0 [58008.905785] #2: (sb_internal){......}, at: [<ffffffff812fdcae>] start_transaction+0x2ce/0x430 [58008.905793] 3 locks held by rsync/6413: [58008.905794] #0: (sb_writers#8){......}, at: [<ffffffff8119ba81>] do_sys_ftruncate.constprop.17+0xb1/0xe0 [58008.905801] #1: (&sb->s_type->i_mutex_key#9){......}, at: [<ffffffff8119b752>] do_truncate+0x62/0xc0 [58008.905807] #2: (sb_internal){......}, at: [<ffffffff812fdcae>] start_transaction+0x2ce/0x430 [58008.905813] 3 locks held by rsync/6664: [58008.905814] #0: (sb_writers#8){......}, at: [<ffffffff811c070f>] mnt_want_write+0x1f/0x50 [58008.905820] #1: (&type->i_mutex_dir_key#2/1){......}, at: [<ffffffff811abe8a>] filename_create+0x7a/0x160 [58008.905828] #2: (sb_internal){......}, at: [<ffffffff812fdcae>] start_transaction+0x2ce/0x430 [58008.905835] 2 locks held by bash/6772: [58008.905836] #0: (&tty->ldisc_sem){......}, at: [<ffffffff8174f4de>] ldsem_down_read+0xe/0x10 [58008.905841] #1: (&ldata->atomic_read_lock){......}, at: [<ffffffff814ac95d>] n_tty_read+0xbd/0x920 [58008.905848] =============================================
Created attachment 255805 [details] full dmesg of my 4.9.18_p14 RT kernel
Maybe related https://bugzilla.kernel.org/show_bug.cgi?id=194967 Observed hangs on different hardware, both ext4/xfs on kernel 4.4. It does not happen with kernel 4.1. Do you still have this problem?
(In reply to Tomas Mozes from comment #6) > Maybe related https://bugzilla.kernel.org/show_bug.cgi?id=194967 > > Observed hangs on different hardware, both ext4/xfs on kernel 4.4. It does > not happen with kernel 4.1. > > Do you still have this problem? I haven't tried yet with anything newer then the 4.10.1
Still having the same problem with 4.12.12 kernel: Attaching the output of the initial stall, the output of a sysrq-l and the output a sysrq-t
Created attachment 260367 [details] 4.12.12 kernel call trace 4.12.12 kernel call trace following btrfs scrub on multi-lun filesystem under xen
Created attachment 260369 [details] sysrq l output following 4.12.12 stall
Created attachment 260371 [details] sysrq t output following 4.12.12 stall
So it seems like #194967 is not related to this as I cannot reproduce it with kernel 4.12+.
It's possible that 4.13 might have fixed the problem. Am investigating
It appears that this might have been a xen block-front / block-back issue of some sort and the size of the grant table. After testing a 4.13 kernel, the btrfs scrub was not locking up (which was taking about 5 minutes). However I started seeing a bunch of xen messages about the hitting a limit for the xen grant table: ... xen:grant_table: xen/grant-table: max_grant_frames reached cur=32 extra=1 limit=32 gnttab_free_count=0 req_entries=29 xen:grant_table: xen/grant-table: max_grant_frames reached cur=32 extra=1 limit=32 gnttab_free_count=0 req_entries=29 xen:grant_table: xen/grant-table: max_grant_frames reached cur=32 extra=1 limit=32 gnttab_free_count=0 req_entries=29 xen:grant_table: xen/grant-table: max_grant_frames reached cur=32 extra=1 limit=32 gnttab_free_count=0 req_entries=29 ... I rebooted the xen host with an increased max grant table that got rid of the message. In investigating the size of the grant table I found a hit on a Novell site that discussed a hang due to heavy IO and the shortage of grant table frames (https://www.novell.com/support/kb/doc.php?id=7018590). What I suspect at this point was that the problem described in the Novell site was probably the core problem I was having. Something in the 4.13 kernel "fixed" the kernel so it wouldn't hang, which allowed the system to continue and reach a point that it could generate the above messages about the grant tables. I ran an additional test with a 4.12 kernel (that was hanging), but with the bump in the host's gnttab_max_frames increased. I wasn't able to reproduce the original hang. So.. to summarize, something in 4.13 "fixed" a hang due to limited number of xen grant_frames (allowing the system to report the error). By increasing the gnttbl_max_frames in the xen host the guest appears to function correctly under heavy IO load (even a pre-4.13 system). I'm closing this issue because 1) the hang itself doesn't occur under a 4.13 kernel and 2) using a prior kernel but with with an increased gnttab_max_frames that appears to fix the hang.
Thanks for the info.
Seems like kernel 4.13 added an optimization, but was not a permanent fix: https://www.mail-archive.com/xen-devel@lists.xen.org/msg116412.html So using kernel 4.13 it's less likely to see a hang, but they still happen. Xen 4.10 increased the gnttab limit to 64 and we have a xen-diag monitoring which can monitor the grant table. Debian bug: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=880554