linux-kernel - Re: 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>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <aAaUKenXzkFPZaMb@kbusch-mbp.dhcp.thefacebook.com>
Date: Mon, 21 Apr 2025 12:53:29 -0600
From: Keith Busch <kbusch@...nel.org>
To: Matt Fleming <mfleming@...udflare.com>
Cc: Jens Axboe <axboe@...nel.dk>, linux-block@...r.kernel.org,
	linux-kernel@...r.kernel.org,
	kernel-team <kernel-team@...udflare.com>
Subject: Re: 10x I/O await times in 6.12

On Mon, Apr 21, 2025 at 07:35:24PM +0100, Matt Fleming wrote:
> On Mon, 21 Apr 2025 at 16:22, Keith Busch <kbusch@...nel.org> wrote:
> >
> > On Mon, Apr 21, 2025 at 09:53:10AM +0100, Matt Fleming wrote:
> > > 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.
> >
> > There are places with a block plug that call cond_resched(), which
> > doesn't invalidate the plug's cached ktime. You could end up with a
> > stale ktime if your process is scheduled out.
> 
> Is that intentional? I know the cached time is invalidated when
> calling schedule(). Does the invalidation need to get pushed down into
> __schedule_loop()?
> 

Not sure. I'm also guessing cond_resched is the reason for your
observation, so that might be worth confirming is happening in whatever
IO paths you're workload is taking in case there's some other
explanation.

fs-writeback happens to work around it by unplugging if it knows
cond_resched is going to schedule. The decision to unplug here wasn't
necessarily because of the plug's ktime, but it gets the job done:

  https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/fs/fs-writeback.c?h=v6.15-rc3#n1984

Doesn't really scale well to copy this for every caller of
cond_resched(), though. An io specific helper implementation of
cond_resched might help.

Or if we don't want cond_resched to unplug (though I feel like you would
normally want that), I think we could invalidate the ktime when
scheduling to get the stats to read the current ktime after the process
is scheduled back in.

---
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -6978,6 +6978,9 @@ static void __sched notrace preempt_schedule_common(void)
 		 * between schedule and now.
 		 */
 	} while (need_resched());
+
+	if (current->flags & PF_BLOCK_TS)
+		blk_plug_invalidate_ts(current);
 }
 
 #ifdef CONFIG_PREEMPTION
--