Re: [BUG] sched/delayacct: blkio_start recorded on the wrong task when a delayed task is blocked from pick

[Christian Loehle]

On 11/3/26 06:01, kiln wrote:
> Hi,
> 
> I think there's a delay accounting bug that came in with DELAY_DEQUEUE.
> __block_task() calls delayacct_blkio_start(), and that helper always
> writes current->delays->blkio_start. That's fine when __block_task() runs
> from __schedule() for prev, but when the task was delayed and gets
> blocked later from pick_next_task_fair() -> pick_next_entity() ->
> dequeue_entities() -> __block_task(), current is whoever is scheduling on
> that CPU, not p. So p's blkio_start is never set (or is left over from
> an older sleep), and when the I/O completes ttwu() calls
> delayacct_blkio_end(p), which adds local_clock() - blkio_start to p's
> blkio_delay. For a fresh thread blkio_start is 0, so the thread gets
> charged the whole time since boot in one go.
> 
> How I ran into it: per-thread blkio delay (taskstats, and field 42 of
> /proc/<pid>/task/<tid>/stat) on some hosts showed threads that were a
> couple of seconds old with ~7,070,000 s of block I/O delay, which was
> exactly the host uptime. Always freshly created threads of a headless
> Chrome (ThreadPoolForeg, Chrome_IOThread, Compositor and so on); Chrome
> creates lots of short-lived threads that soon wait on ext4 journal I/O.
> 
> Kernel: a distro 6.6.102 kernel that carries the EEVDF / DELAY_DEQUEUE
> backport (Alibaba Cloud Linux 4, 6.6.102-7.alnx4). I have not reproduced
> it on mainline yet, but as far as I can tell the code there is the same:
> __block_task() in kernel/sched/sched.h still calls delayacct_blkio_start()
> with no task argument, in v6.12 and current master.
> 
> What I measured with bpftrace while starting Chrome a few times
> (roughly 70 s per run):
> 
> kprobe:dequeue_entities    { @in_de[tid] = 1; }
> kretprobe:dequeue_entities { delete(@in_de[tid]); }
> kprobe:__delayacct_blkio_start {
>   @start[@in_de[tid] ? "from dequeue_entities" : "from __schedule",
>          curtask->in_iowait] = count();
> }
> kprobe:__delayacct_blkio_end {
>   $p = (struct task_struct *)arg0;
>   if ($p->delays->blkio_start == 0) { @zero[$p->comm] = count(); }
> }
> 
> With DELAY_DEQUEUE on (two runs):
>   from __schedule, current in_iowait=1:        11081 / 8691
>   from __schedule, current in_iowait=0:            0 / 0
>   from dequeue_entities, current in_iowait=1:     50 / 61
>   from dequeue_entities, current in_iowait=0:     52 / 103
>   blkio_end with blkio_start == 0:                 3 / 10 (all Chrome threads)
> 
> With NO_DELAY_DEQUEUE (two runs, same workload):
>   from dequeue_entities:                         0 / 2
>   blkio_end with blkio_start == 0:               0 / 0
>   starts vs ends: 12057 vs 12056, 9612 vs 9610
> 
> So on the dequeue_entities path about half of the starts land on a task
> that isn't even in iowait. A kernel stack for one of the zero-start ends:
> 
>   __delayacct_blkio_end+1
>   try_to_wake_up+1509
>   wake_bit_function+57
>   __wake_up_common+118
>   __wake_up_common_lock+129
>   wake_up_bit+127
>   journal_end_buffer_io_sync+48
>   end_bio_bh_io_sync+38
> 
> This looks like the mirror image of c96f5471ce7d ("delayacct: Account
> blkio completion on the correct task"), which fixed the end side the same
> way. The obvious fix would be to pass p down, something like
> delayacct_blkio_start(p) setting p->delays->blkio_start (checking
> p->delays rather than current->delays). Happy to send a patch if that
> direction is okay.
> 
> Thanks
> kiln
> 

This should be fixed by
https://git.kernel.org/pub/scm/linux/kernel/git/peterz/queue.git/commit/?h=sched/urgent&id=5d010dd27be92a68eaac3af4f5ef0555bcde6031
(please give it a try!). It being in queue/sched/urgent should mean it
comes in with -rc2?
Peter any reason this isn't in tip yet?