Message-ID: <20260116181524.GF831285@noisy.programming.kicks-ass.net>
Date: Fri, 16 Jan 2026 19:15:24 +0100
From: Peter Zijlstra <peterz@...radead.org>
To: Thomas Gleixner <tglx@...utronix.de>
Cc: LKML <linux-kernel@...r.kernel.org>,
	Mathieu Desnoyers <mathieu.desnoyers@...icios.com>,
	"Paul E. McKenney" <paulmck@...nel.org>,
	Boqun Feng <boqun.feng@...il.com>, Jonathan Corbet <corbet@....net>,
	Prakash Sangappa <prakash.sangappa@...cle.com>,
	Madadi Vineeth Reddy <vineethr@...ux.ibm.com>,
	K Prateek Nayak <kprateek.nayak@....com>,
	Steven Rostedt <rostedt@...dmis.org>,
	Sebastian Andrzej Siewior <bigeasy@...utronix.de>,
	Arnd Bergmann <arnd@...db.de>, linux-arch@...r.kernel.org,
	Randy Dunlap <rdunlap@...radead.org>,
	Ron Geva <rongevarg@...il.com>, Waiman Long <longman@...hat.com>
Subject: Re: [patch V6 07/11] rseq: Implement time slice extension
 enforcement timer

On Fri, Dec 19, 2025 at 11:05:17AM +0100, Peter Zijlstra wrote:

> I was thinking that perhaps the hrtimer tracepoints, filtered on this
> specific timer, might just do. Arming the timer is the point where the
> extension is granted, cancelling the timer is on the slice_yield() (or
> any other random syscall :/), and the timer actually firing is on fail.

Here, I google pasted this together. I don't actually speak much snake
(as you well know). Nor does it fully work; the handle_expire() thing is
busted, I definitely have expire entries in the trace, but they're not
showing up.

$ trace-cmd record -e hrtimer_start -e hrtimer_cancel -e hrtimer_expire_entry -- ./slice_test
$ ./foo.py

========================================
RSEQ SLICE HISTOGRAM (us)
========================================

Task: slice_test    Mean: 375.577 ns
  Latency (us)    | Count
  ------------------------------
  0 us            | 142031
  1 us            | 292
  2 us            | 67
  3 us            | 33
  4 us            | 34
  5 us            | 27
  6 us            | 15
  7 us            | 14
  8 us            | 24
  9 us            | 33
  10 us           | 691


---
#!/usr/bin/python3

#
# trace-cmd record -e hrtimer_start -e hrtimer_cancel -e hrtimer_expire_entry -- $cmd
#

from tracecmd import *

def load_kallsyms(file_path='/proc/kallsyms'):
    """
    Parses /proc/kallsyms into a dictionary.
    Returns: { address_int: symbol_name }
    """
    kallsyms_map = {}

    try:
        with open(file_path, 'r') as f:
            for line in f:
                # The format is: [address] [type] [name] [module]
                parts = line.split()
                if len(parts) < 3:
                    continue

                addr = int(parts[0], 16)
                name = parts[2]

                kallsyms_map[addr] = name

    except PermissionError:
        print(f"Error: Permission denied reading {file_path}. Try running with sudo.")
    except FileNotFoundError:
        print(f"Error: {file_path} not found.")

    return kallsyms_map

ksyms = load_kallsyms()

# pending[timer_ptr] = {'ts': timestamp, 'comm': comm}
pending = {}

# histograms[comm][bucket] = count
histograms = {}

class OnlineHarmonicMean:
    def __init__(self):
        self.n = 0          # Count of elements
        self.S = 0.0        # Cumulative sum of reciprocals

    def update(self, x):
        if x == 0:
            raise ValueError("Harmonic mean is undefined for zero.")

        self.n += 1
        self.S += 1.0 / x
        return self.n / self.S

    @property
    def mean(self):
        return self.n / self.S if self.n > 0 else 0

ohms = {}

def handle_start(record):
    func_name = ksyms[record.num_field("function")]
    if "rseq_slice_expired" in func_name:
        timer_ptr = record.num_field("hrtimer")
        pending[timer_ptr] = {
            'ts': record.ts,
            'comm': record.comm
        }
    return None 

def handle_cancel(record):
    timer_ptr = record.num_field("hrtimer")
    
    if timer_ptr in pending:
        start_data = pending.pop(timer_ptr)
        duration_ns = record.ts - start_data['ts']
        duration_us = duration_ns // 1000

        comm = start_data['comm']

        if comm not in ohms:
            ohms[comm] = OnlineHarmonicMean()

        ohms[comm].update(duration_ns)
        
        if comm not in histograms:
            histograms[comm] = {}
        
        histograms[comm][duration_us] = histograms[comm].get(duration_us, 0) + 1
    return None

def handle_expire(record):
    timer_ptr = record.num_field("hrtimer")

    if timer_ptr in pending:
        start_data = pending.pop(timer_ptr)
        comm = start_data['comm']
        
        if comm not in histograms:
            histograms[comm] = {}
            
        # Record -1 bucket for expired (failed to cancel)
        histograms[comm][-1] = histograms[comm].get(-1, 0) + 1
    return None

if __name__ == "__main__":
    t = Trace("trace.dat")
    for cpu in range(0, t.cpus):
        ev = t.read_event(cpu)
        while ev:
            if "hrtimer_start" in ev.name:
                handle_start(ev)
            if "hrtimer_cancel" in ev.name:
                handle_cancel(ev)
            if "hrtimer_expire_entry" in ev.name:
                handle_expire(ev)

            ev = t.read_event(cpu)

    print("\n" + "="*40)
    print("RSEQ SLICE HISTOGRAM (us)")
    print("="*40)
    for comm, buckets in histograms.items():
        print(f"\nTask: {comm}    Mean: {ohms[comm].mean:.3f} ns")
        print(f"  {'Latency (us)':<15} | {'Count'}")
        print(f"  {'-'*30}")
        # Sort buckets numerically, putting -1 at the top
        for bucket in sorted(buckets.keys()):
            label = "EXPIRED" if bucket == -1 else f"{bucket} us"
            print(f"  {label:<15} | {buckets[bucket]}")

Powered by blists - more mailing lists