Re: [RFC PATCH v2 3/5] blk-iocost: add iocost_ioc_tick tracepoint for per-period device summary

[bot+bpf-ci@kernel.org]

[-- Attachment #1: Type: text/plain, Size: 8158 bytes --]

> blk-iocost: add iocost_ioc_tick tracepoint for per-period device summary
>
> The existing iocost tracepoints are state-change driven: vrate_adj
> fires only when the adjustment logic runs, inuse_* only on surplus
> state transitions, activate/idle only on cgroup state changes.  In a
> steady state none of them fire.  The only other way to observe the
> controller (period length, vrate, busy level, active cgroup count,
> device utilization) is iocost_monitor.py, which reads kernel memory
> through drgn and is not usable in most production environments.
>
> Add iocost_ioc_tick, emitted once per period from the tail of
> ioc_timer_fn() with the overall controller state: period_us, vrate,
> busy_level, active iocg count, usage percentage and running state.
> It fires every period the controller runs, including steady states,
> plus one final tick before the controller goes idle, which makes
> dormancy (e.g. a device saturated entirely by uncharged IO) directly
> visible.
>
> At the default period this is a couple of events per second per
> device; the cost is zero while the static key is off.

Both halves of this last sentence overstate the case.

"a couple of events per second per device": the default period comes from
ioc_refresh_period_us(), and because the autop[] tables leave QOS_RPPM/QOS_WPPM
at 0, multi is always 2, so period_us = 2 * latency target:

  - AUTOP_HDD:      2 * 250000us = 500ms  ->  2 events/s
  - AUTOP_SSD_QD1:  2 *  25000us =  50ms  -> 20 events/s
  - AUTOP_SSD_DFL:  2 *  25000us =  50ms  -> 20 events/s
  - AUTOP_SSD_FAST: 2 *   5000us =  10ms  -> 100 events/s

Only the rotational default matches "a couple per second"; the SSD defaults -
the common case - are 20-100 events/s per device, 10-50x higher.

"the cost is zero while the static key is off": the nr_active++ added at
block/blk-iocost.c:2284 runs unconditionally on every active iocg in every
period, outside the static key. The cost is negligible, but it is not zero,
and the claim as written invites the reader to believe no work was added to
the timer path.

> diff --git a/block/blk-iocost.c b/block/blk-iocost.c
> index 182601ad783f..bccdbd2496d8 100644
> --- a/block/blk-iocost.c
> +++ b/block/blk-iocost.c

[ ... ]

> @@ -2280,6 +2281,8 @@ static void ioc_timer_fn(struct timer_list *timer)
>  		u64 vdone, vtime, usage_us;
>  		u32 hw_active, hw_inuse;
>
> +		nr_active++;
> +
>  		/*
>  		 * Collect unused and wind vtime closer to vnow to prevent
>  		 * iocgs from accumulating a large amount of budget.

[ ... ]

> @@ -2466,6 +2469,8 @@ static void ioc_timer_fn(struct timer_list *timer)
>  		ioc_refresh_vrate(ioc, &now);
>  	}
>
> +	trace_iocost_ioc_tick(ioc, nr_active, usage_us_sum);
> +
>  	spin_unlock_irq(&ioc->lock);
>  }

Is the tracepoint emitted at the right point in the function? It is called
after the period-rollover bookkeeping, so on the one tick the changelog
specifically advertises, the reported state has already been wiped.

The changelog says: "plus one final tick before the controller goes idle,
which makes dormancy (e.g. a device saturated entirely by uncharged IO)
directly visible." That final tick is taken through the else branch at
block/blk-iocost.c:2464-2467, which executes this:

	} else {
		ioc->busy_level = 0;
		ioc->vtime_err = 0;
		ioc->running = IOC_IDLE;
	}

	ioc_refresh_vrate(ioc, &now);

immediately before the trace call. The event therefore always reports busy=0
for the go-idle tick, even though the busy_level computed earlier in this
very period (from rq_wait_pct / missed_ppm, lines 2401-2420) is the
interesting number in the named scenario: a device saturated by uncharged IO
drives rq_wait_pct up, so busy_level was incremented and ioc_adjust_base_vrate()
already slowed vrate down - and none of that is visible in the emitted record,
which reads active=0 usage=0% busy=0 running=0.

Same ordering issue for running: it is set to IOC_IDLE at line 2466 before the
trace, so the field describes the state entered *after* the period rather than
the state the period ran in. Placing the trace_iocost_ioc_tick() call before
the `if (ioc->running != IOC_STOP)` block (or capturing busy_level/running into
locals right after ioc_adjust_base_vrate()) would emit the period's own state.

> diff --git a/include/trace/events/iocost.h b/include/trace/events/iocost.h
> index e772b1bc60d6..2b9ff348a4f5 100644
> --- a/include/trace/events/iocost.h
> +++ b/include/trace/events/iocost.h

[ ... ]

> +/*
> + * Periodic per-device summary, emitted once per period from the tail of
> + * ioc_timer_fn().  Unlike the state-change events above, this fires every
> + * period the controller is running, including steady states, and carries
> + * the overall controller state so basic monitoring doesn't require drgn.
> + */
> +TRACE_EVENT(iocost_ioc_tick,
> +
> +	TP_PROTO(struct ioc *ioc, int nr_active, u64 usage_us_sum),
> +
> +	TP_ARGS(ioc, nr_active, usage_us_sum),
> +
> +	TP_STRUCT__entry (
> +		__string(devname, ioc_name(ioc))
> +		__field(u32, period_us)
> +		__field(u64, vrate)
> +		__field(int, busy_level)
> +		__field(int, nr_active)
> +		__field(u32, usage_pct)
> +		__field(int, running)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(devname);
> +		__entry->period_us = ioc->period_us;
> +		__entry->vrate = ioc->vtime_base_rate;
> +		__entry->busy_level = ioc->busy_level;
> +		__entry->nr_active = nr_active;
> +		__entry->usage_pct = ioc->period_us ?
> +			div_u64(usage_us_sum * 100, ioc->period_us) : 0;
> +		__entry->running = ioc->running;
> +	),

Does usage_pct normalise against the right divisor? It uses the *nominal*
period length read at the very end of ioc_timer_fn(), which is neither the
interval the usage was accumulated over nor necessarily the period_us that
was in effect during it.

Two concrete problems:

1. Wrong divisor. usage_us_sum is accumulated over the real interval
[ioc->period_at, now.now]. ioc_timer_fn() itself never treats that as equal to
ioc->period_us - the donation loop a few lines above deliberately uses the
measured duration:

    usage_dur = max_t(u64, now.now - ioc->period_at, 1);

and ioc_forgive_debts() (block/blk-iocost.c:2119) does the same for its own
percentage:

    dur = now->now - ioc->dfgv_period_at;
    usage_pct = div64_u64(100 * ioc->dfgv_usage_us_sum, dur);

ioc_start_period() re-arms with a jiffies timer (ioc->timer.expires = jiffies +
usecs_to_jiffies(ioc->period_us)), so a period routinely runs longer than
period_us - which is exactly why the code above measures instead of assuming.
Every microsecond of timer/softirq lateness inflates the reported usage
percentage proportionally, and the consumer cannot correct for it: the
tracepoint is emitted *after* ioc_start_period() has already overwritten
ioc->period_at with now.now, and the event carries neither now.now nor the old
period_at, so the actual duration is unrecoverable from the trace.

2. Stale-vs-new period_us. ioc_refresh_params(ioc, false) runs before the
tracepoint (block/blk-iocost.c:2452) and, when the autop index changes, calls
ioc_refresh_period_us() which rewrites ioc->period_us (e.g. AUTOP_SSD_DFL
50000us -> AUTOP_SSD_FAST 10000us). On such a period the event divides the old
period's usage by the new period length, a 5x error, and also reports the
freshly reset vtime_base_rate (ioc_refresh_params_disk() sets it back to
VTIME_PER_USEC).

Using the measured duration - captured before ioc_start_period() clobbers
ioc->period_at - would make the field mean what the changelog says it means
("device utilization").

Aside on the same line: the `ioc->period_us ?` guard is unreachable.
ioc_refresh_period_us() ends with `period_us = clamp_t(u32, period_us,
MIN_PERIOD, MAX_PERIOD)` (MIN_PERIOD = USEC_PER_MSEC) and runs from
blk_iocost_init()'s ioc_refresh_params_disk(ioc, true, disk) before
timer_setup() at block/blk-iocost.c:3001, so ioc->period_us is never 0 when
ioc_timer_fn() executes.


---
AI reviewed your patch. Please fix the bug or email reply why it's not a bug.
See: https://github.com/kernel-patches/vmtest/blob/master/ci/claude/README.md

CI run summary: https://github.com/kernel-patches/bpf/actions/runs/34481298417