linux-kernel - 10x I/O await times in 6.12

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [day] [month] [year] [list]

Message-ID: <CAGis_TVSAPjYwVjUyur0_NFsDi9jmJ_oWhBHrJ-bEknG-nJO9Q@mail.gmail.com>
Date: Mon, 21 Apr 2025 09:53:10 +0100
From: Matt Fleming <mfleming@...udflare.com>
To: Jens Axboe <axboe@...nel.dk>
Cc: linux-block@...r.kernel.org, linux-kernel@...r.kernel.org, 
	kernel-team <kernel-team@...udflare.com>
Subject: 10x I/O await times in 6.12

Hey there,

We're moving to 6.12 at Cloudflare and noticed that write await times
in iostat are 10x what they were in 6.6. After a bit of bpftracing
(script to find all plug times above 10ms below), it seems like this
is an accounting error caused by the plug->cur_ktime optimisation
rather than anything more material.

It appears as though a task can enter __submit_bio() with ->plug set
and a very stale cur_ktime value on the order of milliseconds. Is this
expected behaviour? It looks like it leads to inaccurate I/O times.

Thanks,
Matt

---->8----
$ sudo bpftrace -e 'k:__submit_bio { $p = curtask->plug; if ($p != 0)
{ if (((nsecs - $p->cur_ktime) / 1000) > 10000) { @[kstack] =
count();}}}'
Attaching 1 probe...
^C

@[
    __submit_bio+1
    submit_bio_noacct_nocheck+390
    submit_bio_wait+92
    swap_writepage_bdev_sync+262
    swap_writepage+315
    pageout+291
    shrink_folio_list+1835
    shrink_lruvec+1683
    shrink_node+784
    balance_pgdat+877
    kswapd+496
    kthread+207
    ret_from_fork+49
    ret_from_fork_asm+26
]: 184
@[
    __submit_bio+1
    submit_bio_noacct_nocheck+390
    _xfs_buf_ioapply+599
    __xfs_buf_submit+110
    xfs_buf_delwri_submit_buffers+399
    xfsaild+691
    kthread+207
    ret_from_fork+49
    ret_from_fork_asm+26
]: 28123