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

[sashiko-bot@kernel.org]

Thank you for your contribution! Sashiko AI review found 9 potential
issues to consider:
- [Medium] perf timechart: live_prune() at last_time deletes all open
  states
- [Medium] perf timechart: checkpoint() and prune() drop blocked and
  waiting states
- [Medium] perf timechart: stale pre-exec comm in task() during live I/O
  mode
- [Medium] perf timechart: io_bytes and switches drift in add() and
  prune()
- [Low] perf timechart: Task.totals drift after checkpoint() and
  change_state()
- [Low] perf timechart: update_views() and dump() use sched tasks with
  -I
- [Low] perf timechart: fix switch count underflow in Task.prune() after
  gaps
- [Low] perf timechart: race in LiveRecorder.pump() clearing
  flush_round_target
- [Low] perf timechart: race on data_fd in LiveRecorder.backlog() during
  stop()
--

commit bf97da434173bd983d47c0d1625c5c56ef3fbfc7
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
streams events from perf record into the TUI and prunes history outside a
sliding time window.

> diff --git a/tools/perf/python/ttimechart.py b/tools/perf/python/ttimechart.py
> index d7ba0276a9fb4..253116d96c717 100755
> --- a/tools/perf/python/ttimechart.py
> +++ b/tools/perf/python/ttimechart.py
[ ... ]
> @@ -265,6 +319,42 @@ class Task:
>              return True
>          return any(f == str(self.tid) or f in self.comms for f in filters)
>  
> +    def prune(self, time: int) -> None:
> +        """Discard history ending at or before time, removing it from the totals."""
> +        segs = self.segs
> +        num = segs.num_ending_by(time)
> +        # A still running task's last segment, extended by checkpoint(), ends
> +        # at since. It hasn't been switched out yet.
> +        open_edge = len(segs) - 1 if self.state == STATE_RUNNING and segs and \
> +            segs.ends[-1] == self.since else -1
> +        for i in range(num):
> +            state = segs.keys[i]
> +            self.totals[state] -= segs.ends[i] - segs.starts[i]
> +            if state == STATE_RUNNING and i != open_edge:
> +                # Running segments end when the task is switched out.
> +                self.switches = max(self.switches - 1, 0)

[Severity: Low]
Does decrementing self.switches for every pruned STATE_RUNNING segment cause
the switch count to drift when running segments are closed without a switch?

TimechartData._close_gap(), TimechartData.finish() and the lost-switch path
in TimechartData.sched_switch() transition a running task to STATE_UNKNOWN
and add a STATE_RUNNING segment without incrementing task.switches.  When
those segments are later pruned, i != open_edge is true and Task.prune()
decrements self.switches anyway.  Conversely, if a switch-in was lost so
prev.state is not STATE_RUNNING in sched_switch(), prev.switches is
incremented without a matching STATE_RUNNING segment to decrement it on
prune.

> +        if num < len(segs.starts) and segs.starts[num] < time:
> +            self.totals[segs.keys[num]] -= time - segs.starts[num]
> +        segs.prune(time)
> +        io = self.io
> +        for i in range(io.num_ending_by(time)):
> +            ret = io.data[i][1]
> +            if ret > 0 and io.keys[i] in (IOTYPE_READ, IOTYPE_WRITE, IOTYPE_TX, IOTYPE_RX):
> +                self.io_bytes -= ret
> +        io.prune(time)

[Severity: Medium]
Can SegmentList.add() merging or clipping segments cause Task.io_bytes and
syscall counts to drift across Task.prune()?

SegmentList.add() merges a new segment into the previous one when
start == self.ends[-1], key == self.keys[-1] and data == self.data[-1], and
drops segments that clip to end <= start.  In TimechartData.io_exit(),
task.io.add() uses iotype as key and (fd, ret) as data, while task.io_bytes
is incremented by ret on every call.  If two consecutive syscalls on the
same fd have the same type and return value and meet at self.ends[-1] (or
share the same timestamp so the second is clipped out), only one segment is
kept in task.io while task.io_bytes is incremented twice.  len(task.io) then
undercounts syscalls and Task.prune() only subtracts ret once, leaking ret
bytes in task.io_bytes.

> +        if self.io_pending and self.io_pending[0] < time:
> +            self.io_pending = (time, self.io_pending[1], self.io_pending[2])
> +        del self.wakeups[:bisect.bisect_right(self.wakeups, (time, sys.maxsize))]
> +        if self.since <= time:
> +            self.since = time
> +            if not segs and self.state != STATE_RUNNING:
> +                self.state = STATE_UNKNOWN

[Severity: Medium]
Does pruning a task whose state is STATE_BLOCKED or STATE_WAITING drop its
current state and history?

TimechartData.checkpoint() only extends open segments for tasks in
STATE_RUNNING, leaving STATE_BLOCKED and STATE_WAITING tasks unextended.
While a task remains blocked or waiting, that state is not shown in the live
timeline until a later event transitions the task, and once the prune window
reaches self.since, segs becomes empty and Task.prune() resets self.state to
STATE_UNKNOWN, allowing TimechartData.prune() to delete the task altogether.

[ ... ]
> @@ -342,13 +500,13 @@ class TimechartData:
>      def task(self, tid: int, comm: Optional[str] = None) -> Task:
>          """Find or create a task."""
>          task = self.tasks.get(tid)
> +        if not comm and self.session and (task is None or task.comm == f"[{tid}]"):
> +            try:
> +                thread = self.session.find_thread(tid, tid)
> +                comm = thread.comm() if thread else None
> +            except (OSError, ValueError, KeyError, RuntimeError, TypeError, AttributeError):
> +                comm = None
>          if task is None:
> -            if not comm and self.session:
> -                try:
> -                    thread = self.session.find_thread(tid, tid)
> -                    comm = thread.comm() if thread else None
> -                except (OSError, ValueError, KeyError, RuntimeError, TypeError, AttributeError):
> -                    comm = None
>              task = Task(tid, comm or f"[{tid}]")
>              self.tasks[tid] = task
>          else:

[Severity: Medium]
In live I/O-only mode, does this leave a task's pre-exec comm stuck after
execve()?

Syscall tracepoints call self.task(tid) with comm=None.  When a child
process (such as a workload started by perf record with comm "perf-exec")
performs an I/O syscall before execve(), self.session.find_thread() sets
task.comm to the pre-exec name.  After execve() emits PERF_RECORD_COMM,
task.comm is neither None nor "[{tid}]", so self.task() never queries
self.session.find_thread() again, and TimechartData.update_comms() is never
called in live mode because self.progress is None.

[ ... ]
> @@ -562,6 +752,32 @@ class TimechartData:
>              except (OSError, ValueError, KeyError, RuntimeError, TypeError, AttributeError):
>                  pass
>  
> +    def checkpoint(self) -> None:
> +        """Extend open running, idle and frequency states to last_time.
> +
> +        Live mode calls this before displaying and pruning so that states that
> +        haven't changed recently are shown up to the latest event, rather than
> +        only once they end. The lock must be held.
> +        """
> +        end = self.last_time
> +        if not end:
> +            return
> +        for task in self.tasks.values():
> +            if task.state == STATE_RUNNING and end > task.since:
> +                task.segs.add(task.since, end, STATE_RUNNING, task.cpu)
> +                task.totals[STATE_RUNNING] += end - task.since
> +                task.since = end

[Severity: Low]
Can extending all running tasks to self.last_time cause Task.totals to drift
when a subsequent flush delivers an earlier event on another CPU?

checkpoint() advances task.segs.ends[-1] and task.since to self.last_time
for every running task.  If the next round flushes an event for one of those
tasks with sample_time < self.last_time, Task.change_state() sets
self.since = time (which is now earlier than self.segs.ends[-1]).  On the
following state change, change_state() adds the unclipped time - self.since
to self.totals, whereas self.segs.add() clips the segment start to
self.segs.ends[-1]; when Task.prune() later removes that segment, it
subtracts the clipped length from self.totals, leaking the difference.

[ ... ]
> @@ -604,7 +820,8 @@ class TimechartData:
>                         if len(t.io) and t.passes_filter(filters)),
>                        key=lambda t: -len(t.io))
>  
> -    def dump(self, power_only: bool, tasks_only: bool, filters: Sequence[str]) -> None:
> +    def dump(self, power_only: bool, tasks_only: bool, filters: Sequence[str],
> +             io_only: bool = False) -> None:
>          """Print a plain text summary, for use without a terminal UI."""
>          duration = self.last_time - self.first_time
>          span = max(duration, 1)
> @@ -613,7 +830,7 @@ class TimechartData:
>          print(f"Duration: {fmt_duration(duration)}, CPUs: {len(self.cpus)}, "
>                f"tasks: {len(tasks) or len(io_tasks)}, sched events: {self.sched_events}, "
>                f"power events: {self.power_events}, I/O events: {self.io_events}")

[Severity: Low]
When io_only is true on a perf.data file that also contains scheduler
events, shouldn't dump() and TimechartApp.update_views() ignore
sched_tasks()?

In both dump() and TimechartApp.update_views(), tasks is still populated
from data.sched_tasks(filters) when io_only is set.  If a recorded file
contains scheduler events as well as I/O events, -I reports the scheduler
task count and fills the Summary tab with scheduler tasks instead of
io_tasks, and pressing Enter on a task without I/O fails to jump to the
hidden Tasks tab.

[ ... ]
> @@ -1486,6 +1743,218 @@ class TimechartApp(App):
[ ... ]
> +    def recording_finished(self) -> None:
> +        """Called on the UI thread when perf record exits, such as when the workload ends."""
> +        # Keep showing the window at the end of recording, or when paused,
> +        # which is after the history already discarded.
> +        self.finished_at = self.paused_at or monotonic_ns()
> +        self.data.finish()
> +        self.recording = False
> +        self.paused_at = 0
> +        self.loaded = True
> +        with self.data.lock:
> +            # Discard history from events flushed when perf record exited.
> +            self.live_prune()
> +        self.refresh_bindings()
> +        self.update_views()
> +        self.update_live_status()
> +
> +    def live_bounds(self) -> Tuple[int, int]:
> +        """The time range kept and shown in live mode, the last window of the recording.
> +
> +        Until a window of time has been recorded the range is the first window,
> +        so the timeline fills from the left, after that it moves with time.
> +        """
> +        assert self.live
> +        if self.paused_at:
> +            now = self.paused_at
> +        elif self.recording:
> +            now = monotonic_ns()
> +        else:
> +            now = self.finished_at
> +        last = max(now, self.live.origin + self.live_window)
> +        return max(self.live.origin, last - self.live_window), last
> +
> +    def live_prune(self) -> None:
> +        """Discard history before the live window, the data's lock must be held.
> +
> +        Open states are only extended up to the last event, see checkpoint(),
> +        so history after it isn't discarded. Otherwise, when events haven't
> +        been seen for a window, a still open state would lose its history.
> +        """
> +        self.data.prune(min(self.live_bounds()[0], self.data.last_time))
> +        self.prune_rows()

[Severity: Medium]
What happens in live_prune() when no new events arrive for --window seconds
so self.live_bounds()[0] reaches self.data.last_time?

TimechartData.checkpoint() and TimechartData.finish() only extend open
segments up to self.last_time, and SegmentList.num_ending_by(time) uses
bisect.bisect_right(self.ends, time), which selects all segments with
end <= time.  Once self.live_bounds()[0] >= self.data.last_time, clamping
the prune time to self.data.last_time passes self.data.last_time to
self.data.prune(), which deletes every segment in the trace (including open
states just extended to self.data.last_time by checkpoint()).  In
recording_finished(), self.data.finish() also sets every task's state to
STATE_UNKNOWN before self.live_prune() runs, so all tasks become empty and
are deleted as well.

[ ... ]
> @@ -1726,52 +2210,642 @@ class TimechartApp(App):
[ ... ]
> +    def pump(self, src: int, dst: int, output: Any) -> None:
[ ... ]
> +                while True:
> +                    try:
> +                        buf = os.read(src, 1 << 16)
> +                    except BlockingIOError:
> +                        break
> +                    except OSError:
> +                        eof = True
> +                        break
> +                    if not buf:
> +                        eof = True
> +                        break
> +                    if output:
> +                        output.write(buf)
> +                    with self.round_lock:
> +                        tracker.feed(buf)
> +                    if forwarding and not self.stopping.is_set():
> +                        # Keep draining src if dst is no longer read.
> +                        forwarding = self.write_pump(dst, buf)
> +                if eof or not forwarding or self.stopping.is_set():
> +                    continue
> +                flush = False
> +                with self.round_lock:
> +                    target = self.flush_round_target
> +                    self.flush_round_target = None
> +                    if (target is not None and tracker.at_boundary() and
> +                            tracker.unflushed_round and
> +                            (target < 0 or tracker.rounds == target)):
> +                        tracker.unflushed_round = False
> +                        flush = True

[Severity: Low]
Can pump() clear self.flush_round_target before reading the data that
control_loop() wanted to flush?

pump thread                       control thread
-----------                       --------------
os.read(src) -> BlockingIOError
                                  send("ping")
                                    perf record writes round + FINISHED_ROUND
                                    perf record writes ack
                                  with self.round_lock:
                                    self.flush_round_target = -1
                                  wake_pump()
with self.round_lock:
  target = self.flush_round_target
  self.flush_round_target = None  <-- cleared before new data in src is read

On the next loop iteration pump() drains the new round from src (setting
tracker.unflushed_round = True), but self.flush_round_target has already
been reset to None, leaving the final round unflushed in ordered_events
while paused.  Snapshotting self.flush_round_target before draining src (and
only clearing it if it wasn't updated in the meantime) would avoid losing
the flush request.

[ ... ]
> +    def backlog(self) -> float:
> +        """The fraction of the data pipe filled with data waiting to be processed."""
> +        try:
> +            pending = array.array("i", [0])
> +            fcntl.ioctl(self.data_fd, termios.FIONREAD, pending)
> +            size = fcntl.fcntl(self.data_fd, fcntl.F_GETPIPE_SZ)
> +        except OSError:
> +            return 0.0
> +        return pending[0] / max(size, 1)

[Severity: Low]
Can backlog() race with close_data_fds() when recording stops and raise an
uncaught ValueError on the UI thread?

worker thread                     UI thread
-------------                     ---------
record_events()
  live.stop()
    close_data_fds()
      self.data_fd = -1
      os.close(tee_r)
                                  live_refreshed()
                                    tune_refresh()
                                      live.backlog()
                                        fcntl.ioctl(-1, ...)  <-- raises ValueError
  call_from_thread(recording_finished)
    self.recording = False

In Python, passing -1 to fcntl.ioctl() or fcntl.fcntl() raises ValueError
rather than OSError, which is not caught here.  In addition, if
close_data_fds() closes tee_r right after backlog() reads self.data_fd, a
concurrent open() (such as restore_own_comm() opening /proc/self/comm) can
reuse that file descriptor number before ioctl() runs.

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