On Mon, 2018-02-12 at 08:24 +0100, Paolo Valente wrote:
Il giorno 10 feb 2018, alle ore 09:29, Oleksandr Natalenko oleksandr@natalenko.name ha scritto:
Hi.
On pátek 9. února 2018 18:29:39 CET Mike Galbraith wrote:
On Fri, 2018-02-09 at 14:21 +0100, Oleksandr Natalenko wrote:
In addition to this I think it should be worth considering CC'ing Greg to pull this fix into 4.15 stable tree.
This isn't one he can cherry-pick, some munging required, in which case he usually wants a properly tested backport.
-Mike
Maybe, this could be a good opportunity to push all the pending BFQ patches into the stable 4.15 branch? Because IIUC currently BFQ in 4.15 is just unusable.
Paolo?
Of course ok for me, and thanks Oleksandr for proposing this. These commits should apply cleanly on 4.15, and FWIW have been tested, by me and BFQ users, on 4.15 too in these months.
How does that work without someone actually submitting patches? CC stable and pass along a conveniently sorted cherry-pick list?
9b25bd0368d5 block, bfq: remove batches of confusing ifdefs a34b024448eb block, bfq: consider also past I/O in soft real-time detection 4403e4e467c3 block, bfq: remove superfluous check in queue-merging setup 7b8fa3b900a0 block, bfq: let a queue be merged only shortly after starting I/O 1be6e8a964ee block, bfq: check low_latency flag in bfq_bfqq_save_state() 05e902835616 block, bfq: add missing rq_pos_tree update on rq removal f0ba5ea2fe45 block, bfq: increase threshold to deem I/O as random 0d52af590552 block, bfq: release oom-queue ref to root group on exit 52257ffbfcaf block, bfq: put async queues for root bfq groups too 8abef10b3de1 bfq-iosched: don't call bfqg_and_blkg_put for !CONFIG_BFQ_GROUP_IOSCHED 8993d445df38 block, bfq: fix occurrences of request finish method's old name 8a8747dc01ce block, bfq: limit sectors served with interactive weight raising a52a69ea89dc block, bfq: limit tags for writes and async I/O a78773906147 block, bfq: add requeue-request hook
block, bfq: add requeue-request hook bfq-iosched: don't call bfqg_and_blkg_put for !CONFIG_BFQ_GROUP_IOSCHED block, bfq: release oom-queue ref to root group on exit block, bfq: put async queues for root bfq groups too block, bfq: limit sectors served with interactive weight raising block, bfq: limit tags for writes and async I/O block, bfq: increase threshold to deem I/O as random block, bfq: remove superfluous check in queue-merging setup block, bfq: let a queue be merged only shortly after starting I/O block, bfq: check low_latency flag in bfq_bfqq_save_state() block, bfq: add missing rq_pos_tree update on rq removal block, bfq: fix occurrences of request finish method's old name block, bfq: consider also past I/O in soft real-time detection block, bfq: remove batches of confusing ifdefs
Hi.
12.02.2018 12:22, Mike Galbraith wrote:
How does that work without someone actually submitting patches? CC stable and pass along a conveniently sorted cherry-pick list?
From my experience, Greg is fine with the list of hashes, but he needs an approval from the relevant subtree maintainer (Jens in this case).
On Mon, 2018-02-12 at 13:48 +0100, Oleksandr Natalenko wrote:
Hi.
12.02.2018 12:22, Mike Galbraith wrote:
How does that work without someone actually submitting patches? CC stable and pass along a conveniently sorted cherry-pick list?
From my experience, Greg is fine with the list of hashes, but he needs an approval from the relevant subtree maintainer (Jens in this case).
Oh dear. I'm a bit reluctant to even mention this, buuut, when creating that hash list, I extracted/applied them to 4.15.3 via quilt to make sure that they really do slip right in.. and later, while building two fat enterprise config kernels concurrently, trees living in separate spinning rust buckets, box IO stalled on me. Not good. Hard reboot, clean up and try it again, it reproduced. Switch to master, that reproduced. Extra not good.
I found that rather odd, because I had earlier done this to 4.15..
patches/block-bfq:-fix-occurrences-of-request-finish-method-s-old-name.patch patches/block-bfq:-add-requeue-request-hook.patch
..ie take only the rename, wedge the fix in on top of it, beat on box, it worked fine. This morning, I go back to only those two, and box is again (at least pretending to be) perfectly happy to build the same trees it hung on twice in a row yesterday, it _seems_ to be completely uninterested in stalling no matter what I do.
So, something not so funny is still going on, here at least. Test results imply that something in that hash list _may_ not be all that desirable a thing to send to stable, but who knows, some playful gremlin may well be pulling my chain, will let box stall on me again a few seconds after I write that, and poke send :)
Ok IO gremlin, go for it...
-Mike
Il giorno 13 feb 2018, alle ore 06:02, Mike Galbraith efault@gmx.de ha scritto:
On Mon, 2018-02-12 at 13:48 +0100, Oleksandr Natalenko wrote:
Hi.
12.02.2018 12:22, Mike Galbraith wrote:
How does that work without someone actually submitting patches? CC stable and pass along a conveniently sorted cherry-pick list?
From my experience, Greg is fine with the list of hashes, but he needs an approval from the relevant subtree maintainer (Jens in this case).
Oh dear. I'm a bit reluctant to even mention this, buuut, when creating that hash list, I extracted/applied them to 4.15.3 via quilt to make sure that they really do slip right in.. and later, while building two fat enterprise config kernels concurrently, trees living in separate spinning rust buckets, box IO stalled on me. Not good. Hard reboot, clean up and try it again, it reproduced. Switch to master, that reproduced. Extra not good.
I found that rather odd, because I had earlier done this to 4.15..
patches/block-bfq:-fix-occurrences-of-request-finish-method-s-old-name.patch patches/block-bfq:-add-requeue-request-hook.patch
..ie take only the rename, wedge the fix in on top of it, beat on box, it worked fine. This morning, I go back to only those two, and box is again (at least pretending to be) perfectly happy to build the same trees it hung on twice in a row yesterday, it _seems_ to be completely uninterested in stalling no matter what I do.
So, something not so funny is still going on, here at least. Test results imply that something in that hash list _may_ not be all that desirable a thing to send to stable, but who knows, some playful gremlin may well be pulling my chain, will let box stall on me again a few seconds after I write that, and poke send :)
Ok IO gremlin, go for it...
Any chance your gremlin grants you some OOPS?
BTW, the only other commit in that series that affects bfq interaction with the rest of the system is: a52a69ea89dc block, bfq: limit tags for writes and async I/O
And the other commits that do something beyond changing some calculation are: 0d52af590552 block, bfq: release oom-queue ref to root group on exit 52257ffbfcaf block, bfq: put async queues for root bfq groups too
Thanks, Paolo
-Mike
On Tue, 2018-02-13 at 06:46 +0100, Paolo Valente wrote:
Any chance your gremlin grants you some OOPS?
I crash dumped it, though I'm unlikely to have time to even figure out what the hell _I'm_ doing in IO land, much less what it's doing :)
If you want it, and have a spot, I could try an over night upload (vmcore=14GB). Hung tasks are not in short supply.
crash> ps | grep UN 4 2 0 ffff880187f12940 UN 0.0 0 0 [kworker/0:0H] 6 2 0 ffff880187f144c0 UN 0.0 0 0 [mm_percpu_wq] 8 2 1 ffff880187f16040 UN 0.0 0 0 [rcu_sched] 9 2 4 ffff880187f16e00 UN 0.0 0 0 [rcu_bh] 18 2 1 ffff88018740d280 UN 0.0 0 0 [kworker/1:0H] 24 2 2 ffff880187582940 UN 0.0 0 0 [kworker/2:0H] 30 2 3 ffff8801875e8000 UN 0.0 0 0 [kworker/3:0H] 36 2 4 ffff8801875ed280 UN 0.0 0 0 [kworker/4:0H] 42 2 5 ffff88018769a940 UN 0.0 0 0 [kworker/5:0H] 48 2 6 ffff880187700000 UN 0.0 0 0 [kworker/6:0H] 54 2 7 ffff880187705280 UN 0.0 0 0 [kworker/7:0H] 57 2 1 ffff8801877b1b80 UN 0.0 0 0 [netns] 58 2 0 ffff8801877b2940 UN 0.0 0 0 [kworker/0:1] 62 2 2 ffff8801877b6040 UN 0.0 0 0 [writeback] 66 2 3 ffff88041e881b80 UN 0.0 0 0 [crypto] 67 2 5 ffff88041e882940 UN 0.0 0 0 [kintegrityd] 68 2 6 ffff88041e883700 UN 0.0 0 0 [kblockd] 69 2 2 ffff88041e8844c0 UN 0.0 0 0 [kworker/2:1] 73 2 4 ffff88041e910dc0 UN 0.0 0 0 [edac-poller] 74 2 7 ffff88041e911b80 UN 0.0 0 0 [devfreq_wq] 75 2 5 ffff8801877b0000 UN 0.0 0 0 [watchdogd] 91 2 3 ffff8803fa08d280 UN 0.0 0 0 [nvme-wq] 92 2 0 ffff8803fa08e040 UN 0.0 0 0 [ipv6_addrconf] 160 2 1 ffff88041e886e00 UN 0.0 0 0 [kaluad] 163 2 5 ffff8803fa346e00 UN 0.0 0 0 [kmpath_rdacd] 167 2 7 ffff8803fa346040 UN 0.0 0 0 [kmpathd] 168 2 3 ffff8803fa345280 UN 0.0 0 0 [kmpath_handlerd] 290 2 7 ffff8803f784a940 UN 0.0 0 0 [kworker/7:2] 356 2 6 ffff8803f677ee00 UN 0.0 0 0 [ata_sff] 526 2 3 ffff8803fc678000 UN 0.0 0 0 [scsi_tmf_0] 528 2 0 ffff8803fc679b80 UN 0.0 0 0 [scsi_tmf_1] 530 2 3 ffff8803fc67b700 UN 0.0 0 0 [scsi_tmf_2] 532 2 7 ffff8803fc67d280 UN 0.0 0 0 [scsi_tmf_3] 534 2 7 ffff8803fc67ee00 UN 0.0 0 0 [scsi_tmf_4] 536 2 3 ffff8803f6848dc0 UN 0.0 0 0 [scsi_tmf_5] 540 2 2 ffff8803f684c4c0 UN 0.0 0 0 [kworker/u16:6] 541 2 5 ffff8803f684d280 UN 0.0 0 0 [nvkm-disp] 543 2 4 ffff8803f684ee00 UN 0.0 0 0 [ttm_swap] 546 2 3 ffff8803f3ae8000 UN 0.0 0 0 [kworker/3:1H] 547 2 2 ffff8803f3ae8dc0 UN 0.0 0 0 [kworker/2:1H] 550 2 6 ffff8803f3ae9b80 UN 0.0 0 0 [kworker/6:1H] 552 2 5 ffff8803f3aeb700 UN 0.0 0 0 [scsi_tmf_6] 591 2 1 ffff8803f3aeee00 UN 0.0 0 0 [ext4-rsv-conver] 601 2 5 ffff8803f880ee00 UN 0.0 0 0 [kworker/5:1H] 632 2 1 ffff8803fa023700 UN 0.0 0 0 [kworker/1:1H] 643 2 0 ffff8803fa025280 UN 0.0 0 0 [kworker/0:1H] 659 2 4 ffff8803f677d280 UN 0.0 0 0 [kworker/4:1H] 663 2 7 ffff8803f6779b80 UN 0.0 0 0 [kworker/7:1H] 701 2 0 ffff8803f9eea940 UN 0.0 0 0 [kworker/0:2] 702 2 1 ffff8803f9eeb700 UN 0.0 0 0 [rpciod] 703 2 7 ffff8803f9eee040 UN 0.0 0 0 [xprtiod] 1020 2 4 ffff8803fc1c44c0 UN 0.0 0 0 [acpi_thermal_pm] 1170 2 3 ffff8803f1708dc0 UN 0.0 0 0 [jbd2/sdd1-8] 1171 2 6 ffff8803f170c4c0 UN 0.0 0 0 [ext4-rsv-conver] 1176 2 3 ffff8803fac58000 UN 0.0 0 0 [ext4-rsv-conver] 4233 2 5 ffff8803a8be8dc0 UN 0.0 0 0 [kworker/5:1] 8808 10134 6 ffff88037e789b80 UN 0.0 8104 3248 make 15603 2 5 ffff88041e886040 UN 0.0 0 0 [kworker/5:0] 15815 2 1 ffff88037e788dc0 UN 0.0 0 0 [kworker/1:0] 19344 8808 6 ffff8803c6658dc0 UN 0.0 7720 2960 make 19633 19632 3 ffff88041e916e00 UN 0.0 9924 2296 gcc 19651 19649 3 ffff8803a8bee040 UN 0.0 9896 2276 gcc 19683 19682 3 ffff8803b6e29b80 UN 0.0 9904 2300 gcc 19709 19687 2 ffff8803a8a41b80 UN 0.0 5852 1868 rm 19728 19727 2 ffff8803a8be9b80 UN 0.0 9932 2256 gcc 19732 19731 5 ffff880396dc0dc0 UN 0.0 9920 2296 gcc 19739 19606 4 ffff8803f394d280 UN 0.0 4560 1608 rm 19740 1 5 ffff8803b6ec2940 UN 0.1 49792 19732 cc1 19744 19656 2 ffff880396ceb700 UN 0.0 4524 1828 recordmcount 19922 1 3 ffff8803a8a40dc0 UN 0.1 388140 13996 pool 20278 2 2 ffff880396dc2940 UN 0.0 0 0 [kworker/u16:1] 20505 2 2 ffff8803b6eb1b80 UN 0.0 0 0 [kworker/2:2] 20648 2 3 ffff88037e78a940 UN 0.0 0 0 [kworker/3:1] 20766 2 6 ffff880187f11b80 UN 0.0 0 0 [kworker/u16:0] 21007 2 6 ffff8803c97844c0 UN 0.0 0 0 [kworker/6:0] 21385 2 4 ffff8803a8a46040 UN 0.0 0 0 [kworker/4:1] 21562 2 1 ffff8803f7b61b80 UN 0.0 0 0 [kworker/1:2] 21730 2 7 ffff8803d6525280 UN 0.0 0 0 [kworker/7:3] 22775 2 4 ffff880396dbe040 UN 0.0 0 0 [kworker/4:2] 22879 2 6 ffff880396db8000 UN 0.0 0 0 [kworker/6:1] 22937 2 7 ffff880396dbc4c0 UN 0.0 0 0 [kworker/7:0] 22952 2 4 ffff880396dbee00 UN 0.0 0 0 [kworker/u16:2] 23004 2 5 ffff880396dbb700 UN 0.0 0 0 [kworker/5:2] 23070 2 1 ffff8803d6520dc0 UN 0.0 0 0 [kworker/1:1] 23152 4478 2 ffff8803a8a444c0 UN 0.0 5748 1656 sync 31874 2 3 ffff88018740c4c0 UN 0.0 0 0 [kworker/3:0]
BTW, the only other commit in that series that affects bfq interaction with the rest of the system is: a52a69ea89dc block, bfq: limit tags for writes and async I/O
I'll see if that changes things on the side. Work beckons.
And the other commits that do something beyond changing some calculation are: 0d52af590552 block, bfq: release oom-queue ref to root group on exit 52257ffbfcaf block, bfq: put async queues for root bfq groups too
Thanks, Paolo
-Mike
Oops, meant to provide the dmesg spew.
[ 1954.780829] INFO: task kworker/7:2:290 blocked for more than 480 seconds. [ 1954.780837] Tainted: G E 4.15.3-smp #8 [ 1954.780839] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.780843] kworker/7:2 D 0 290 2 0x80000000 [ 1954.780858] Workqueue: events_freezable_power_ disk_events_workfn [ 1954.780862] Call Trace: [ 1954.780876] ? __schedule+0x268/0x840 [ 1954.780883] schedule+0x32/0x80 [ 1954.780891] io_schedule+0x12/0x40 [ 1954.780896] blk_mq_get_tag+0x11e/0x230 [ 1954.780902] ? blk_mq_sched_dispatch_requests+0x108/0x180 [ 1954.780910] ? remove_wait_queue+0x60/0x60 [ 1954.780920] blk_mq_get_request+0xcc/0x340 [ 1954.780927] blk_mq_alloc_request+0x5a/0xa0 [ 1954.780933] blk_get_request_flags+0x44/0x170 [ 1954.780955] scsi_execute+0x38/0x1e0 [scsi_mod] [ 1954.780971] scsi_test_unit_ready+0x9c/0xe0 [scsi_mod] [ 1954.780981] sd_check_events+0xf7/0x170 [sd_mod] [ 1954.780988] disk_check_events+0x55/0x120 [ 1954.780997] process_one_work+0x147/0x350 [ 1954.781003] worker_thread+0x47/0x3e0 [ 1954.781009] kthread+0xf8/0x130 [ 1954.781015] ? rescuer_thread+0x360/0x360 [ 1954.781019] ? kthread_stop+0x120/0x120 [ 1954.781025] ret_from_fork+0x35/0x40 [ 1954.781033] INFO: task kworker/u16:6:540 blocked for more than 480 seconds. [ 1954.781037] Tainted: G E 4.15.3-smp #8 [ 1954.781039] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.781042] kworker/u16:6 D 0 540 2 0x80000000 [ 1954.781053] Workqueue: writeback wb_workfn (flush-8:48) [ 1954.781057] Call Trace: [ 1954.781064] ? __schedule+0x268/0x840 [ 1954.781071] schedule+0x32/0x80 [ 1954.781076] io_schedule+0x12/0x40 [ 1954.781081] blk_mq_get_tag+0x11e/0x230 [ 1954.781087] ? remove_wait_queue+0x60/0x60 [ 1954.781094] blk_mq_get_request+0xcc/0x340 [ 1954.781099] blk_mq_make_request+0xf8/0x580 [ 1954.781105] generic_make_request+0xfd/0x2d0 [ 1954.781110] submit_bio+0x5e/0x120 [ 1954.781151] ext4_io_submit+0x48/0x60 [ext4] [ 1954.781178] ext4_bio_write_page+0x199/0x3a0 [ext4] [ 1954.781202] mpage_submit_page+0x51/0x70 [ext4] [ 1954.781223] mpage_map_and_submit_buffers+0x109/0x1d0 [ext4] [ 1954.781248] ext4_writepages+0x831/0xe50 [ext4] [ 1954.781255] ? bfq_deactivate_entity+0x21/0x50 [ 1954.781263] ? cpumask_next_and+0x2b/0x40 [ 1954.781272] do_writepages+0x1a/0x70 [ 1954.781279] __writeback_single_inode+0x3d/0x340 [ 1954.781286] writeback_sb_inodes+0x21f/0x4c0 [ 1954.781294] __writeback_inodes_wb+0x87/0xb0 [ 1954.781300] wb_writeback+0x258/0x2f0 [ 1954.781306] ? cpumask_next+0x16/0x20 [ 1954.781313] wb_workfn+0x2f0/0x400 [ 1954.781319] process_one_work+0x147/0x350 [ 1954.781325] worker_thread+0x47/0x3e0 [ 1954.781330] kthread+0xf8/0x130 [ 1954.781336] ? rescuer_thread+0x360/0x360 [ 1954.781340] ? kthread_stop+0x120/0x120 [ 1954.781345] ret_from_fork+0x35/0x40 [ 1954.781356] INFO: task jbd2/sdd1-8:1170 blocked for more than 480 seconds. [ 1954.781359] Tainted: G E 4.15.3-smp #8 [ 1954.781361] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.781364] jbd2/sdd1-8 D 0 1170 2 0x80000000 [ 1954.781368] Call Trace: [ 1954.781375] ? __schedule+0x268/0x840 [ 1954.781381] ? __wake_up_common_lock+0x77/0x90 [ 1954.781387] schedule+0x32/0x80 [ 1954.781401] jbd2_journal_commit_transaction+0x262/0x1b50 [jbd2] [ 1954.781409] ? rb_erase_cached+0x31b/0x390 [ 1954.781415] ? pick_next_task_fair+0x58d/0x8c0 [ 1954.781424] ? __switch_to+0x98/0x3f0 [ 1954.781430] ? remove_wait_queue+0x60/0x60 [ 1954.781441] kjournald2+0xb1/0x230 [jbd2] [ 1954.781447] ? remove_wait_queue+0x60/0x60 [ 1954.781452] kthread+0xf8/0x130 [ 1954.781460] ? commit_timeout+0x10/0x10 [jbd2] [ 1954.781464] ? kthread_stop+0x120/0x120 [ 1954.781469] ret_from_fork+0x35/0x40 [ 1954.781493] INFO: task pool:19922 blocked for more than 480 seconds. [ 1954.781498] Tainted: G E 4.15.3-smp #8 [ 1954.781502] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.781506] pool D 0 19922 1 0x00000000 [ 1954.781512] Call Trace: [ 1954.781520] ? __schedule+0x268/0x840 [ 1954.781526] schedule+0x32/0x80 [ 1954.781531] schedule_timeout+0x1d2/0x2e0 [ 1954.781538] wait_for_completion+0xff/0x160 [ 1954.781543] ? wake_up_q+0x70/0x70 [ 1954.781549] flush_work+0x109/0x180 [ 1954.781554] ? wake_up_worker+0x30/0x30 [ 1954.781560] __cancel_work_timer+0xe3/0x160 [ 1954.781569] ? kobj_lookup+0x111/0x160 [ 1954.781574] ? disk_map_sector_rcu+0x70/0x70 [ 1954.781580] disk_block_events+0x6f/0x90 [ 1954.781587] __blkdev_get+0x5a/0x470 [ 1954.781592] ? bd_acquire+0xd0/0xd0 [ 1954.781597] blkdev_get+0x195/0x2e0 [ 1954.781605] ? __inode_permission+0x2d/0x110 [ 1954.781609] ? bd_acquire+0x37/0xd0 [ 1954.781613] ? bd_acquire+0xd0/0xd0 [ 1954.781619] do_dentry_open.isra.20+0x1ee/0x300 [ 1954.781625] path_openat+0x28a/0x1050 [ 1954.781631] do_filp_open+0x7e/0xd0 [ 1954.781640] ? read_null+0x10/0x10 [ 1954.781646] ? _cond_resched+0x15/0x30 [ 1954.781653] do_sys_open+0x116/0x1e0 [ 1954.781659] do_syscall_64+0x75/0x1a0 [ 1954.781665] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.781670] RIP: 0033:0x7f81a021d44d [ 1954.781673] RSP: 002b:00007f819d542b30 EFLAGS: 00000293 ORIG_RAX: 0000000000000002 [ 1954.781679] RAX: ffffffffffffffda RBX: 000000000234b0c0 RCX: 00007f81a021d44d [ 1954.781682] RDX: 00007f819fc62f03 RSI: 0000000000000800 RDI: 00000000023606b0 [ 1954.781685] RBP: 00007f8190011ec0 R08: 0000000000000073 R09: 0000000000000003 [ 1954.781689] R10: 0000000000000000 R11: 0000000000000293 R12: 00007f819d542cc8 [ 1954.781692] R13: 00007f819d542bf0 R14: 00007f8190011ec0 R15: 0000000000000001 [ 1954.781735] INFO: task gcc:19633 blocked for more than 480 seconds. [ 1954.781738] Tainted: G E 4.15.3-smp #8 [ 1954.781741] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.781743] gcc D 0 19633 19632 0x00000000 [ 1954.781748] Call Trace: [ 1954.781755] ? __schedule+0x268/0x840 [ 1954.781761] schedule+0x32/0x80 [ 1954.781766] io_schedule+0x12/0x40 [ 1954.781771] blk_mq_get_tag+0x11e/0x230 [ 1954.781779] ? elv_merge+0x66/0xe0 [ 1954.781786] ? remove_wait_queue+0x60/0x60 [ 1954.781796] blk_mq_get_request+0xcc/0x340 [ 1954.781803] blk_mq_make_request+0xf8/0x580 [ 1954.781810] generic_make_request+0xfd/0x2d0 [ 1954.781815] submit_bio+0x5e/0x120 [ 1954.781835] ? __ext4_journal_stop+0x37/0xa0 [ext4] [ 1954.781857] ext4_io_submit+0x48/0x60 [ext4] [ 1954.781878] ext4_writepages+0x64a/0xe50 [ext4] [ 1954.781888] do_writepages+0x1a/0x70 [ 1954.781893] __filemap_fdatawrite_range+0x71/0x90 [ 1954.781915] ext4_rename+0x600/0x830 [ext4] [ 1954.781923] ? legitimize_path.isra.54+0x28/0x50 [ 1954.781929] ? terminate_walk+0x55/0xb0 [ 1954.781935] vfs_rename+0x1df/0x6d0 [ 1954.781942] ? __d_lookup+0x111/0x130 [ 1954.781948] SyS_rename+0x325/0x390 [ 1954.781954] do_syscall_64+0x75/0x1a0 [ 1954.781960] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.781964] RIP: 0033:0x147b429b7a67 [ 1954.781967] RSP: 002b:00007ffca7063be8 EFLAGS: 00000202 ORIG_RAX: 0000000000000052 [ 1954.781971] RAX: ffffffffffffffda RBX: 000000000000001d RCX: 0000147b429b7a67 [ 1954.781975] RDX: 0000000000000000 RSI: 000000000212e200 RDI: 000000000212f1c0 [ 1954.781978] RBP: 000000000211a390 R08: 000000000212f310 R09: 0000147b433d4700 [ 1954.781981] R10: 0000000000000000 R11: 0000000000000202 R12: 000000000212f230 [ 1954.781984] R13: 000000000212e200 R14: 0000000000000000 R15: 0000000000000006 [ 1954.781990] INFO: task gcc:19651 blocked for more than 480 seconds. [ 1954.781993] Tainted: G E 4.15.3-smp #8 [ 1954.781995] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.781998] gcc D 0 19651 19649 0x00000000 [ 1954.782002] Call Trace: [ 1954.782008] ? __schedule+0x268/0x840 [ 1954.782014] schedule+0x32/0x80 [ 1954.782020] io_schedule+0x12/0x40 [ 1954.782025] blk_mq_get_tag+0x11e/0x230 [ 1954.782030] ? elv_merge+0x66/0xe0 [ 1954.782036] ? remove_wait_queue+0x60/0x60 [ 1954.782042] blk_mq_get_request+0xcc/0x340 [ 1954.782047] blk_mq_make_request+0xf8/0x580 [ 1954.782053] generic_make_request+0xfd/0x2d0 [ 1954.782058] submit_bio+0x5e/0x120 [ 1954.782076] ? __ext4_journal_stop+0x37/0xa0 [ext4] [ 1954.782095] ext4_io_submit+0x48/0x60 [ext4] [ 1954.782114] ext4_writepages+0x64a/0xe50 [ext4] [ 1954.782123] do_writepages+0x1a/0x70 [ 1954.782128] __filemap_fdatawrite_range+0x71/0x90 [ 1954.782147] ext4_rename+0x600/0x830 [ext4] [ 1954.782154] ? legitimize_path.isra.54+0x28/0x50 [ 1954.782160] ? terminate_walk+0x55/0xb0 [ 1954.782165] vfs_rename+0x1df/0x6d0 [ 1954.782172] ? __d_lookup+0x111/0x130 [ 1954.782177] SyS_rename+0x325/0x390 [ 1954.782183] do_syscall_64+0x75/0x1a0 [ 1954.782188] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.782192] RIP: 0033:0x146b9f33ca67 [ 1954.782194] RSP: 002b:00007fffe33828b8 EFLAGS: 00000202 ORIG_RAX: 0000000000000052 [ 1954.782199] RAX: ffffffffffffffda RBX: 000000000000001d RCX: 0000146b9f33ca67 [ 1954.782202] RDX: 0000000000000000 RSI: 000000000233b910 RDI: 000000000233c110 [ 1954.782205] RBP: 000000000232a390 R08: 000000000233c260 R09: 0000146b9fd59700 [ 1954.782208] R10: 0000000000000000 R11: 0000000000000202 R12: 000000000233c180 [ 1954.782211] R13: 000000000233b910 R14: 0000000000000000 R15: 0000000000000006 [ 1954.782217] INFO: task gcc:19683 blocked for more than 480 seconds. [ 1954.782220] Tainted: G E 4.15.3-smp #8 [ 1954.782222] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.782225] gcc D 0 19683 19682 0x00000000 [ 1954.782229] Call Trace: [ 1954.782236] ? __schedule+0x268/0x840 [ 1954.782242] schedule+0x32/0x80 [ 1954.782247] io_schedule+0x12/0x40 [ 1954.782252] blk_mq_get_tag+0x11e/0x230 [ 1954.782257] ? elv_merge+0x66/0xe0 [ 1954.782262] ? remove_wait_queue+0x60/0x60 [ 1954.782269] blk_mq_get_request+0xcc/0x340 [ 1954.782274] blk_mq_make_request+0xf8/0x580 [ 1954.782279] generic_make_request+0xfd/0x2d0 [ 1954.782284] submit_bio+0x5e/0x120 [ 1954.782302] ? __ext4_journal_stop+0x37/0xa0 [ext4] [ 1954.782320] ext4_io_submit+0x48/0x60 [ext4] [ 1954.782338] ext4_writepages+0x64a/0xe50 [ext4] [ 1954.782347] do_writepages+0x1a/0x70 [ 1954.782352] __filemap_fdatawrite_range+0x71/0x90 [ 1954.782370] ext4_rename+0x600/0x830 [ext4] [ 1954.782376] ? legitimize_path.isra.54+0x28/0x50 [ 1954.782382] ? terminate_walk+0x55/0xb0 [ 1954.782388] vfs_rename+0x1df/0x6d0 [ 1954.782394] ? __d_lookup+0x111/0x130 [ 1954.782400] SyS_rename+0x325/0x390 [ 1954.782405] do_syscall_64+0x75/0x1a0 [ 1954.782411] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.782414] RIP: 0033:0x14d933ff7a67 [ 1954.782417] RSP: 002b:00007fffc5db42c8 EFLAGS: 00000206 ORIG_RAX: 0000000000000052 [ 1954.782421] RAX: ffffffffffffffda RBX: 000000000000001d RCX: 000014d933ff7a67 [ 1954.782424] RDX: 0000000000000000 RSI: 00000000016eba00 RDI: 00000000016e7b30 [ 1954.782427] RBP: 00000000016d6390 R08: 00000000016e7c80 R09: 000014d934a14700 [ 1954.782430] R10: 0000000000000000 R11: 0000000000000206 R12: 00000000016e7ba0 [ 1954.782433] R13: 00000000016eba00 R14: 0000000000000000 R15: 0000000000000006 [ 1954.782438] INFO: task rm:19709 blocked for more than 480 seconds. [ 1954.782442] Tainted: G E 4.15.3-smp #8 [ 1954.782444] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.782446] rm D 0 19709 19687 0x00000000 [ 1954.782450] Call Trace: [ 1954.782457] ? __schedule+0x268/0x840 [ 1954.782463] schedule+0x32/0x80 [ 1954.782471] wait_transaction_locked+0x76/0xa0 [jbd2] [ 1954.782478] ? remove_wait_queue+0x60/0x60 [ 1954.782486] add_transaction_credits+0x1a4/0x280 [jbd2] [ 1954.782494] start_this_handle+0x189/0x3e0 [jbd2] [ 1954.782500] ? _cond_resched+0x15/0x30 [ 1954.782505] ? kmem_cache_alloc+0x142/0x150 [ 1954.782513] jbd2__journal_start+0xe9/0x1f0 [jbd2] [ 1954.782532] ext4_unlink+0x1ac/0x330 [ext4] [ 1954.782537] vfs_unlink+0xb1/0x1a0 [ 1954.782542] do_unlinkat+0x23b/0x280 [ 1954.782548] do_syscall_64+0x75/0x1a0 [ 1954.782553] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.782556] RIP: 0033:0x7fca75fcfba7 [ 1954.782559] RSP: 002b:00007ffdaa5b75a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000107 [ 1954.782563] RAX: ffffffffffffffda RBX: 00000000011bf770 RCX: 00007fca75fcfba7 [ 1954.782566] RDX: 0000000000000000 RSI: 00000000011bf878 RDI: 0000000000000006 [ 1954.782569] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000 [ 1954.782573] R10: 000000000000004a R11: 0000000000000246 R12: 00000000011b3fdc [ 1954.782576] R13: 00007ffdaa5b7700 R14: 00000000011bf770 R15: 0000000000000000 [ 1954.782581] INFO: task gcc:19728 blocked for more than 480 seconds. [ 1954.782584] Tainted: G E 4.15.3-smp #8 [ 1954.782586] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.782588] gcc D 0 19728 19727 0x00000000 [ 1954.782592] Call Trace: [ 1954.782599] ? __schedule+0x268/0x840 [ 1954.782603] ? filename_parentat+0xc9/0x120 [ 1954.782609] schedule+0x32/0x80 [ 1954.782614] rwsem_down_write_failed+0x1e9/0x360 [ 1954.782620] call_rwsem_down_write_failed+0x13/0x20 [ 1954.782627] down_write+0x29/0x40 [ 1954.782632] filename_create+0x66/0x150 [ 1954.782637] SyS_symlink+0x4e/0xc0 [ 1954.782642] do_syscall_64+0x75/0x1a0 [ 1954.782647] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.782650] RIP: 0033:0x147656b2cab7 [ 1954.782653] RSP: 002b:00007fff10c42988 EFLAGS: 00000206 ORIG_RAX: 0000000000000058 [ 1954.782657] RAX: ffffffffffffffda RBX: 0000000000643250 RCX: 0000147656b2cab7 [ 1954.782661] RDX: 0000000000643390 RSI: 0000000000643250 RDI: 0000000000643390 [ 1954.782664] RBP: 0000000000000000 R08: 3836333633343800 R09: 0000000000658be0 [ 1954.782667] R10: 00000000ba5a914c R11: 0000000000000206 R12: 0000000000643390 [ 1954.782670] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000006 [ 1954.782675] INFO: task gcc:19732 blocked for more than 480 seconds. [ 1954.782678] Tainted: G E 4.15.3-smp #8 [ 1954.782680] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.782683] gcc D 0 19732 19731 0x00000000 [ 1954.782687] Call Trace: [ 1954.782693] ? __schedule+0x268/0x840 [ 1954.782699] schedule+0x32/0x80 [ 1954.782704] io_schedule+0x12/0x40 [ 1954.782709] blk_mq_get_tag+0x11e/0x230 [ 1954.782715] ? elv_merge+0x66/0xe0 [ 1954.782720] ? remove_wait_queue+0x60/0x60 [ 1954.782727] blk_mq_get_request+0xcc/0x340 [ 1954.782732] blk_mq_make_request+0xf8/0x580 [ 1954.782737] generic_make_request+0xfd/0x2d0 [ 1954.782741] submit_bio+0x5e/0x120 [ 1954.782759] ? __ext4_journal_stop+0x37/0xa0 [ext4] [ 1954.782777] ext4_io_submit+0x48/0x60 [ext4] [ 1954.782795] ext4_writepages+0x64a/0xe50 [ext4] [ 1954.782805] do_writepages+0x1a/0x70 [ 1954.782809] __filemap_fdatawrite_range+0x71/0x90 [ 1954.782828] ext4_rename+0x600/0x830 [ext4] [ 1954.782834] ? legitimize_path.isra.54+0x28/0x50 [ 1954.782840] ? terminate_walk+0x55/0xb0 [ 1954.782846] vfs_rename+0x1df/0x6d0 [ 1954.782853] ? __d_lookup+0x111/0x130 [ 1954.782858] SyS_rename+0x325/0x390 [ 1954.782864] do_syscall_64+0x75/0x1a0 [ 1954.782869] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.782872] RIP: 0033:0x15499c5b4a67 [ 1954.782875] RSP: 002b:00007fff60bd92b8 EFLAGS: 00000202 ORIG_RAX: 0000000000000052 [ 1954.782879] RAX: ffffffffffffffda RBX: 000000000000001d RCX: 000015499c5b4a67 [ 1954.782882] RDX: 0000000000000000 RSI: 0000000001966b60 RDI: 00000000019673c0 [ 1954.782886] RBP: 000000000194d2e0 R08: 0000000001967510 R09: 000015499cfd1700 [ 1954.782888] R10: 0000000000000000 R11: 0000000000000202 R12: 0000000001967430 [ 1954.782891] R13: 0000000001966b60 R14: 0000000000000000 R15: 0000000000000006
Il giorno 13 feb 2018, alle ore 07:50, Mike Galbraith efault@gmx.de ha scritto:
Oops, meant to provide the dmesg spew.
[ 1954.780829] INFO: task kworker/7:2:290 blocked for more than 480 seconds. [ 1954.780837] Tainted: G E 4.15.3-smp #8 [ 1954.780839] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.780843] kworker/7:2 D 0 290 2 0x80000000 [ 1954.780858] Workqueue: events_freezable_power_ disk_events_workfn [ 1954.780862] Call Trace: [ 1954.780876] ? __schedule+0x268/0x840 [ 1954.780883] schedule+0x32/0x80 [ 1954.780891] io_schedule+0x12/0x40 [ 1954.780896] blk_mq_get_tag+0x11e/0x230 [ 1954.780902] ? blk_mq_sched_dispatch_requests+0x108/0x180 [ 1954.780910] ? remove_wait_queue+0x60/0x60 [ 1954.780920] blk_mq_get_request+0xcc/0x340 [ 1954.780927] blk_mq_alloc_request+0x5a/0xa0 [ 1954.780933] blk_get_request_flags+0x44/0x170 [ 1954.780955] scsi_execute+0x38/0x1e0 [scsi_mod] [ 1954.780971] scsi_test_unit_ready+0x9c/0xe0 [scsi_mod] [ 1954.780981] sd_check_events+0xf7/0x170 [sd_mod] [ 1954.780988] disk_check_events+0x55/0x120 [ 1954.780997] process_one_work+0x147/0x350 [ 1954.781003] worker_thread+0x47/0x3e0 [ 1954.781009] kthread+0xf8/0x130 [ 1954.781015] ? rescuer_thread+0x360/0x360 [ 1954.781019] ? kthread_stop+0x120/0x120 [ 1954.781025] ret_from_fork+0x35/0x40 [ 1954.781033] INFO: task kworker/u16:6:540 blocked for more than 480 seconds. [ 1954.781037] Tainted: G E 4.15.3-smp #8 [ 1954.781039] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.781042] kworker/u16:6 D 0 540 2 0x80000000 [ 1954.781053] Workqueue: writeback wb_workfn (flush-8:48) [ 1954.781057] Call Trace: [ 1954.781064] ? __schedule+0x268/0x840 [ 1954.781071] schedule+0x32/0x80 [ 1954.781076] io_schedule+0x12/0x40 [ 1954.781081] blk_mq_get_tag+0x11e/0x230 [ 1954.781087] ? remove_wait_queue+0x60/0x60 [ 1954.781094] blk_mq_get_request+0xcc/0x340 [ 1954.781099] blk_mq_make_request+0xf8/0x580 [ 1954.781105] generic_make_request+0xfd/0x2d0 [ 1954.781110] submit_bio+0x5e/0x120 [ 1954.781151] ext4_io_submit+0x48/0x60 [ext4] [ 1954.781178] ext4_bio_write_page+0x199/0x3a0 [ext4] [ 1954.781202] mpage_submit_page+0x51/0x70 [ext4] [ 1954.781223] mpage_map_and_submit_buffers+0x109/0x1d0 [ext4] [ 1954.781248] ext4_writepages+0x831/0xe50 [ext4] [ 1954.781255] ? bfq_deactivate_entity+0x21/0x50 [ 1954.781263] ? cpumask_next_and+0x2b/0x40 [ 1954.781272] do_writepages+0x1a/0x70 [ 1954.781279] __writeback_single_inode+0x3d/0x340 [ 1954.781286] writeback_sb_inodes+0x21f/0x4c0 [ 1954.781294] __writeback_inodes_wb+0x87/0xb0 [ 1954.781300] wb_writeback+0x258/0x2f0 [ 1954.781306] ? cpumask_next+0x16/0x20 [ 1954.781313] wb_workfn+0x2f0/0x400 [ 1954.781319] process_one_work+0x147/0x350 [ 1954.781325] worker_thread+0x47/0x3e0 [ 1954.781330] kthread+0xf8/0x130 [ 1954.781336] ? rescuer_thread+0x360/0x360 [ 1954.781340] ? kthread_stop+0x120/0x120 [ 1954.781345] ret_from_fork+0x35/0x40 [ 1954.781356] INFO: task jbd2/sdd1-8:1170 blocked for more than 480 seconds. [ 1954.781359] Tainted: G E 4.15.3-smp #8 [ 1954.781361] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.781364] jbd2/sdd1-8 D 0 1170 2 0x80000000 [ 1954.781368] Call Trace: [ 1954.781375] ? __schedule+0x268/0x840 [ 1954.781381] ? __wake_up_common_lock+0x77/0x90 [ 1954.781387] schedule+0x32/0x80 [ 1954.781401] jbd2_journal_commit_transaction+0x262/0x1b50 [jbd2] [ 1954.781409] ? rb_erase_cached+0x31b/0x390 [ 1954.781415] ? pick_next_task_fair+0x58d/0x8c0 [ 1954.781424] ? __switch_to+0x98/0x3f0 [ 1954.781430] ? remove_wait_queue+0x60/0x60 [ 1954.781441] kjournald2+0xb1/0x230 [jbd2] [ 1954.781447] ? remove_wait_queue+0x60/0x60 [ 1954.781452] kthread+0xf8/0x130 [ 1954.781460] ? commit_timeout+0x10/0x10 [jbd2] [ 1954.781464] ? kthread_stop+0x120/0x120 [ 1954.781469] ret_from_fork+0x35/0x40 [ 1954.781493] INFO: task pool:19922 blocked for more than 480 seconds. [ 1954.781498] Tainted: G E 4.15.3-smp #8 [ 1954.781502] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.781506] pool D 0 19922 1 0x00000000 [ 1954.781512] Call Trace: [ 1954.781520] ? __schedule+0x268/0x840 [ 1954.781526] schedule+0x32/0x80 [ 1954.781531] schedule_timeout+0x1d2/0x2e0 [ 1954.781538] wait_for_completion+0xff/0x160 [ 1954.781543] ? wake_up_q+0x70/0x70 [ 1954.781549] flush_work+0x109/0x180 [ 1954.781554] ? wake_up_worker+0x30/0x30 [ 1954.781560] __cancel_work_timer+0xe3/0x160 [ 1954.781569] ? kobj_lookup+0x111/0x160 [ 1954.781574] ? disk_map_sector_rcu+0x70/0x70 [ 1954.781580] disk_block_events+0x6f/0x90 [ 1954.781587] __blkdev_get+0x5a/0x470 [ 1954.781592] ? bd_acquire+0xd0/0xd0 [ 1954.781597] blkdev_get+0x195/0x2e0 [ 1954.781605] ? __inode_permission+0x2d/0x110 [ 1954.781609] ? bd_acquire+0x37/0xd0 [ 1954.781613] ? bd_acquire+0xd0/0xd0 [ 1954.781619] do_dentry_open.isra.20+0x1ee/0x300 [ 1954.781625] path_openat+0x28a/0x1050 [ 1954.781631] do_filp_open+0x7e/0xd0 [ 1954.781640] ? read_null+0x10/0x10 [ 1954.781646] ? _cond_resched+0x15/0x30 [ 1954.781653] do_sys_open+0x116/0x1e0 [ 1954.781659] do_syscall_64+0x75/0x1a0 [ 1954.781665] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.781670] RIP: 0033:0x7f81a021d44d [ 1954.781673] RSP: 002b:00007f819d542b30 EFLAGS: 00000293 ORIG_RAX: 0000000000000002 [ 1954.781679] RAX: ffffffffffffffda RBX: 000000000234b0c0 RCX: 00007f81a021d44d [ 1954.781682] RDX: 00007f819fc62f03 RSI: 0000000000000800 RDI: 00000000023606b0 [ 1954.781685] RBP: 00007f8190011ec0 R08: 0000000000000073 R09: 0000000000000003 [ 1954.781689] R10: 0000000000000000 R11: 0000000000000293 R12: 00007f819d542cc8 [ 1954.781692] R13: 00007f819d542bf0 R14: 00007f8190011ec0 R15: 0000000000000001 [ 1954.781735] INFO: task gcc:19633 blocked for more than 480 seconds. [ 1954.781738] Tainted: G E 4.15.3-smp #8 [ 1954.781741] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.781743] gcc D 0 19633 19632 0x00000000 [ 1954.781748] Call Trace: [ 1954.781755] ? __schedule+0x268/0x840 [ 1954.781761] schedule+0x32/0x80 [ 1954.781766] io_schedule+0x12/0x40 [ 1954.781771] blk_mq_get_tag+0x11e/0x230 [ 1954.781779] ? elv_merge+0x66/0xe0 [ 1954.781786] ? remove_wait_queue+0x60/0x60 [ 1954.781796] blk_mq_get_request+0xcc/0x340 [ 1954.781803] blk_mq_make_request+0xf8/0x580 [ 1954.781810] generic_make_request+0xfd/0x2d0 [ 1954.781815] submit_bio+0x5e/0x120 [ 1954.781835] ? __ext4_journal_stop+0x37/0xa0 [ext4] [ 1954.781857] ext4_io_submit+0x48/0x60 [ext4] [ 1954.781878] ext4_writepages+0x64a/0xe50 [ext4] [ 1954.781888] do_writepages+0x1a/0x70 [ 1954.781893] __filemap_fdatawrite_range+0x71/0x90 [ 1954.781915] ext4_rename+0x600/0x830 [ext4] [ 1954.781923] ? legitimize_path.isra.54+0x28/0x50 [ 1954.781929] ? terminate_walk+0x55/0xb0 [ 1954.781935] vfs_rename+0x1df/0x6d0 [ 1954.781942] ? __d_lookup+0x111/0x130 [ 1954.781948] SyS_rename+0x325/0x390 [ 1954.781954] do_syscall_64+0x75/0x1a0 [ 1954.781960] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.781964] RIP: 0033:0x147b429b7a67 [ 1954.781967] RSP: 002b:00007ffca7063be8 EFLAGS: 00000202 ORIG_RAX: 0000000000000052 [ 1954.781971] RAX: ffffffffffffffda RBX: 000000000000001d RCX: 0000147b429b7a67 [ 1954.781975] RDX: 0000000000000000 RSI: 000000000212e200 RDI: 000000000212f1c0 [ 1954.781978] RBP: 000000000211a390 R08: 000000000212f310 R09: 0000147b433d4700 [ 1954.781981] R10: 0000000000000000 R11: 0000000000000202 R12: 000000000212f230 [ 1954.781984] R13: 000000000212e200 R14: 0000000000000000 R15: 0000000000000006 [ 1954.781990] INFO: task gcc:19651 blocked for more than 480 seconds. [ 1954.781993] Tainted: G E 4.15.3-smp #8 [ 1954.781995] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.781998] gcc D 0 19651 19649 0x00000000 [ 1954.782002] Call Trace: [ 1954.782008] ? __schedule+0x268/0x840 [ 1954.782014] schedule+0x32/0x80 [ 1954.782020] io_schedule+0x12/0x40 [ 1954.782025] blk_mq_get_tag+0x11e/0x230 [ 1954.782030] ? elv_merge+0x66/0xe0 [ 1954.782036] ? remove_wait_queue+0x60/0x60 [ 1954.782042] blk_mq_get_request+0xcc/0x340 [ 1954.782047] blk_mq_make_request+0xf8/0x580 [ 1954.782053] generic_make_request+0xfd/0x2d0 [ 1954.782058] submit_bio+0x5e/0x120 [ 1954.782076] ? __ext4_journal_stop+0x37/0xa0 [ext4] [ 1954.782095] ext4_io_submit+0x48/0x60 [ext4] [ 1954.782114] ext4_writepages+0x64a/0xe50 [ext4] [ 1954.782123] do_writepages+0x1a/0x70 [ 1954.782128] __filemap_fdatawrite_range+0x71/0x90 [ 1954.782147] ext4_rename+0x600/0x830 [ext4] [ 1954.782154] ? legitimize_path.isra.54+0x28/0x50 [ 1954.782160] ? terminate_walk+0x55/0xb0 [ 1954.782165] vfs_rename+0x1df/0x6d0 [ 1954.782172] ? __d_lookup+0x111/0x130 [ 1954.782177] SyS_rename+0x325/0x390 [ 1954.782183] do_syscall_64+0x75/0x1a0 [ 1954.782188] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.782192] RIP: 0033:0x146b9f33ca67 [ 1954.782194] RSP: 002b:00007fffe33828b8 EFLAGS: 00000202 ORIG_RAX: 0000000000000052 [ 1954.782199] RAX: ffffffffffffffda RBX: 000000000000001d RCX: 0000146b9f33ca67 [ 1954.782202] RDX: 0000000000000000 RSI: 000000000233b910 RDI: 000000000233c110 [ 1954.782205] RBP: 000000000232a390 R08: 000000000233c260 R09: 0000146b9fd59700 [ 1954.782208] R10: 0000000000000000 R11: 0000000000000202 R12: 000000000233c180 [ 1954.782211] R13: 000000000233b910 R14: 0000000000000000 R15: 0000000000000006 [ 1954.782217] INFO: task gcc:19683 blocked for more than 480 seconds. [ 1954.782220] Tainted: G E 4.15.3-smp #8 [ 1954.782222] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.782225] gcc D 0 19683 19682 0x00000000 [ 1954.782229] Call Trace: [ 1954.782236] ? __schedule+0x268/0x840 [ 1954.782242] schedule+0x32/0x80 [ 1954.782247] io_schedule+0x12/0x40 [ 1954.782252] blk_mq_get_tag+0x11e/0x230 [ 1954.782257] ? elv_merge+0x66/0xe0 [ 1954.782262] ? remove_wait_queue+0x60/0x60 [ 1954.782269] blk_mq_get_request+0xcc/0x340 [ 1954.782274] blk_mq_make_request+0xf8/0x580 [ 1954.782279] generic_make_request+0xfd/0x2d0 [ 1954.782284] submit_bio+0x5e/0x120 [ 1954.782302] ? __ext4_journal_stop+0x37/0xa0 [ext4] [ 1954.782320] ext4_io_submit+0x48/0x60 [ext4] [ 1954.782338] ext4_writepages+0x64a/0xe50 [ext4] [ 1954.782347] do_writepages+0x1a/0x70 [ 1954.782352] __filemap_fdatawrite_range+0x71/0x90 [ 1954.782370] ext4_rename+0x600/0x830 [ext4] [ 1954.782376] ? legitimize_path.isra.54+0x28/0x50 [ 1954.782382] ? terminate_walk+0x55/0xb0 [ 1954.782388] vfs_rename+0x1df/0x6d0 [ 1954.782394] ? __d_lookup+0x111/0x130 [ 1954.782400] SyS_rename+0x325/0x390 [ 1954.782405] do_syscall_64+0x75/0x1a0 [ 1954.782411] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.782414] RIP: 0033:0x14d933ff7a67 [ 1954.782417] RSP: 002b:00007fffc5db42c8 EFLAGS: 00000206 ORIG_RAX: 0000000000000052 [ 1954.782421] RAX: ffffffffffffffda RBX: 000000000000001d RCX: 000014d933ff7a67 [ 1954.782424] RDX: 0000000000000000 RSI: 00000000016eba00 RDI: 00000000016e7b30 [ 1954.782427] RBP: 00000000016d6390 R08: 00000000016e7c80 R09: 000014d934a14700 [ 1954.782430] R10: 0000000000000000 R11: 0000000000000206 R12: 00000000016e7ba0 [ 1954.782433] R13: 00000000016eba00 R14: 0000000000000000 R15: 0000000000000006 [ 1954.782438] INFO: task rm:19709 blocked for more than 480 seconds. [ 1954.782442] Tainted: G E 4.15.3-smp #8 [ 1954.782444] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.782446] rm D 0 19709 19687 0x00000000 [ 1954.782450] Call Trace: [ 1954.782457] ? __schedule+0x268/0x840 [ 1954.782463] schedule+0x32/0x80 [ 1954.782471] wait_transaction_locked+0x76/0xa0 [jbd2] [ 1954.782478] ? remove_wait_queue+0x60/0x60 [ 1954.782486] add_transaction_credits+0x1a4/0x280 [jbd2] [ 1954.782494] start_this_handle+0x189/0x3e0 [jbd2] [ 1954.782500] ? _cond_resched+0x15/0x30 [ 1954.782505] ? kmem_cache_alloc+0x142/0x150 [ 1954.782513] jbd2__journal_start+0xe9/0x1f0 [jbd2] [ 1954.782532] ext4_unlink+0x1ac/0x330 [ext4] [ 1954.782537] vfs_unlink+0xb1/0x1a0 [ 1954.782542] do_unlinkat+0x23b/0x280 [ 1954.782548] do_syscall_64+0x75/0x1a0 [ 1954.782553] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.782556] RIP: 0033:0x7fca75fcfba7 [ 1954.782559] RSP: 002b:00007ffdaa5b75a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000107 [ 1954.782563] RAX: ffffffffffffffda RBX: 00000000011bf770 RCX: 00007fca75fcfba7 [ 1954.782566] RDX: 0000000000000000 RSI: 00000000011bf878 RDI: 0000000000000006 [ 1954.782569] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000 [ 1954.782573] R10: 000000000000004a R11: 0000000000000246 R12: 00000000011b3fdc [ 1954.782576] R13: 00007ffdaa5b7700 R14: 00000000011bf770 R15: 0000000000000000 [ 1954.782581] INFO: task gcc:19728 blocked for more than 480 seconds. [ 1954.782584] Tainted: G E 4.15.3-smp #8 [ 1954.782586] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.782588] gcc D 0 19728 19727 0x00000000 [ 1954.782592] Call Trace: [ 1954.782599] ? __schedule+0x268/0x840 [ 1954.782603] ? filename_parentat+0xc9/0x120 [ 1954.782609] schedule+0x32/0x80 [ 1954.782614] rwsem_down_write_failed+0x1e9/0x360 [ 1954.782620] call_rwsem_down_write_failed+0x13/0x20 [ 1954.782627] down_write+0x29/0x40 [ 1954.782632] filename_create+0x66/0x150 [ 1954.782637] SyS_symlink+0x4e/0xc0 [ 1954.782642] do_syscall_64+0x75/0x1a0 [ 1954.782647] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.782650] RIP: 0033:0x147656b2cab7 [ 1954.782653] RSP: 002b:00007fff10c42988 EFLAGS: 00000206 ORIG_RAX: 0000000000000058 [ 1954.782657] RAX: ffffffffffffffda RBX: 0000000000643250 RCX: 0000147656b2cab7 [ 1954.782661] RDX: 0000000000643390 RSI: 0000000000643250 RDI: 0000000000643390 [ 1954.782664] RBP: 0000000000000000 R08: 3836333633343800 R09: 0000000000658be0 [ 1954.782667] R10: 00000000ba5a914c R11: 0000000000000206 R12: 0000000000643390 [ 1954.782670] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000006 [ 1954.782675] INFO: task gcc:19732 blocked for more than 480 seconds. [ 1954.782678] Tainted: G E 4.15.3-smp #8 [ 1954.782680] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1954.782683] gcc D 0 19732 19731 0x00000000 [ 1954.782687] Call Trace: [ 1954.782693] ? __schedule+0x268/0x840 [ 1954.782699] schedule+0x32/0x80 [ 1954.782704] io_schedule+0x12/0x40 [ 1954.782709] blk_mq_get_tag+0x11e/0x230 [ 1954.782715] ? elv_merge+0x66/0xe0 [ 1954.782720] ? remove_wait_queue+0x60/0x60 [ 1954.782727] blk_mq_get_request+0xcc/0x340 [ 1954.782732] blk_mq_make_request+0xf8/0x580 [ 1954.782737] generic_make_request+0xfd/0x2d0 [ 1954.782741] submit_bio+0x5e/0x120 [ 1954.782759] ? __ext4_journal_stop+0x37/0xa0 [ext4] [ 1954.782777] ext4_io_submit+0x48/0x60 [ext4] [ 1954.782795] ext4_writepages+0x64a/0xe50 [ext4] [ 1954.782805] do_writepages+0x1a/0x70 [ 1954.782809] __filemap_fdatawrite_range+0x71/0x90 [ 1954.782828] ext4_rename+0x600/0x830 [ext4] [ 1954.782834] ? legitimize_path.isra.54+0x28/0x50 [ 1954.782840] ? terminate_walk+0x55/0xb0 [ 1954.782846] vfs_rename+0x1df/0x6d0 [ 1954.782853] ? __d_lookup+0x111/0x130 [ 1954.782858] SyS_rename+0x325/0x390 [ 1954.782864] do_syscall_64+0x75/0x1a0 [ 1954.782869] entry_SYSCALL_64_after_hwframe+0x21/0x86 [ 1954.782872] RIP: 0033:0x15499c5b4a67 [ 1954.782875] RSP: 002b:00007fff60bd92b8 EFLAGS: 00000202 ORIG_RAX: 0000000000000052 [ 1954.782879] RAX: ffffffffffffffda RBX: 000000000000001d RCX: 000015499c5b4a67 [ 1954.782882] RDX: 0000000000000000 RSI: 0000000001966b60 RDI: 00000000019673c0 [ 1954.782886] RBP: 000000000194d2e0 R08: 0000000001967510 R09: 000015499cfd1700 [ 1954.782888] R10: 0000000000000000 R11: 0000000000000202 R12: 0000000001967430 [ 1954.782891] R13: 0000000001966b60 R14: 0000000000000000 R15: 0000000000000006
No bfq in the trace, so probably yet another problem stemming from the interaction between bfq and blk-mq. Hung tasks seem to wait indefinitely for a tag, and the only bfq patch that affects tag distribution is: a52a69ea89dc block, bfq: limit tags for writes and async I/O
So, for the next step (and as you already decided to do), please retry after adding the above commit to your initial pair: patches/block-bfq:-fix-occurrences-of-request-finish-method-s-old-name.patch patches/block-bfq:-add-requeue-request-hook.patch
Thanks, Paolo
On Tue, 2018-02-13 at 09:15 +0100, Paolo Valente wrote:
No bfq in the trace, so probably yet another problem stemming from the interaction between bfq and blk-mq. Hung tasks seem to wait indefinitely for a tag, and the only bfq patch that affects tag distribution is: a52a69ea89dc block, bfq: limit tags for writes and async I/O
So, for the next step (and as you already decided to do), please retry after adding the above commit to your initial pair: patches/block-bfq:-fix-occurrences-of-request-finish-method-s-old-name.patch patches/block-bfq:-add-requeue-request-hook.patch
I did it a bit differently, revert that commit in master, and skip it in 4.15.3 with the otherwise full set first, and saw no hangs testing either. I then added it to the 2 patch series, and was rewarded with... no bloody hang. So it's not as deterministic as it had appeared to be, there's a phase-of-moon factor. Oh. Joy.
-Mike
On Tue, 2018-02-13 at 15:30 +0100, Mike Galbraith wrote:
On Tue, 2018-02-13 at 09:15 +0100, Paolo Valente wrote:
No bfq in the trace, so probably yet another problem stemming from the interaction between bfq and blk-mq. Hung tasks seem to wait indefinitely for a tag, and the only bfq patch that affects tag distribution is: a52a69ea89dc block, bfq: limit tags for writes and async I/O
So, for the next step (and as you already decided to do), please retry after adding the above commit to your initial pair: patches/block-bfq:-fix-occurrences-of-request-finish-method-s-old-name.patch patches/block-bfq:-add-requeue-request-hook.patch
I did it a bit differently, revert that commit in master, and skip it in 4.15.3 with the otherwise full set first, and saw no hangs testing either. I then added it to the 2 patch series, and was rewarded with... no bloody hang. So it's not as deterministic as it had appeared to be, there's a phase-of-moon factor. Oh. Joy.
Bah. I'm back on 4.15.3 with the full set, and it's holding up fine too, so file this report under "elves 'n' gremlins".
-Mike
On Wed, 2018-02-14 at 06:58 +0100, Mike Galbraith wrote:
On Tue, 2018-02-13 at 15:30 +0100, Mike Galbraith wrote:
On Tue, 2018-02-13 at 09:15 +0100, Paolo Valente wrote:
No bfq in the trace, so probably yet another problem stemming from the interaction between bfq and blk-mq. Hung tasks seem to wait indefinitely for a tag, and the only bfq patch that affects tag distribution is: a52a69ea89dc block, bfq: limit tags for writes and async I/O
So, for the next step (and as you already decided to do), please retry after adding the above commit to your initial pair: patches/block-bfq:-fix-occurrences-of-request-finish-method-s-old-name.patch patches/block-bfq:-add-requeue-request-hook.patch
I did it a bit differently, revert that commit in master, and skip it in 4.15.3 with the otherwise full set first, and saw no hangs testing either. I then added it to the 2 patch series, and was rewarded with... no bloody hang. So it's not as deterministic as it had appeared to be, there's a phase-of-moon factor. Oh. Joy.
Bah. I'm back on 4.15.3 with the full set, and it's holding up fine too, so file this report under "elves 'n' gremlins".
And _of course_, roughly two minutes later, IO stalled. Ok gremlin, back to deadline I go, scoot, go wreck somebody else's day ;-)
-Mike
On Wed, 2018-02-14 at 08:04 +0100, Mike Galbraith wrote:
And _of course_, roughly two minutes later, IO stalled.
P.S.
crash> bt 19117 PID: 19117 TASK: ffff8803d2dcd280 CPU: 7 COMMAND: "kworker/7:2" #0 [ffff8803f7207bb8] __schedule at ffffffff81595e18 #1 [ffff8803f7207c40] schedule at ffffffff81596422 #2 [ffff8803f7207c50] io_schedule at ffffffff8108a832 #3 [ffff8803f7207c60] blk_mq_get_tag at ffffffff8129cd1e #4 [ffff8803f7207cc0] blk_mq_get_request at ffffffff812987cc #5 [ffff8803f7207d00] blk_mq_alloc_request at ffffffff81298a9a #6 [ffff8803f7207d38] blk_get_request_flags at ffffffff8128e674 #7 [ffff8803f7207d60] scsi_execute at ffffffffa0025b58 [scsi_mod] #8 [ffff8803f7207d98] scsi_test_unit_ready at ffffffffa002611c [scsi_mod] #9 [ffff8803f7207df8] sd_check_events at ffffffffa0212747 [sd_mod] #10 [ffff8803f7207e20] disk_check_events at ffffffff812a0f85 #11 [ffff8803f7207e78] process_one_work at ffffffff81079867 #12 [ffff8803f7207eb8] worker_thread at ffffffff8107a127 #13 [ffff8803f7207f10] kthread at ffffffff8107ef48 #14 [ffff8803f7207f50] ret_from_fork at ffffffff816001a5 crash>
Il giorno 14 feb 2018, alle ore 08:15, Mike Galbraith efault@gmx.de ha scritto:
On Wed, 2018-02-14 at 08:04 +0100, Mike Galbraith wrote:
And _of course_, roughly two minutes later, IO stalled.
P.S.
crash> bt 19117 PID: 19117 TASK: ffff8803d2dcd280 CPU: 7 COMMAND: "kworker/7:2" #0 [ffff8803f7207bb8] __schedule at ffffffff81595e18 #1 [ffff8803f7207c40] schedule at ffffffff81596422 #2 [ffff8803f7207c50] io_schedule at ffffffff8108a832 #3 [ffff8803f7207c60] blk_mq_get_tag at ffffffff8129cd1e #4 [ffff8803f7207cc0] blk_mq_get_request at ffffffff812987cc #5 [ffff8803f7207d00] blk_mq_alloc_request at ffffffff81298a9a #6 [ffff8803f7207d38] blk_get_request_flags at ffffffff8128e674 #7 [ffff8803f7207d60] scsi_execute at ffffffffa0025b58 [scsi_mod] #8 [ffff8803f7207d98] scsi_test_unit_ready at ffffffffa002611c [scsi_mod] #9 [ffff8803f7207df8] sd_check_events at ffffffffa0212747 [sd_mod] #10 [ffff8803f7207e20] disk_check_events at ffffffff812a0f85 #11 [ffff8803f7207e78] process_one_work at ffffffff81079867 #12 [ffff8803f7207eb8] worker_thread at ffffffff8107a127 #13 [ffff8803f7207f10] kthread at ffffffff8107ef48 #14 [ffff8803f7207f50] ret_from_fork at ffffffff816001a5 crash>
This has evidently to do with tag pressure. I've looked for a way to easily reduce the number of tags online, so as to put your system in the bad spot deterministically. But at no avail. Does anyone know a way to do it?
Thanks, Paolo
Hi.
14.02.2018 09:56, Paolo Valente wrote:
This has evidently to do with tag pressure. I've looked for a way to easily reduce the number of tags online, so as to put your system in the bad spot deterministically. But at no avail. Does anyone know a way to do it?
Isn't this a case for block device queue_depth? IIRC, the amount of tags is derived from it.
Oleksandr
On Wed, 2018-02-14 at 10:55 +0100, Oleksandr Natalenko wrote:
Hi.
14.02.2018 09:56, Paolo Valente wrote:
This has evidently to do with tag pressure. I've looked for a way to easily reduce the number of tags online, so as to put your system in the bad spot deterministically. But at no avail. Does anyone know a way to do it?
Isn't this a case for block device queue_depth? IIRC, the amount of tags is derived from it.
/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/queue_depth /sys/devices/pci0000:00/0000:00:1f.2/ata6/host5/target5:0:0/5:0:0:0/queue_depth /sys/devices/pci0000:00/0000:00:1f.2/ata2/host1/target1:0:0/1:0:0:0/queue_depth /sys/devices/pci0000:00/0000:00:1f.2/ata5/host4/target4:0:0/4:0:0:0/queue_depth
FWIW, these guys are all 31.
On 2/14/18 1:56 AM, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 08:15, Mike Galbraith efault@gmx.de ha scritto:
On Wed, 2018-02-14 at 08:04 +0100, Mike Galbraith wrote:
And _of course_, roughly two minutes later, IO stalled.
P.S.
crash> bt 19117 PID: 19117 TASK: ffff8803d2dcd280 CPU: 7 COMMAND: "kworker/7:2" #0 [ffff8803f7207bb8] __schedule at ffffffff81595e18 #1 [ffff8803f7207c40] schedule at ffffffff81596422 #2 [ffff8803f7207c50] io_schedule at ffffffff8108a832 #3 [ffff8803f7207c60] blk_mq_get_tag at ffffffff8129cd1e #4 [ffff8803f7207cc0] blk_mq_get_request at ffffffff812987cc #5 [ffff8803f7207d00] blk_mq_alloc_request at ffffffff81298a9a #6 [ffff8803f7207d38] blk_get_request_flags at ffffffff8128e674 #7 [ffff8803f7207d60] scsi_execute at ffffffffa0025b58 [scsi_mod] #8 [ffff8803f7207d98] scsi_test_unit_ready at ffffffffa002611c [scsi_mod] #9 [ffff8803f7207df8] sd_check_events at ffffffffa0212747 [sd_mod] #10 [ffff8803f7207e20] disk_check_events at ffffffff812a0f85 #11 [ffff8803f7207e78] process_one_work at ffffffff81079867 #12 [ffff8803f7207eb8] worker_thread at ffffffff8107a127 #13 [ffff8803f7207f10] kthread at ffffffff8107ef48 #14 [ffff8803f7207f50] ret_from_fork at ffffffff816001a5 crash>
This has evidently to do with tag pressure. I've looked for a way to easily reduce the number of tags online, so as to put your system in the bad spot deterministically. But at no avail. Does anyone know a way to do it?
The key here might be that it's not a regular file system request, which I'm sure bfq probably handles differently. So it's possible that you are slowly leaking those tags, and we end up in this miserable situation after a while.
Il giorno 14 feb 2018, alle ore 16:19, Jens Axboe axboe@kernel.dk ha scritto:
On 2/14/18 1:56 AM, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 08:15, Mike Galbraith efault@gmx.de ha scritto:
On Wed, 2018-02-14 at 08:04 +0100, Mike Galbraith wrote:
And _of course_, roughly two minutes later, IO stalled.
P.S.
crash> bt 19117 PID: 19117 TASK: ffff8803d2dcd280 CPU: 7 COMMAND: "kworker/7:2" #0 [ffff8803f7207bb8] __schedule at ffffffff81595e18 #1 [ffff8803f7207c40] schedule at ffffffff81596422 #2 [ffff8803f7207c50] io_schedule at ffffffff8108a832 #3 [ffff8803f7207c60] blk_mq_get_tag at ffffffff8129cd1e #4 [ffff8803f7207cc0] blk_mq_get_request at ffffffff812987cc #5 [ffff8803f7207d00] blk_mq_alloc_request at ffffffff81298a9a #6 [ffff8803f7207d38] blk_get_request_flags at ffffffff8128e674 #7 [ffff8803f7207d60] scsi_execute at ffffffffa0025b58 [scsi_mod] #8 [ffff8803f7207d98] scsi_test_unit_ready at ffffffffa002611c [scsi_mod] #9 [ffff8803f7207df8] sd_check_events at ffffffffa0212747 [sd_mod] #10 [ffff8803f7207e20] disk_check_events at ffffffff812a0f85 #11 [ffff8803f7207e78] process_one_work at ffffffff81079867 #12 [ffff8803f7207eb8] worker_thread at ffffffff8107a127 #13 [ffff8803f7207f10] kthread at ffffffff8107ef48 #14 [ffff8803f7207f50] ret_from_fork at ffffffff816001a5 crash>
This has evidently to do with tag pressure. I've looked for a way to easily reduce the number of tags online, so as to put your system in the bad spot deterministically. But at no avail. Does anyone know a way to do it?
The key here might be that it's not a regular file system request, which I'm sure bfq probably handles differently. So it's possible that you are slowly leaking those tags, and we end up in this miserable situation after a while.
Could you elaborate more on this? My mental model of bfq hooks in this respect is that they do only side operations, which AFAIK cannot block the putting of a tag. IOW, tag getting and putting is done outside bfq, regardless of what bfq does with I/O requests. Is there a flaw in this?
In any case, is there any flag in or the like, in requests passed to bfq, that I could make bfq check, to raise some warning?
Thanks, Paolo
-- Jens Axboe
On 2/14/18 8:39 AM, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 16:19, Jens Axboe axboe@kernel.dk ha scritto:
On 2/14/18 1:56 AM, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 08:15, Mike Galbraith efault@gmx.de ha scritto:
On Wed, 2018-02-14 at 08:04 +0100, Mike Galbraith wrote:
And _of course_, roughly two minutes later, IO stalled.
P.S.
crash> bt 19117 PID: 19117 TASK: ffff8803d2dcd280 CPU: 7 COMMAND: "kworker/7:2" #0 [ffff8803f7207bb8] __schedule at ffffffff81595e18 #1 [ffff8803f7207c40] schedule at ffffffff81596422 #2 [ffff8803f7207c50] io_schedule at ffffffff8108a832 #3 [ffff8803f7207c60] blk_mq_get_tag at ffffffff8129cd1e #4 [ffff8803f7207cc0] blk_mq_get_request at ffffffff812987cc #5 [ffff8803f7207d00] blk_mq_alloc_request at ffffffff81298a9a #6 [ffff8803f7207d38] blk_get_request_flags at ffffffff8128e674 #7 [ffff8803f7207d60] scsi_execute at ffffffffa0025b58 [scsi_mod] #8 [ffff8803f7207d98] scsi_test_unit_ready at ffffffffa002611c [scsi_mod] #9 [ffff8803f7207df8] sd_check_events at ffffffffa0212747 [sd_mod] #10 [ffff8803f7207e20] disk_check_events at ffffffff812a0f85 #11 [ffff8803f7207e78] process_one_work at ffffffff81079867 #12 [ffff8803f7207eb8] worker_thread at ffffffff8107a127 #13 [ffff8803f7207f10] kthread at ffffffff8107ef48 #14 [ffff8803f7207f50] ret_from_fork at ffffffff816001a5 crash>
This has evidently to do with tag pressure. I've looked for a way to easily reduce the number of tags online, so as to put your system in the bad spot deterministically. But at no avail. Does anyone know a way to do it?
The key here might be that it's not a regular file system request, which I'm sure bfq probably handles differently. So it's possible that you are slowly leaking those tags, and we end up in this miserable situation after a while.
Could you elaborate more on this? My mental model of bfq hooks in this respect is that they do only side operations, which AFAIK cannot block the putting of a tag. IOW, tag getting and putting is done outside bfq, regardless of what bfq does with I/O requests. Is there a flaw in this?
In any case, is there any flag in or the like, in requests passed to bfq, that I could make bfq check, to raise some warning?
I'm completely guessing, and I don't know if this trace is always what Mike sees when things hang. It just seems suspect that we end up with a "special" request here, since I'm sure the regular file system requests outnumber them greatly. That raises my suspicion that the type is related.
But no, there should be no special handling on the freeing side, my guess was that BFQ ends them a bit differently.
Mike, when you see a hang like that, would it be possible for you to dump the contents of /sys/kernel/debug/block/<dev in question/* for us to inspect? That will tell us a lot about the internal state at that time.
Il giorno 14 feb 2018, alle ore 16:44, Jens Axboe axboe@kernel.dk ha scritto:
On 2/14/18 8:39 AM, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 16:19, Jens Axboe axboe@kernel.dk ha scritto:
On 2/14/18 1:56 AM, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 08:15, Mike Galbraith efault@gmx.de ha scritto:
On Wed, 2018-02-14 at 08:04 +0100, Mike Galbraith wrote:
And _of course_, roughly two minutes later, IO stalled.
P.S.
crash> bt 19117 PID: 19117 TASK: ffff8803d2dcd280 CPU: 7 COMMAND: "kworker/7:2" #0 [ffff8803f7207bb8] __schedule at ffffffff81595e18 #1 [ffff8803f7207c40] schedule at ffffffff81596422 #2 [ffff8803f7207c50] io_schedule at ffffffff8108a832 #3 [ffff8803f7207c60] blk_mq_get_tag at ffffffff8129cd1e #4 [ffff8803f7207cc0] blk_mq_get_request at ffffffff812987cc #5 [ffff8803f7207d00] blk_mq_alloc_request at ffffffff81298a9a #6 [ffff8803f7207d38] blk_get_request_flags at ffffffff8128e674 #7 [ffff8803f7207d60] scsi_execute at ffffffffa0025b58 [scsi_mod] #8 [ffff8803f7207d98] scsi_test_unit_ready at ffffffffa002611c [scsi_mod] #9 [ffff8803f7207df8] sd_check_events at ffffffffa0212747 [sd_mod] #10 [ffff8803f7207e20] disk_check_events at ffffffff812a0f85 #11 [ffff8803f7207e78] process_one_work at ffffffff81079867 #12 [ffff8803f7207eb8] worker_thread at ffffffff8107a127 #13 [ffff8803f7207f10] kthread at ffffffff8107ef48 #14 [ffff8803f7207f50] ret_from_fork at ffffffff816001a5 crash>
This has evidently to do with tag pressure. I've looked for a way to easily reduce the number of tags online, so as to put your system in the bad spot deterministically. But at no avail. Does anyone know a way to do it?
The key here might be that it's not a regular file system request, which I'm sure bfq probably handles differently. So it's possible that you are slowly leaking those tags, and we end up in this miserable situation after a while.
Could you elaborate more on this? My mental model of bfq hooks in this respect is that they do only side operations, which AFAIK cannot block the putting of a tag. IOW, tag getting and putting is done outside bfq, regardless of what bfq does with I/O requests. Is there a flaw in this?
In any case, is there any flag in or the like, in requests passed to bfq, that I could make bfq check, to raise some warning?
I'm completely guessing, and I don't know if this trace is always what Mike sees when things hang. It just seems suspect that we end up with a "special" request here, since I'm sure the regular file system requests outnumber them greatly. That raises my suspicion that the type is related.
But no, there should be no special handling on the freeing side, my guess was that BFQ ends them a bit differently.
Hi Jens, whatever the exact cause of leakage is, a leakage in its turn does sound like a reasonable cause for these hangs. But also if leakage is the cause, it seems to me that reducing tags to just 1 might help trigger the problem quickly and reliably on Mike's machine. If you agree, Jens, which would be the quickest/easiest way to reduce tags?
Thanks, Paolo
Mike, when you see a hang like that, would it be possible for you to dump the contents of /sys/kernel/debug/block/<dev in question/* for us to inspect? That will tell us a lot about the internal state at that time.
-- Jens Axboe
On Thu, 2018-02-15 at 19:13 +0100, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 16:44, Jens Axboe axboe@kernel.dk ha scritto:
On 2/14/18 8:39 AM, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 16:19, Jens Axboe axboe@kernel.dk ha scritto:
On 2/14/18 1:56 AM, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 08:15, Mike Galbraith efault@gmx.de ha scritto:
On Wed, 2018-02-14 at 08:04 +0100, Mike Galbraith wrote: > > And _of course_, roughly two minutes later, IO stalled.
P.S.
crash> bt 19117 PID: 19117 TASK: ffff8803d2dcd280 CPU: 7 COMMAND: "kworker/7:2" #0 [ffff8803f7207bb8] __schedule at ffffffff81595e18 #1 [ffff8803f7207c40] schedule at ffffffff81596422 #2 [ffff8803f7207c50] io_schedule at ffffffff8108a832 #3 [ffff8803f7207c60] blk_mq_get_tag at ffffffff8129cd1e #4 [ffff8803f7207cc0] blk_mq_get_request at ffffffff812987cc #5 [ffff8803f7207d00] blk_mq_alloc_request at ffffffff81298a9a #6 [ffff8803f7207d38] blk_get_request_flags at ffffffff8128e674 #7 [ffff8803f7207d60] scsi_execute at ffffffffa0025b58 [scsi_mod] #8 [ffff8803f7207d98] scsi_test_unit_ready at ffffffffa002611c [scsi_mod] #9 [ffff8803f7207df8] sd_check_events at ffffffffa0212747 [sd_mod] #10 [ffff8803f7207e20] disk_check_events at ffffffff812a0f85 #11 [ffff8803f7207e78] process_one_work at ffffffff81079867 #12 [ffff8803f7207eb8] worker_thread at ffffffff8107a127 #13 [ffff8803f7207f10] kthread at ffffffff8107ef48 #14 [ffff8803f7207f50] ret_from_fork at ffffffff816001a5 crash>
This has evidently to do with tag pressure. I've looked for a way to easily reduce the number of tags online, so as to put your system in the bad spot deterministically. But at no avail. Does anyone know a way to do it?
The key here might be that it's not a regular file system request, which I'm sure bfq probably handles differently. So it's possible that you are slowly leaking those tags, and we end up in this miserable situation after a while.
Could you elaborate more on this? My mental model of bfq hooks in this respect is that they do only side operations, which AFAIK cannot block the putting of a tag. IOW, tag getting and putting is done outside bfq, regardless of what bfq does with I/O requests. Is there a flaw in this?
In any case, is there any flag in or the like, in requests passed to bfq, that I could make bfq check, to raise some warning?
I'm completely guessing, and I don't know if this trace is always what Mike sees when things hang. It just seems suspect that we end up with a "special" request here, since I'm sure the regular file system requests outnumber them greatly. That raises my suspicion that the type is related.
But no, there should be no special handling on the freeing side, my guess was that BFQ ends them a bit differently.
Hi Jens, whatever the exact cause of leakage is, a leakage in its turn does sound like a reasonable cause for these hangs. But also if leakage is the cause, it seems to me that reducing tags to just 1 might help trigger the problem quickly and reliably on Mike's machine. If you agree, Jens, which would be the quickest/easiest way to reduce tags?
Whatever the cause, seems this wants some instrumentation that can be left in place for a while. I turned on CONFIG_BLK_DEBUG_FS for Jens, but the little bugger didn't raise it's ugly head all day long.
What you need most is more reproducers. My box swears there's something amiss, and that something is BFQ.. but it's alone.
-Mike
Il giorno 16 feb 2018, alle ore 06:39, Mike Galbraith efault@gmx.de ha scritto:
On Thu, 2018-02-15 at 19:13 +0100, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 16:44, Jens Axboe axboe@kernel.dk ha scritto:
On 2/14/18 8:39 AM, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 16:19, Jens Axboe axboe@kernel.dk ha scritto:
On 2/14/18 1:56 AM, Paolo Valente wrote:
> Il giorno 14 feb 2018, alle ore 08:15, Mike Galbraith efault@gmx.de ha scritto: > > On Wed, 2018-02-14 at 08:04 +0100, Mike Galbraith wrote: >> >> And _of course_, roughly two minutes later, IO stalled. > > P.S. > > crash> bt 19117 > PID: 19117 TASK: ffff8803d2dcd280 CPU: 7 COMMAND: "kworker/7:2" > #0 [ffff8803f7207bb8] __schedule at ffffffff81595e18 > #1 [ffff8803f7207c40] schedule at ffffffff81596422 > #2 [ffff8803f7207c50] io_schedule at ffffffff8108a832 > #3 [ffff8803f7207c60] blk_mq_get_tag at ffffffff8129cd1e > #4 [ffff8803f7207cc0] blk_mq_get_request at ffffffff812987cc > #5 [ffff8803f7207d00] blk_mq_alloc_request at ffffffff81298a9a > #6 [ffff8803f7207d38] blk_get_request_flags at ffffffff8128e674 > #7 [ffff8803f7207d60] scsi_execute at ffffffffa0025b58 [scsi_mod] > #8 [ffff8803f7207d98] scsi_test_unit_ready at ffffffffa002611c [scsi_mod] > #9 [ffff8803f7207df8] sd_check_events at ffffffffa0212747 [sd_mod] > #10 [ffff8803f7207e20] disk_check_events at ffffffff812a0f85 > #11 [ffff8803f7207e78] process_one_work at ffffffff81079867 > #12 [ffff8803f7207eb8] worker_thread at ffffffff8107a127 > #13 [ffff8803f7207f10] kthread at ffffffff8107ef48 > #14 [ffff8803f7207f50] ret_from_fork at ffffffff816001a5 > crash>
This has evidently to do with tag pressure. I've looked for a way to easily reduce the number of tags online, so as to put your system in the bad spot deterministically. But at no avail. Does anyone know a way to do it?
The key here might be that it's not a regular file system request, which I'm sure bfq probably handles differently. So it's possible that you are slowly leaking those tags, and we end up in this miserable situation after a while.
Could you elaborate more on this? My mental model of bfq hooks in this respect is that they do only side operations, which AFAIK cannot block the putting of a tag. IOW, tag getting and putting is done outside bfq, regardless of what bfq does with I/O requests. Is there a flaw in this?
In any case, is there any flag in or the like, in requests passed to bfq, that I could make bfq check, to raise some warning?
I'm completely guessing, and I don't know if this trace is always what Mike sees when things hang. It just seems suspect that we end up with a "special" request here, since I'm sure the regular file system requests outnumber them greatly. That raises my suspicion that the type is related.
But no, there should be no special handling on the freeing side, my guess was that BFQ ends them a bit differently.
Hi Jens, whatever the exact cause of leakage is, a leakage in its turn does sound like a reasonable cause for these hangs. But also if leakage is the cause, it seems to me that reducing tags to just 1 might help trigger the problem quickly and reliably on Mike's machine. If you agree, Jens, which would be the quickest/easiest way to reduce tags?
Whatever the cause, seems this wants some instrumentation that can be left in place for a while. I turned on CONFIG_BLK_DEBUG_FS for Jens, but the little bugger didn't raise it's ugly head all day long.
What you need most is more reproducers.
Yeah, which is however out of our control. That's why I'm nagging Jens, and other knowledgeable people, for that trick to hopefully push your system to quick failure.
Paolo
Il giorno 16 feb 2018, alle ore 06:39, Mike Galbraith efault@gmx.de ha scritto:
On Thu, 2018-02-15 at 19:13 +0100, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 16:44, Jens Axboe axboe@kernel.dk ha scritto:
On 2/14/18 8:39 AM, Paolo Valente wrote:
Il giorno 14 feb 2018, alle ore 16:19, Jens Axboe axboe@kernel.dk ha scritto:
On 2/14/18 1:56 AM, Paolo Valente wrote:
> Il giorno 14 feb 2018, alle ore 08:15, Mike Galbraith efault@gmx.de ha scritto: > > On Wed, 2018-02-14 at 08:04 +0100, Mike Galbraith wrote: >> >> And _of course_, roughly two minutes later, IO stalled. > > P.S. > > crash> bt 19117 > PID: 19117 TASK: ffff8803d2dcd280 CPU: 7 COMMAND: "kworker/7:2" > #0 [ffff8803f7207bb8] __schedule at ffffffff81595e18 > #1 [ffff8803f7207c40] schedule at ffffffff81596422 > #2 [ffff8803f7207c50] io_schedule at ffffffff8108a832 > #3 [ffff8803f7207c60] blk_mq_get_tag at ffffffff8129cd1e > #4 [ffff8803f7207cc0] blk_mq_get_request at ffffffff812987cc > #5 [ffff8803f7207d00] blk_mq_alloc_request at ffffffff81298a9a > #6 [ffff8803f7207d38] blk_get_request_flags at ffffffff8128e674 > #7 [ffff8803f7207d60] scsi_execute at ffffffffa0025b58 [scsi_mod] > #8 [ffff8803f7207d98] scsi_test_unit_ready at ffffffffa002611c [scsi_mod] > #9 [ffff8803f7207df8] sd_check_events at ffffffffa0212747 [sd_mod] > #10 [ffff8803f7207e20] disk_check_events at ffffffff812a0f85 > #11 [ffff8803f7207e78] process_one_work at ffffffff81079867 > #12 [ffff8803f7207eb8] worker_thread at ffffffff8107a127 > #13 [ffff8803f7207f10] kthread at ffffffff8107ef48 > #14 [ffff8803f7207f50] ret_from_fork at ffffffff816001a5 > crash>
This has evidently to do with tag pressure. I've looked for a way to easily reduce the number of tags online, so as to put your system in the bad spot deterministically. But at no avail. Does anyone know a way to do it?
The key here might be that it's not a regular file system request, which I'm sure bfq probably handles differently. So it's possible that you are slowly leaking those tags, and we end up in this miserable situation after a while.
Could you elaborate more on this? My mental model of bfq hooks in this respect is that they do only side operations, which AFAIK cannot block the putting of a tag. IOW, tag getting and putting is done outside bfq, regardless of what bfq does with I/O requests. Is there a flaw in this?
In any case, is there any flag in or the like, in requests passed to bfq, that I could make bfq check, to raise some warning?
I'm completely guessing, and I don't know if this trace is always what Mike sees when things hang. It just seems suspect that we end up with a "special" request here, since I'm sure the regular file system requests outnumber them greatly. That raises my suspicion that the type is related.
But no, there should be no special handling on the freeing side, my guess was that BFQ ends them a bit differently.
Hi Jens, whatever the exact cause of leakage is, a leakage in its turn does sound like a reasonable cause for these hangs. But also if leakage is the cause, it seems to me that reducing tags to just 1 might help trigger the problem quickly and reliably on Mike's machine. If you agree, Jens, which would be the quickest/easiest way to reduce tags?
Whatever the cause, seems this wants some instrumentation that can be left in place for a while. I turned on CONFIG_BLK_DEBUG_FS for Jens, but the little bugger didn't raise it's ugly head all day long.
What you need most is more reproducers.
Yeah, which is however out of our control. That's why I'm nagging Jens, and other knowledgeable people, for that trick to hopefully push your system to quick failure.
Paolo
On Wed, 2018-02-14 at 08:44 -0700, Jens Axboe wrote:
Mike, when you see a hang like that, would it be possible for you to dump the contents of /sys/kernel/debug/block/<dev in question/* for us to inspect? That will tell us a lot about the internal state at that time.
Finally. 4.15.4 stalled this morning while building other updated trees.
#!/bin/sh
for i in `find /sys/kernel/debug/block/sd[bd] -type f` do echo $i: cat $i echo done
/sys/kernel/debug/block/sdb/hctx0/cpu7/completed: 7483 4884
/sys/kernel/debug/block/sdb/hctx0/cpu7/merged: 0
/sys/kernel/debug/block/sdb/hctx0/cpu7/dispatched: 7483 4884
/sys/kernel/debug/block/sdb/hctx0/cpu7/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu6/completed: 12240 7814
/sys/kernel/debug/block/sdb/hctx0/cpu6/merged: 0
/sys/kernel/debug/block/sdb/hctx0/cpu6/dispatched: 12240 7814
/sys/kernel/debug/block/sdb/hctx0/cpu6/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu5/completed: 8549 7842
/sys/kernel/debug/block/sdb/hctx0/cpu5/merged: 0
/sys/kernel/debug/block/sdb/hctx0/cpu5/dispatched: 8549 7842
/sys/kernel/debug/block/sdb/hctx0/cpu5/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu4/completed: 10115 5073
/sys/kernel/debug/block/sdb/hctx0/cpu4/merged: 0
/sys/kernel/debug/block/sdb/hctx0/cpu4/dispatched: 10115 5073
/sys/kernel/debug/block/sdb/hctx0/cpu4/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu3/completed: 13181 4867
/sys/kernel/debug/block/sdb/hctx0/cpu3/merged: 0
/sys/kernel/debug/block/sdb/hctx0/cpu3/dispatched: 13181 4867
/sys/kernel/debug/block/sdb/hctx0/cpu3/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu2/completed: 101270 9089
/sys/kernel/debug/block/sdb/hctx0/cpu2/merged: 0
/sys/kernel/debug/block/sdb/hctx0/cpu2/dispatched: 101270 9089
/sys/kernel/debug/block/sdb/hctx0/cpu2/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu1/completed: 8158 4392
/sys/kernel/debug/block/sdb/hctx0/cpu1/merged: 0
/sys/kernel/debug/block/sdb/hctx0/cpu1/dispatched: 8158 4392
/sys/kernel/debug/block/sdb/hctx0/cpu1/rq_list:
/sys/kernel/debug/block/sdb/hctx0/cpu0/completed: 8605 5819
/sys/kernel/debug/block/sdb/hctx0/cpu0/merged: 0
/sys/kernel/debug/block/sdb/hctx0/cpu0/dispatched: 8605 5819
/sys/kernel/debug/block/sdb/hctx0/cpu0/rq_list:
/sys/kernel/debug/block/sdb/hctx0/active: 0
/sys/kernel/debug/block/sdb/hctx0/run: 373736
/sys/kernel/debug/block/sdb/hctx0/queued: 219336
/sys/kernel/debug/block/sdb/hctx0/dispatched: 0 7629 1 216748 2 446 4 0 8 0 16 0 32+ 0
/sys/kernel/debug/block/sdb/hctx0/io_poll: considered=0 invoked=0 success=0
/sys/kernel/debug/block/sdb/hctx0/sched_tags_bitmap: 00000000: 0000 0000 0000 0000
/sys/kernel/debug/block/sdb/hctx0/sched_tags: nr_tags=62 nr_reserved_tags=0 active_queues=0
bitmap_tags: depth=62 busy=0 bits_per_word=8 map_nr=8 alloc_hint={9, 1, 3, 0, 17, 0, 9, 17} wake_batch=7 wake_index=4 ws={ {.wait_cnt=7, .wait=active}, {.wait_cnt=7, .wait=active}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=1, .wait=active}, {.wait_cnt=7, .wait=active}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=active}, } round_robin=1
/sys/kernel/debug/block/sdb/hctx0/tags_bitmap: 00000000: 0000 0000
/sys/kernel/debug/block/sdb/hctx0/tags: nr_tags=31 nr_reserved_tags=0 active_queues=0
bitmap_tags: depth=31 busy=0 bits_per_word=4 map_nr=8 alloc_hint={3, 12, 2, 9, 18, 2, 4, 11} wake_batch=3 wake_index=0 ws={ {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, } round_robin=1
/sys/kernel/debug/block/sdb/hctx0/ctx_map: 00000000: 00
/sys/kernel/debug/block/sdb/hctx0/busy:
/sys/kernel/debug/block/sdb/hctx0/dispatch:
/sys/kernel/debug/block/sdb/hctx0/flags: alloc_policy=RR SHOULD_MERGE|SG_MERGE
/sys/kernel/debug/block/sdb/hctx0/state:
/sys/kernel/debug/block/sdb/write_hints: hint0: 0 hint1: 0 hint2: 0 hint3: 0 hint4: 0
/sys/kernel/debug/block/sdb/state: SAME_COMP|IO_STAT|INIT_DONE|POLL|WC|FLUSH_NQ|REGISTERED|SCSI_PASSTHROUGH
/sys/kernel/debug/block/sdb/requeue_list:
/sys/kernel/debug/block/sdb/poll_stat: read (512 Bytes): samples=0 write (512 Bytes): samples=0 read (1024 Bytes): samples=0 write (1024 Bytes): samples=0 read (2048 Bytes): samples=0 write (2048 Bytes): samples=0 read (4096 Bytes): samples=0 write (4096 Bytes): samples=0 read (8192 Bytes): samples=0 write (8192 Bytes): samples=0 read (16384 Bytes): samples=0 write (16384 Bytes): samples=0 read (32768 Bytes): samples=0 write (32768 Bytes): samples=0 read (65536 Bytes): samples=0 write (65536 Bytes): samples=0
/sys/kernel/debug/block/sdd/hctx0/cpu7/completed: 2642 5235
/sys/kernel/debug/block/sdd/hctx0/cpu7/merged: 0
/sys/kernel/debug/block/sdd/hctx0/cpu7/dispatched: 2642 5235
/sys/kernel/debug/block/sdd/hctx0/cpu7/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu6/completed: 2873 15051
/sys/kernel/debug/block/sdd/hctx0/cpu6/merged: 0
/sys/kernel/debug/block/sdd/hctx0/cpu6/dispatched: 2873 15051
/sys/kernel/debug/block/sdd/hctx0/cpu6/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu5/completed: 3212 13912
/sys/kernel/debug/block/sdd/hctx0/cpu5/merged: 0
/sys/kernel/debug/block/sdd/hctx0/cpu5/dispatched: 3212 13912
/sys/kernel/debug/block/sdd/hctx0/cpu5/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu4/completed: 4304 8158
/sys/kernel/debug/block/sdd/hctx0/cpu4/merged: 0
/sys/kernel/debug/block/sdd/hctx0/cpu4/dispatched: 4304 8158
/sys/kernel/debug/block/sdd/hctx0/cpu4/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu3/completed: 3034 6275
/sys/kernel/debug/block/sdd/hctx0/cpu3/merged: 0
/sys/kernel/debug/block/sdd/hctx0/cpu3/dispatched: 3034 6275
/sys/kernel/debug/block/sdd/hctx0/cpu3/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu2/completed: 10339 21025
/sys/kernel/debug/block/sdd/hctx0/cpu2/merged: 0
/sys/kernel/debug/block/sdd/hctx0/cpu2/dispatched: 10339 21025
/sys/kernel/debug/block/sdd/hctx0/cpu2/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu1/completed: 3237 9737
/sys/kernel/debug/block/sdd/hctx0/cpu1/merged: 0
/sys/kernel/debug/block/sdd/hctx0/cpu1/dispatched: 3237 9737
/sys/kernel/debug/block/sdd/hctx0/cpu1/rq_list:
/sys/kernel/debug/block/sdd/hctx0/cpu0/completed: 1490 6101
/sys/kernel/debug/block/sdd/hctx0/cpu0/merged: 0
/sys/kernel/debug/block/sdd/hctx0/cpu0/dispatched: 1490 6101
/sys/kernel/debug/block/sdd/hctx0/cpu0/rq_list:
/sys/kernel/debug/block/sdd/hctx0/active: 0
/sys/kernel/debug/block/sdd/hctx0/run: 116625
/sys/kernel/debug/block/sdd/hctx0/queued: 116625
/sys/kernel/debug/block/sdd/hctx0/dispatched: 0 2438 1 116700 2 92 4 0 8 0 16 0 32+ 0
/sys/kernel/debug/block/sdd/hctx0/io_poll: considered=0 invoked=0 success=0
/sys/kernel/debug/block/sdd/hctx0/sched_tags_bitmap: 00000000: 0000 0000 0000 0000
/sys/kernel/debug/block/sdd/hctx0/sched_tags: nr_tags=62 nr_reserved_tags=0 active_queues=0
bitmap_tags: depth=62 busy=0 bits_per_word=8 map_nr=8 alloc_hint={9, 51, 57, 0, 0, 2, 2, 21} wake_batch=7 wake_index=0 ws={ {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, {.wait_cnt=7, .wait=inactive}, } round_robin=1
/sys/kernel/debug/block/sdd/hctx0/tags_bitmap: 00000000: 0000 0000
/sys/kernel/debug/block/sdd/hctx0/tags: nr_tags=31 nr_reserved_tags=0 active_queues=0
bitmap_tags: depth=31 busy=0 bits_per_word=4 map_nr=8 alloc_hint={7, 21, 26, 26, 25, 2, 22, 6} wake_batch=3 wake_index=0 ws={ {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, {.wait_cnt=3, .wait=inactive}, } round_robin=1
/sys/kernel/debug/block/sdd/hctx0/ctx_map: 00000000: 00
/sys/kernel/debug/block/sdd/hctx0/busy:
/sys/kernel/debug/block/sdd/hctx0/dispatch:
/sys/kernel/debug/block/sdd/hctx0/flags: alloc_policy=RR SHOULD_MERGE|SG_MERGE
/sys/kernel/debug/block/sdd/hctx0/state:
/sys/kernel/debug/block/sdd/write_hints: hint0: 0 hint1: 0 hint2: 0 hint3: 0 hint4: 0
/sys/kernel/debug/block/sdd/state: SAME_COMP|IO_STAT|INIT_DONE|POLL|WC|FLUSH_NQ|REGISTERED|SCSI_PASSTHROUGH
/sys/kernel/debug/block/sdd/requeue_list:
/sys/kernel/debug/block/sdd/poll_stat: read (512 Bytes): samples=0 write (512 Bytes): samples=0 read (1024 Bytes): samples=0 write (1024 Bytes): samples=0 read (2048 Bytes): samples=0 write (2048 Bytes): samples=0 read (4096 Bytes): samples=0 write (4096 Bytes): samples=0 read (8192 Bytes): samples=0 write (8192 Bytes): samples=0 read (16384 Bytes): samples=0 write (16384 Bytes): samples=0 read (32768 Bytes): samples=0 write (32768 Bytes): samples=0 read (65536 Bytes): samples=0 write (65536 Bytes): samples=0
homer:..crash/2018-02-17-06:12 # grep blk_mq_get_tag bta #3 [ffff8803f794b7e8] blk_mq_get_tag at ffffffff8129cf8e #3 [ffff88035ef139b8] blk_mq_get_tag at ffffffff8129cf8e #3 [ffff8802430439b8] blk_mq_get_tag at ffffffff8129cf8e #3 [ffff880290fbb9b8] blk_mq_get_tag at ffffffff8129cf8e
FWIW, my box spent the weekend running a kbuild marathon with a52a69ea reverted, has convinced me that it _is_ the source of the hang woes (directly or indirectly). No outright stalls, no stall for way too long but then recover, nada, not the slightest hint of trouble.
-Mike
On Mon, 2018-02-19 at 07:05 +0100, Oleksandr Natalenko wrote:
On pondělí 19. února 2018 6:34:44 CET Mike Galbraith wrote:
a52a69ea
…which is strange as I'm running it since the very beginning w/o any troubles on 4 machines (hence my tested-by tag there)…
My box routinely bitches about stuff with signed-off-by's and tested- by's, it has no respect at all for other boxen's opinions :) It's the only box bitching, so salt to taste.. but it remains adamant.
-Mike
On Mon, 2018-02-19 at 08:09 +0100, Mike Galbraith wrote:
On Mon, 2018-02-19 at 07:05 +0100, Oleksandr Natalenko wrote:
On pondělí 19. února 2018 6:34:44 CET Mike Galbraith wrote:
a52a69ea
…which is strange as I'm running it since the very beginning w/o any troubles on 4 machines (hence my tested-by tag there)…
My box routinely bitches about stuff with signed-off-by's and tested- by's, it has no respect at all for other boxen's opinions :) It's the only box bitching, so salt to taste.. but it remains adamant.
Given it is the only one, and whatever the problem being so non- deterministic, ignoring my box, shipping the lot off to stable then wait and see seems perfectly reasonable. It won't be any worse off.
-Mike
Il giorno 19 feb 2018, alle ore 06:34, Mike Galbraith efault@gmx.de ha scritto:
FWIW, my box spent the weekend running a kbuild marathon with a52a69ea reverted, has convinced me that it _is_ the source of the hang woes (directly or indirectly). No outright stalls, no stall for way too long but then recover, nada, not the slightest hint of trouble.
ok, after this piece of evidence, and while waiting for more authoritative suggestions, I have investigated a little bit how to reduce the number of your angry tags available, to hopefully push your system so close to failure to have your problem reproduced reliably and quickly.
The only easy way seems to be that you, as root, issue an echo 4 > /sys/block/sda/queue/nr_requests (nr_requests is lower-bounded to 4)
NOTE: do/repeat this *after* you switch to a new scheduler, because a scheduler switch restores a high 62 value.
Reducing nr_requests does not change the value of the nr_tags parameter, but, according to the code, it should de facto reduce the number of available tags, by reducing the depth of the bitmaps of free tags.
Thanks, Paolo
-Mike
On Mon, 2018-02-19 at 10:37 +0100, Paolo Valente wrote:
Il giorno 19 feb 2018, alle ore 06:34, Mike Galbraith efault@gmx.de ha scritto:
FWIW, my box spent the weekend running a kbuild marathon with a52a69ea reverted, has convinced me that it _is_ the source of the hang woes (directly or indirectly). No outright stalls, no stall for way too long but then recover, nada, not the slightest hint of trouble.
ok, after this piece of evidence, and while waiting for more authoritative suggestions, I have investigated a little bit how to reduce the number of your angry tags available, to hopefully push your system so close to failure to have your problem reproduced reliably and quickly.
Neither wish came true.
-Mike
On Sat, 2018-02-17 at 06:30 +0100, Mike Galbraith wrote:
On Wed, 2018-02-14 at 08:44 -0700, Jens Axboe wrote:
Mike, when you see a hang like that, would it be possible for you to dump the contents of /sys/kernel/debug/block/<dev in question/* for us to inspect? That will tell us a lot about the internal state at that time.
Finally. 4.15.4 stalled this morning while building other updated trees.
#!/bin/sh
for i in `find /sys/kernel/debug/block/sd[bd] -type f` do echo $i: cat $i echo done
sdd was idle.. should have chopped that off.
On Mon, Feb 12, 2018 at 01:48:28PM +0100, Oleksandr Natalenko wrote:
Hi.
12.02.2018 12:22, Mike Galbraith wrote:
How does that work without someone actually submitting patches? CC stable and pass along a conveniently sorted cherry-pick list?
From my experience, Greg is fine with the list of hashes, but he needs an approval from the relevant subtree maintainer (Jens in this case).
Yes, that's fine with me.
What ever happened to this? Do you have a list of patches I should apply? Or a patch series?
thanks,
greg k-h
Hi.
On pondělí 26. února 2018 20:48:33 CET Greg KH wrote:
Yes, that's fine with me.
What ever happened to this? Do you have a list of patches I should apply? Or a patch series?
Here are BFQ commits that are already merged into Linus' tree:
a78773906147 block, bfq: add requeue-request hook 8a8747dc01ce block, bfq: limit sectors served with interactive weight raising a52a69ea89dc block, bfq: limit tags for writes and async I/O 8993d445df38 block, bfq: fix occurrences of request finish method's old name 8abef10b3de1 bfq-iosched: don't call bfqg_and_blkg_put for ! CONFIG_BFQ_GROUP_IOSCHED 0d52af590552 block, bfq: release oom-queue ref to root group on exit 52257ffbfcaf block, bfq: put async queues for root bfq groups too 9b25bd0368d5 block, bfq: remove batches of confusing ifdefs a34b024448eb block, bfq: consider also past I/O in soft real-time detection 4403e4e467c3 block, bfq: remove superfluous check in queue-merging setup 7b8fa3b900a0 block, bfq: let a queue be merged only shortly after starting I/O 1be6e8a964ee block, bfq: check low_latency flag in bfq_bfqq_save_state() 05e902835616 block, bfq: add missing rq_pos_tree update on rq removal f0ba5ea2fe45 block, bfq: increase threshold to deem I/O as random
Paolo, could you please confirm we are not missing anything here?
Oleksandr
On 2/26/18 1:10 PM, Oleksandr Natalenko wrote:
Hi.
On pondělí 26. února 2018 20:48:33 CET Greg KH wrote:
Yes, that's fine with me.
What ever happened to this? Do you have a list of patches I should apply? Or a patch series?
Here are BFQ commits that are already merged into Linus' tree:
a78773906147 block, bfq: add requeue-request hook 8a8747dc01ce block, bfq: limit sectors served with interactive weight raising a52a69ea89dc block, bfq: limit tags for writes and async I/O 8993d445df38 block, bfq: fix occurrences of request finish method's old name 8abef10b3de1 bfq-iosched: don't call bfqg_and_blkg_put for ! CONFIG_BFQ_GROUP_IOSCHED 0d52af590552 block, bfq: release oom-queue ref to root group on exit 52257ffbfcaf block, bfq: put async queues for root bfq groups too 9b25bd0368d5 block, bfq: remove batches of confusing ifdefs a34b024448eb block, bfq: consider also past I/O in soft real-time detection 4403e4e467c3 block, bfq: remove superfluous check in queue-merging setup 7b8fa3b900a0 block, bfq: let a queue be merged only shortly after starting I/O 1be6e8a964ee block, bfq: check low_latency flag in bfq_bfqq_save_state() 05e902835616 block, bfq: add missing rq_pos_tree update on rq removal f0ba5ea2fe45 block, bfq: increase threshold to deem I/O as random
Paolo, could you please confirm we are not missing anything here?
Guys, this is crazy, I'm not going to ack this for stable backports. This is everything including code cleanups.
linux-stable-mirror@lists.linaro.org
-
Greg KH -
Jens Axboe -
Mike Galbraith -
Oleksandr Natalenko -
Paolo Valente