Re: [PATCH v5 1/2] perf timechart: Add a --live mode to the TUI

[sashiko-bot@kernel.org]

Thank you for your contribution! Sashiko AI review found 6 potential issue(s) to consider:
- [Medium] perf timechart: broken live cursor following on zoom, reset, and goto_task()
- [Medium] perf timechart: mark_gap() overwrites pending gap_at on rapid pause/resume
- [Medium] perf timechart: unlocked nr_samples increment races with live_refresh()
- [Medium] perf timechart: missing finished_round leaves live events buffered
- [Medium] perf timechart: incomplete syscall filter in LiveRecorder.start()
- [Medium] perf timechart: live mode stop() blocks perf record and orphans workload
--

commit dc903a5155a83951be9359f3695ae64ac3fc69e5
Author: Alice Rogers <alice.mei.rogers@gmail.com>

perf timechart: Add a --live mode to the TUI

This commit adds a --live mode to perf timechart and ttimechart.py that
runs perf record into a pipe and displays a rolling window of scheduler,
power, or I/O events interactively in the terminal UI. It also supports
pausing and resuming recording via perf record's control pipe and adaptive
refresh intervals.

> diff --git a/tools/perf/python/ttimechart.py b/tools/perf/python/ttimechart.py
> index 34ecf84e68c1d..acd1a8651244e 100755
> --- a/tools/perf/python/ttimechart.py
> +++ b/tools/perf/python/ttimechart.py

[ ... ]

> @@ -326,21 +425,83 @@ class TimechartData:

[ ... ]

> +    def mark_gap(self, time: int) -> None:
> +        """Note that recording, paused for a while, resumes at time, the lock must be held.
> +
> +        Events weren't recorded while paused, so the states at the pause aren't
> +        known to have continued. They are closed before the first event after
> +        time is processed, the events are processed in time order.
> +        """
> +        self.gap_at = time
> +
> +    def _close_gap(self) -> None:
> +        """Close open states at the last event before the gap, see mark_gap()."""
> +        end = self.last_time
> +        for task in self.tasks.values():
> +            task.change_state(end, STATE_UNKNOWN)
> +            task.io_pending = None
> +        for c in self.cpus.values():
> +            if c.cur_tid > 0:
> +                c.run.add(c.since, end, 1, c.cur_tid)
> +            c.cur_tid = -1
> +            if c.cstate_cur:
> +                c.cstate.add(c.cstate_cur[0], end, 1, c.cstate_cur[1])
> +                c.cstate_cur = None
> +            if c.pstate_cur:
> +                c.pstate.add(c.pstate_cur[0], end, 1, c.pstate_cur[1])
> +                c.pstate_cur = None
> +        self.resumed_at = self.gap_at
> +        self.gap_at = 0

[ ... ]

> @@ -527,6 +701,8 @@ class TimechartData:
>      def _process_event(self, sample: perf.sample_event) -> None:
>          """Update the data from a sample, the lock must be held."""
>          time = sample.sample_time
> +        if self.gap_at and time >= self.gap_at:
> +            self._close_gap()
>          if not self.first_time or time < self.first_time:
>              self.first_time = time
>          self.last_time = max(self.last_time, time)

[Severity: Medium]
What happens in TimechartData.mark_gap() and TimechartData._process_event()
if the user pauses and resumes live recording again before an event from
the first resumed interval has been processed?

In TimechartApp.action_toggle_pause(), resuming from pause calls
self.data.mark_gap(monotonic_ns()), which sets self.gap_at = time. Open
task and CPU states from before the pause are only closed when
TimechartData._process_event() sees a sample with time >= self.gap_at and
calls self._close_gap().

Because perf record flushes periodically on ping and perf.session buffers
events in ordered_events until a subsequent round marker, a user can resume
at T2, pause at T3, and resume at T4 before any sample with time >= T2
reaches TimechartData._process_event(). When mark_gap(T4) overwrites
self.gap_at = T4, buffered samples from [T2, T3) have sample_time < T4 and
bypass _close_gap(), stretching pre-pause task and CPU states across the
first pause gap.

Should mark_gap() avoid overwriting a smaller non-zero self.gap_at, or
close the pending gap immediately before recording the new timestamp?

[ ... ]

> @@ -1486,6 +1726,204 @@ class TimechartApp(App):

[ ... ]

> +    def live_refresh(self) -> None:
> +        """Show newly recorded events and discard those no longer in the window."""
> +        start = monotonic()
> +        with self.data.lock:
> +            samples = self.data.nr_samples
> +        # When paused, once the buffered events are shown there's nothing new.
> +        if not self.paused_at or samples != self.refreshed_samples:
> +            self.refreshed_samples = samples
> +            with self.data.lock:
> +                self.data.checkpoint()
> +                if self.recording and not self.paused_at:
> +                    self.live_prune()
> +            self.update_views()
> +            self.update_live_status()
> +        # Measure the cost of the refresh including drawing the screen.
> +        self.call_after_refresh(self.live_refreshed, start)

[Severity: Medium]
Can TimechartApp.live_refresh() race with TimechartData.process_event() and
miss rendering the final buffered event when paused?

In TimechartData.process_event(), the worker thread increments
self.nr_samples before acquiring self.lock to call _process_event(sample):

    def process_event(self, sample: perf.sample_event) -> None:
        """Callback from perf.session for each sample."""
        self.nr_samples += 1
        ...
        with self.lock:
            self._process_event(sample)

Meanwhile, TimechartApp.live_refresh() reads self.data.nr_samples under
self.data.lock, releases the lock, updates self.refreshed_samples = samples,
and then re-acquires self.data.lock to call self.data.checkpoint() and
self.update_views().

If live recording is paused (self.paused_at != 0) and live_refresh() reads
the incremented self.data.nr_samples before the worker thread acquires
self.lock and finishes _process_event(sample), live_refresh() records
self.refreshed_samples = samples and renders the views before the sample is
added to self.data. Subsequent live_refresh() ticks while paused then see
samples == self.refreshed_samples and skip refreshing.

Should self.nr_samples be incremented inside with self.lock: in
TimechartData.process_event(), and read inside the same lock acquisition in
TimechartApp.live_refresh()?

[ ... ]

> +    def user_window(self, window: TimeWindow) -> None:
> +        """Change the window for the user.
> +
> +        In live mode, zooming or panning so that the whole window isn't shown
> +        stops the view following the latest events.
> +        """
> +        if self.live:
> +            whole = window.start == window.first and window.end == window.last
> +            if window.cursor != self.window.cursor:
> +                self.follow_cursor = False
> +            elif whole and not self.following:
> +                self.follow_cursor = True
> +                if self.data.last_time:
> +                    window = replace(window, cursor=min(max(self.data.last_time, window.first),
> +                                                        window.last))
> +            if self.following != whole:
> +                self.following = whole
> +                self.update_live_status()
> +        self.window = window

[ ... ]

> @@ -1569,14 +2012,23 @@ class TimechartApp(App):

[ ... ]

> -        if first or last:
> +        if self.live:
> +            live_first, live_last = self.live_bounds()
> +            win = self.window.extend(live_first, live_last)
> +            if self.following:
> +                win = win.reset()
> +            if self.follow_cursor and last:
> +                win = replace(win, cursor=min(max(last, live_first), live_last))
> +            self.window = win
> +        elif first or last:
>              self.window = self.window.extend(first, last)

[Severity: Medium]
Does cursor following in TimechartApp.user_window(),
TimechartApp.update_views(), and TimechartApp.goto_task() stay in sync when
zooming, resetting zoom, or jumping to a waker in live mode?

There appear to be three related cases where self.follow_cursor and
self.following diverge:

1. When zooming in or out via TimelineView.action_zoom_in() or
action_zoom_out(), TimeWindow.zoom() keeps window.cursor ==
self.window.cursor whenever the cursor is within [self.start, self.end].
In TimechartApp.user_window(), whole becomes False and self.following is
set to False, but self.follow_cursor = False is only run if window.cursor
!= self.window.cursor. Because self.follow_cursor remains True, every
subsequent live_refresh() -> update_views() overwrites win.cursor with
last, dragging the cursor out of the zoomed view.

2. If the user moves the cursor without zooming or panning, user_window()
sets self.follow_cursor = False while whole and self.following remain True.
Pressing 0 (TimelineView.action_zoom_reset()) then calls
user_window(self.window.reset()), where elif whole and not self.following:
is skipped because self.following is already True, leaving
self.follow_cursor stuck at False.

3. Pressing w (TimechartApp.action_goto_waker() -> goto_task()) assigns
self.window = self.window.with_cursor(time) directly instead of calling
self.user_window(), leaving self.follow_cursor (and self.following) True so
the next refresh snaps the cursor and view back to the latest event.

[ ... ]

> @@ -1727,52 +2180,374 @@ class TimechartApp(App):

[ ... ]

> +    def start(self) -> None:
> +        """Start perf record, the data is then read from data_fd."""
> +        output = open(self.output, "wb") if self.output else None
> +        # perf record's ends of the control pipes, closed once it is started.
> +        child_fds: List[int] = []
> +        try:
> +            ctl_r, self.ctl_fd = os.pipe()
> +            child_fds.append(ctl_r)
> +            self.ack_fd, ack_w = os.pipe()
> +            child_fds.append(ack_w)
> +            # Quiet so that only errors are written to stderr, see error_text().
> +            cmd = [self.perf_exe, "record", "-q", "-o", "-", "-R", "-c", "1", "-k", "mono",
> +                   "--synth=task", "--control", f"fd:{ctl_r},{ack_w}"]
> +            filt = f"common_pid != {os.getpid()}"
> +            for name in self.events():
> +                cmd += ["-e", name]
> +                if name.startswith("syscalls:"):
> +                    cmd += ["--filter", filt]

[Severity: Medium]
Does the tracepoint filter common_pid != os.getpid() in
LiveRecorder.start() exclude I/O syscalls made by the child perf record
process and ttimechart.py's worker threads when running with --live -I?

In kernel tracepoints, common_pid is current->pid (the thread ID, not the
process TGID). Unlike builtin-timechart.c:timechart__io_record(), which
runs cmd_record() in-process on a single thread, LiveRecorder.start() spawns
perf record as a child process and runs control_thread, tee_thread,
record_events, and Textual workers on separate Python threads whose TIDs
differ from os.getpid().

While TimechartApp.__init__() adds os.getpid() and proc.pid to
self.data.ignore_pids to hide them from live TUI rows, all of their
read/write/poll/select syscalls are still recorded by the kernel. Those
events increment self.nr_samples in TimechartData.process_event() before
io_enter() and io_exit() check ignore_pids, and tee_thread writes them into
any file saved with -o, polluting the saved perf.data when later viewed
with perf timechart or perf timechart --tui.

[ ... ]

> +    def control_loop(self) -> None:
> +        """Send queued commands, otherwise pings that flush perf record's buffers."""
> +        try:
> +            while not self.stopping.is_set():
> +                try:
> +                    cmd = self.commands.get(timeout=self.flush_interval)
> +                except queue.Empty:
> +                    if self.paused:
> +                        continue
> +                    cmd = "ping"
> +                if not cmd or self.stopping.is_set() or not self.send(cmd):
> +                    break
> +        finally:
> +            self.close_control_fds()
> +
> +    def set_paused(self, paused: bool) -> None:
> +        """Pause or resume recording."""
> +        self.paused = paused
> +        self.commands.put("disable" if paused else "enable")

[Severity: Medium]
When pausing recording or running in --power-only mode, can the latest
round of events remain buffered in perf.session's ordered_events queue
without being delivered to TimechartData.process_event()?

In tools/perf/util/ordered-events.c:__ordered_events__flush(), handling
OE_FLUSH__ROUND (on PERF_RECORD_FINISHED_ROUND) calls do_flush() up to the
previous oe->next_flush before advancing oe->next_flush = oe->max_timestamp:

    err = do_flush(oe, show_progress);

    if (!err) {
        if (how == OE_FLUSH__ROUND)
            oe->next_flush = oe->max_timestamp;

        oe->last_flush_type = how;
    }

TimechartApp.tune_refresh() sets self.live.flush_interval =
self.refresh_interval / 2 so that two pings occur per refresh. However, in
tools/perf/builtin-record.c:record__mmap_read_evlist(), perf record only
writes finished_round_event when new bytes were actually read from the
ring buffers during that pass:

    if (!record__threads_enabled(rec) && bytes_written != rec->bytes_written)
        rc = record__write(rec, NULL, &finished_round_event, sizeof(finished_round_event));

When LiveRecorder.set_paused(True) queues "disable" and stops sending
"ping" in LiveRecorder.control_loop(), perf record disables the evlist,
drains the final pre-pause events in one pass, and writes only one
PERF_RECORD_FINISHED_ROUND (which flushes the prior round and sets
oe->next_flush). The next pass reads 0 bytes from the disabled ring buffers
and emits no second PERF_RECORD_FINISHED_ROUND, leaving the final round of
pre-pause events buffered in ordered_events while paused. The same happens
in --power-only mode when a subsequent ping pass sees no new power events.

[ ... ]

> +    def stop(self) -> None:
> +        """Stop recording, perf record then writes any remaining data and exits.
> +
> +        Called from both the UI thread and the thread processing the events,
> +        so they don't both signal, reap and close perf record's pipes at once.
> +        """
> +        self.stopping.set()
> +        self.commands.put("")
> +        with self.stop_lock:
> +            self._stop()
> +
> +    def _stop(self) -> None:
> +        """Stop perf record and the threads, stop_lock must be held."""
> +        proc = self.proc
> +        if proc is not None and proc.poll() is None:
> +            try:
> +                proc.send_signal(signal.SIGINT)
> +                proc.wait(timeout=1)
> +            except subprocess.TimeoutExpired:
> +                # Probably blocked writing data that is no longer processed.
> +                proc.kill()
> +                proc.wait()
> +        if self.tee_thread and self.tee_thread is not threading.current_thread():
> +            self.tee_thread.join(timeout=1)
> +        if self.control_thread and self.control_thread is not threading.current_thread():
> +            self.control_thread.join(timeout=1)
> +        self.close_control_fds()
> +        self.close_data_fds()
> +
> +    def close_data_fds(self) -> None:
> +        """Close the read ends of the data pipes, stop_lock must be held.
> +
> +        perf.data() duplicates the file descriptor it reads from, so they
> +        aren't needed once processing has started. Closing them means writes
> +        to them fail, rather than block, once they are no longer read.
> +        """
> +        self.data_fd = -1
> +        tee_r, self.tee_r = self.tee_r, -1
> +        if tee_r >= 0:
> +            try:
> +                os.close(tee_r)
> +            except OSError:
> +                pass
> +        # Unless the tee thread is still reading from it.
> +        if self.proc and self.proc.stdout and not (self.tee_thread and
> +                                                   self.tee_thread.is_alive()):
> +            self.proc.stdout.close()

[Severity: Medium]
When quitting live mode, can TimechartApp.cancel_loading() and
LiveRecorder._stop() cause perf record to block on pipe writes, get killed
with SIGKILL, and leave the workload child process running as an orphan?

When quitting, TimechartApp.cancel_loading() sets loading.cancelled = True
before calling self.live.stop():

    loading = self.loading
    if loading is not None:
        loading.cancelled = True
    if self.live:
        self.live.stop()

On the worker thread, TimechartData.process_event() raises LoadCancelled at
the next PROGRESS_INTERVAL (1000 samples), causing read_events() to exit
and close perf.data's duplicated pipe fd while LiveRecorder._stop() sends
SIGINT to perf record and calls proc.wait(timeout=1). However,
self.close_data_fds() is not called until the end of _stop(), so
self.proc.stdout remains open while nobody is reading from it.

In tools/perf/builtin-record.c:__cmd_record(), perf record flushes all
ring buffers to stdout before sending SIGTERM to its workload child:

    record__mmap_read_all(rec, true);
    goto out_free_threads;
    ...
    if (forks) {
        int exit_status;

        if (!child_finished)
            kill(evlist__workload_pid(rec->evlist), SIGTERM);

Once the pipe fills, perf record blocks in write(), hits
subprocess.TimeoutExpired after 1 second, and proc.kill() sends SIGKILL
only to proc.pid (even though perf record was started with
start_new_session=True), leaving any workload started after -- running
in the background. (Even if close_data_fds() were called before
proc.wait(), an early EPIPE/SIGPIPE during record__mmap_read_all() would
still terminate perf record before it reaches the kill(..., SIGTERM) call.)

-- 
Sashiko AI review · https://sashiko.dev/#/patchset/20261023054952.2503540-1-irogers@google.com?part=1