cgroup_rstat_tracepoint.bt

#!/usr/bin/env bpftrace
/* SPDX-License-Identifier: GPL-2.0+
 *
 * Script for evaluation the latency effect cgroup rstat (recursive stats).
 *
 * It depends on tracepoints expected added in kernel 6.10
 *
 * Production experience with softirq_net_latency.bt indicate that reading
 * cgroup rstat (files under subdirs in /sys/fs/cgroup/) is *one* of the
 * factors that can disrupt softirq processing.
 *
 * This script zoom into cgroup rstat locking tracepoints to evaluate kernel
 * improvements in this area.
 *
 * 19-Apr-2024	Jesper Dangaard Brouer	Created this
 *
 */
BEGIN
{
	/* Cmdline arg#1: runtime threshold input in usec */
	@threshold1_usecs = $1 ? $1: 10000;
	@threshold1_ns = @threshold1_usecs * 1000;

	/* Cmdline arg#2: wait time threshold input in usec */
	@threshold2_usecs = $2 ? $2: 1000;
	@threshold2_ns = @threshold2_usecs * 1000;

	/* Cmdline arg#3: wait time threshold input in usec */
	@threshold3_usecs = $3 ? $3: 100;
	@threshold3_ns = @threshold3_usecs * 1000;

	printf("Tracing latency caused by cgroup rstat\n");
	printf(" - Will report on locked time above %d usecs (= %d ms)\n",
	       @threshold1_usecs, @threshold1_usecs / 1000);
	printf(" - Will report on WAIT time above %d usecs (= %d ms)\n",
	       @threshold2_usecs, @threshold2_usecs / 1000);
	printf(" - Will report on per-CPU (wait/locked) time above %d usecs (= %d ms)\n",
	       @threshold3_usecs, @threshold3_usecs / 1000);
	printf("... Hit Ctrl-C to end.\n");
}

tracepoint:cgroup:cgroup_rstat_lock_contended
{
	$now = nsecs;

	/* Concurrency issue here? */
	if (@wait_start[tid]) {
		printf("Concurrency issue: tid[%d] comm[%s] %s\n",
		       tid, comm, probe);
	}
	@contended_cnt++;
	@contended_cnt2++;

	@wait_start[tid]=$now;
}

tracepoint:cgroup:cgroup_rstat_locked
{
	$now = nsecs;
	@locked_start[tid]=$now;
	if (args->contended) {
		$wait_time = $now - @wait_start[tid];
		@wait_ns=hist($wait_time);
		delete(@wait_start[tid]);
	} else {
		$wait = 0;
	}

	/* WARNING: Using @xxx++ is an expensive atomic operation.
	 *  Recommend using @xxx = count()
	 *  Not doing it here as "count" type cannot be used in printf
	*/
	@lock_cnt++;
	@lock_cnt2++;

	/* Detect if lock was yielded inside cgroup_rstat_flush_locked */
	if (args->cpu >= 0) {
		@yield_cnt++;
		@yield_cnt2++;
	}

	/* Report/record on events over threshold.
	 *  for lock contention on cgroup_rstat_lock.
	 */
	if ($wait_time >= @threshold2_ns ) {
		$cgrp = args->id;
		@stack_wait[tid, comm, $cgrp] = kstack;
		time("%H:%M:%S ");
		printf("High Lock-contention: wait: %d usec (%d ms) on CPU:%d cgrp:%d comm:%s\n",
		       $wait_time / 1000, $wait_time / 1000000,
		       cpu, $cgrp, comm);
	}
}

tracepoint:cgroup:cgroup_rstat_unlock
{
	$now = nsecs;
	$locked_time = $now - @locked_start[tid];
	@locked_ns = hist($locked_time);

	/* Report/record on events over threshold.
	 *  for lock contention on cgroup_rstat_lock.
	 */
	if ($locked_time >= @threshold1_ns ) {
		$cgrp = args->id;
		@stack_locked[tid, comm, $cgrp] = kstack;
		time("%H:%M:%S ");
		printf("Long lock-hold time: %d usec (%d ms) on CPU:%d cgrp:%d comm:%s\n",
		       $locked_time / 1000, $locked_time / 1000000,
		       cpu, $cgrp, comm);
	}

	delete(@locked_start[tid]);
}

/* Get a count on how many times flush is called.
 *  - Remember that lock can be yielded inside this function
 *    Thus, a single call can result in many unlock/lock calls
 */
kfunc:cgroup_rstat_flush_locked
{
	@flush_calls++;
	@flush_calls2++;
	// @flush_calls = count();
}

/* Track high freq update events
 *  - WARNING comment-in for DEBUGGING only
 *  - overhead is mitigated via count() but still enable with caution
 *
kfunc:__mod_memcg_state,
kfunc:__mod_memcg_lruvec_state,
kfunc:__count_memcg_events
{
        // These functions calls: memcg_rstat_updated() inlined
        @memcg_rstat_updated_cnt[probe] = count();
}

kfunc:cgroup_rstat_updated
{
	// Notice: using count() which does per-cpu counter until read
	// Don't use @cgroup_rstat_updated_cnt++ in a place like this!
        @cgroup_rstat_updated_cnt = count();
}
 * WARNING comment-in above for DEBUGGING only */

/* The per-CPU locks are different from global lock.
 *  - While holding global lock
 *  - Kernel walks for_each CPU talking these locks
 *  - Global lock can by yielded
 *  - Thus, per-CPU lock latency shows lower bound on latency possible
 *  - Reminder: This is slow-path "flush" code, not fast-path "update" code
 */
tracepoint:cgroup:cgroup_rstat_cpu_lock_contended
{
	$now = nsecs;

	/* Concurrency issue here? */
	if (@wait_cpu_start[tid]) {
		printf("Concurrency issue: tid[%d] comm[%s] %s\n",
		       tid, comm, probe);
	}
	@contended_cpu_cnt++;
	@contended_cpu_cnt2++;

	@wait_cpu_start[tid]=$now;
}

tracepoint:cgroup:cgroup_rstat_cpu_locked
{
	$now = nsecs;
	@locked_cpu_start[tid]=$now;
	if (args->contended) {
		$wait_time = $now - @wait_cpu_start[tid];
		@wait_per_cpu_ns=hist($wait_time);
		delete(@wait_cpu_start[tid]);
	} else {
		$wait = 0;
	}

	@lock_cpu_cnt = count();
	@lock_cpu_cnt2 = count();

	if ($wait_time >= @threshold3_ns ) {
		$cgrp = args->id;
		@stack_per_cpu_wait[tid, comm, $cgrp] = kstack;
		time("%H:%M:%S ");
		printf("PER_CPU - High CPU-Lock-contention: wait: %d usec (%d ms) on CPU:%d cgrp:%d comm:%s\n",
		       $wait_time / 1000, $wait_time / 1000000,
		       cpu, $cgrp, comm);
	}
}

tracepoint:cgroup:cgroup_rstat_cpu_unlock
{
	$now = nsecs;
	$locked_time = $now - @locked_cpu_start[tid];
	@locked_per_cpu_ns = hist($locked_time);

	if ($locked_time >= @threshold3_ns ) {
		$cgrp = args->id;
		@stack_per_cpu_locked[tid, comm, $cgrp] = kstack;
		time("%H:%M:%S ");
		printf("PER_CPU - Long CPU-lock-hold time: %d usec (%d ms) on CPU:%d cgrp:%d comm:%s\n",
		       $locked_time / 1000, $locked_time / 1000000,
		       cpu, $cgrp, comm);
	}

	delete(@locked_cpu_start[tid]);
}

interval:s:1
{
	$sec = (uint64) elapsed/1000000000;
	time("\n%H:%M:%S ");
	printf(" time elapsed: %d sec (interval = 1 sec)\n", $sec);

	/* Rate per interval is calculate via resetting cnt2 vars */
	$flush_interval = @flush_calls2;	@flush_calls2 = 0;
	$lock_interval  = @lock_cnt2;		@lock_cnt2 = 0;
	$yield_interval = @yield_cnt2;		@yield_cnt2 = 0;
	$contended_interval = @contended_cnt2;	@contended_cnt2 = 0;
	$contended_cpu_interval = @contended_cpu_cnt2;	@contended_cpu_cnt2 = 0;

	printf(" Flushes(%d) %d/interval (avg %d/sec)\n",
	       @flush_calls, $flush_interval, @flush_calls / $sec);

        printf(" Locks(%d) %d/interval (avg %d/sec)\n",
	       @lock_cnt, $lock_interval, @lock_cnt / $sec);

	printf(" Yields(%d) %d/interval (avg %d/sec)\n",
	       @yield_cnt, $yield_interval, @yield_cnt / $sec);

	printf(" Contended(%d) %d/interval (avg %d/sec)\n",
	       @contended_cnt, $contended_interval, @contended_cnt / $sec);

	printf(" PER-CPU-contended(%d) %d/interval (avg %d/sec)\n",
	       @contended_cpu_cnt, $contended_cpu_interval, @contended_cpu_cnt / $sec);

	//print(@wait_ns);
	//print(@locked_ns);

	/* For high-freq update events comment below in
	 *
	printf("DEBUG: memcg_rstat_updated per/interval:\n");
	print(@memcg_rstat_updated_cnt);
	clear(@memcg_rstat_updated_cnt);
	printf("DEBUG: cgroup_rstat_updated per/interval:\n");
	print(@cgroup_rstat_updated_cnt);
	clear(@cgroup_rstat_updated_cnt);
	 */

	/* How can we record rate spikes?*/
	@flush_rates = hist($flush_interval);
	@locks_rates = hist($lock_interval);
	@yield_rates = hist($yield_interval);
	@contended_rates = hist($contended_interval);
	@PER_CPU_contended_rates = hist($contended_cpu_interval);
}

END
{	/* Default bpftrace will print all remaining maps at END */
	clear(@threshold1_usecs);
	clear(@threshold1_ns);
	clear(@threshold2_usecs);
	clear(@threshold2_ns);

	/* Interval counter are not relevant to print at END */
	clear(@contended_cnt2);
	clear(@lock_cnt2);
	clear(@yield_cnt2);
	clear(@lock_cnt2);
	clear(@flush_calls2);

	time("%H:%M:%S ");
	printf("END time elapsed: %d sec\n", elapsed / 1000000000);
}