Re: [PATCH FIXES/IMPROVEMENTS 0/7] block, bfq: preserve control, boost throughput, fix bugs

[Jan Kara <jack@suse.cz>]

On Mon 02-08-21 22:40:26, Oleksandr Natalenko wrote:
> Hello.
> 
> On sobota 3. července 2021 0:07:53 CEST Oleksandr Natalenko wrote:
> > On úterý 22. června 2021 18:29:48 CEST Jan Kara wrote:
> > > On Tue 22-06-21 09:35:05, Oleksandr Natalenko wrote:
> > > > On úterý 22. června 2021 9:08:43 CEST Paolo Valente wrote:
> > > > > CCing also Jan and Khazhy, because in your commit log I see also the
> > > > > commit on bfq_requests_merged().
> > > > > 
> > > > > Is this OOPS reproducible for you?
> > > > 
> > > > No, I haven't found a reproducer, at least yet. It took half a day of
> > > > uptime to hit this, so might not be that easy.
> > > 
> > > Hum, if you can acquire a crash dump it would be the easiest I guess. We'd
> > > need to find out more about the request we crash on - whether it's
> > > otherwise valid, in what state it is etc...
> > 
> > Still have no reliable reproducer and no vmcore, however I'm running v5.13
> > with the following patches applied on top of it:
> > 
> > ```
> > blk: Fix lock inversion between ioc lock and bfqd lock
> > bfq: Remove merged request already in bfq_requests_merged()
> > block: Remove unnecessary elevator operation checks
> > block: Do not pull requests from the scheduler when we cannot dispatch them
> > block, bfq: reset waker pointer with shared queues
> > block, bfq: check waker only for queues with no in-flight I/O
> > block, bfq: avoid delayed merge of async queues
> > block, bfq: boost throughput by extending queue-merging times
> > block, bfq: consider also creation time in delayed stable merge
> > block, bfq: fix delayed stable merge check
> > block, bfq: let also stably merged queues enjoy weight raising
> > ```
> > 
> > and just got the following crash:
> > 
> > ```
> > [60313.522570] ------------[ cut here ]------------
> > [60313.522579] WARNING: CPU: 20 PID: 388 at arch/x86/include/asm/kfence.h:44
> > kfence_protect_page+0x39/0xc0

<snip>

> > [60313.522665] CPU: 20 PID: 388 Comm: kworker/20:1H Tainted: G        W
> > 5.13.0-pf2 #1
> > [60313.522668] Hardware name: ASUS System Product Name/Pro WS X570-ACE, BIOS
> > 3601 05/26/2021
> > [60313.522671] Workqueue: kblockd blk_mq_run_work_fn
> > [60313.522675] RIP: 0010:kfence_protect_page+0x39/0xc0
> > [60313.522679] Code: 04 65 48 8b 04 25 28 00 00 00 48 89 44 24 08 31 c0 c7
> > 44 24 04 00 00 00 00 e8 83 20 d5 ff 48 85 c0 74 07 83 7c 24 04 01 74 06
> > <0f> 0b 31 c0 eb 4c 48 8b 38 48 89 c2 84 db 75 59 48 89 f8 0f 1f 40
> > [60313.522682] RSP: 0018:ffffb559c0affb28 EFLAGS: 00010046
> > [60313.522684] RAX: 0000000000000000 RBX: 0000000000000000 RCX:
> > ffffb559c0affb2c [60313.522687] RDX: ffffb559c0affb2c RSI: 0000000000000000
> > RDI: 0000000000000000 [60313.522690] RBP: 0000000000000000 R08:
> > 0000000000000000 R09:
> > 0000000000000000
> > [60313.522692] R10: 0000000000000000 R11: 0000000000000000 R12:
> > 0000000000000002
> > [60313.522694] R13: ffffb559c0affc28 R14: 00000000c0affc01 R15:
> > 0000000000000000 [60313.522696] FS:  0000000000000000(0000)
> > GS:ffff8cf44ef00000(0000) knlGS: 0000000000000000
> > [60313.522698] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [60313.522700] CR2: 0000000000000120 CR3: 000000013ebce000 CR4:
> > 0000000000350ee0
> > [60313.522702] Call Trace:
> > [60313.522707]  kfence_handle_page_fault+0xa6/0x280
> > [60313.522710]  page_fault_oops+0x9d/0x2d0
> > [60313.522714]  exc_page_fault+0x78/0x180
> > [60313.522718]  asm_exc_page_fault+0x1e/0x30
> > [60313.522721] RIP: 0010:bfq_dispatch_request+0x4c3/0x1280
> > [60313.522725] Code: 4c 89 e7 e8 ef da ff ff 4c 89 ff 89 c6 e8 75 64 00 00
> > 4c 39 bb a0 00 00 00 0f 84 86 04 00 00 49 8b 84 24 90 00 00 00 48 8b 33
> > <ff> 80 20 01 00 00 48 89 34 24 48 8b 46 08 4c 8b 58 08 4c 89 5c 24
> > [60313.522727] RSP: 0018:ffffb559c0affcd0 EFLAGS: 00010046
> > [60313.522729] RAX: 0000000000000000 RBX: ffff8ced4d6a1000 RCX:
> > 0000000000000000 [60313.522731] RDX: 0000000000000000 RSI: ffff8ced4ad90000
> > RDI: ffff8ced52fc9f40 [60313.522733] RBP: 0000000000000000 R08:
> > 0000000000000001 R09:
> > 0000000000000000
> > [60313.522735] R10: 000000000000003f R11: 0000000000000000 R12:
> > ffff8cf20e5a5400 [60313.522737] R13: ffff8cf0e7e91c70 R14: ffff8ced4d6a1420
> > R15: ffff8cf0e7e91c70 [60313.522741]  ? mod_delayed_work_on+0x71/0xe0
> > [60313.522745]  ? __sbitmap_get_word+0x30/0x80
> > [60313.522748]  __blk_mq_do_dispatch_sched+0x218/0x320
> > [60313.522752]  __blk_mq_sched_dispatch_requests+0x107/0x150
> > [60313.522755]  blk_mq_sched_dispatch_requests+0x2f/0x60
> > [60313.522758]  blk_mq_run_work_fn+0x43/0xc0
> > [60313.522761]  process_one_work+0x24e/0x430
> > [60313.522765]  worker_thread+0x54/0x4d0
> > [60313.522767]  ? process_one_work+0x430/0x430
> > [60313.522770]  kthread+0x182/0x1b0
> > [60313.522773]  ? __kthread_init_worker+0x50/0x50
> > [60313.522776]  ret_from_fork+0x22/0x30
> > [60313.522781] ---[ end trace 55ef262e614b59af ]---

<snip>

> This is just to let you know that I'm running v5.13.7 without any extra 
> patches under block/ applied, and the issue is not reproducible.
> 
> I'll probably defer investigating this till v5.14 unless it is fixed there 
> already.

Thanks for info! I've looked some more into this. It appears the trapping
instruction is:

static void bfq_dispatch_remove(struct request_queue *q, struct request *rq)
{
        struct bfq_queue *bfqq = RQ_BFQQ(rq);

        /*
         * For consistency, the next instruction should have been
         * executed after removing the request from the queue and
         * dispatching it.  We execute instead this instruction before
         * bfq_remove_request() (and hence introduce a temporary
         * inconsistency), for efficiency.  In fact, should this
         * dispatch occur for a non in-service bfqq, this anticipated
         * increment prevents two counters related to bfqq->dispatched
         * from risking to be, first, uselessly decremented, and then
         * incremented again when the (new) value of bfqq->dispatched
         * happens to be taken into account.
         */
>>>     bfqq->dispatched++;
        bfq_update_peak_rate(q->elevator->elevator_data, rq);

        bfq_remove_request(q, rq);
}

The bfqq is in RAX and apparently is NULL. This function was called from
bfq_dispatch_rq_from_bfqq() and the above can only happen if bfqq->next_rq
was pointing to a request that was no longer attached to any bfq queue
(maybe rq was being freed?). But at this point I have no idea how this
could have possibly happened with current codebase. Can you maybe test with
5.14-rc4 to see whether current upstream has the issue?

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR