Parse Traces to find top hrtimer users who actually have timers fire

hrtimer_trace_parse.py

#!/usr/bin/python3
# Run for tracing:
# With full screen video playing on device, run:
# trace-cmd record -e timer:hrtimer_start -R stacktrace -e hrtimer_cancel -e timer:hrtimer_expire_entry -- sleep 5
# trace-cmd report > trace.txt
# Pass the trace to this script.
# The script will produce a filter_trace.txt which only shows hrtimer events that actually fired and
# did not get canceled.
# The script will also output the top-most frequent stacks that queued a timer.

import re
import sys

# lines -> count
unique_stack_counts = {}

def process_trace_file(file_path):
    with open(file_path, 'r') as f:
        lines = f.readlines()

    output_lines = []
    last_hrtimer_id_start = {}
    hrtimer_events = {}
    last_hrtimer_stack_cpu = None

    # cpu -> lines
    last_stack_trace = {}

    # hrtimer id -> func
    hrtimer_id_func = {}

    for line in lines:
        hrtimer_start_match = re.match(r'.*\[([\d]+)\].*hrtimer_start:.*hrtimer=(0x[a-fA-F0-9]+).*function=([a-zA-Z0-9_]+)', line)
        hrtimer_cancel_match = re.match(r'.*\[([\d]+)\].*hrtimer_cancel:.*hrtimer=(0x[a-fA-F0-9]+)', line)
        hrtimer_expire_match = re.match(r'.*\[([\d]+)\].*hrtimer_expire_entry:.*hrtimer=(0x[a-fA-F0-9]+)', line)
        kernel_stack_match = re.match(r'.*\[([\d]+)\].*kernel_stack:', line)
        stack_trace_match = re.match(r'.*=>', line)

        # print(line)
        if hrtimer_start_match:
            cpu, hrtimer_id, func = hrtimer_start_match.groups()
            if cpu is None or hrtimer_id is None:
                continue
            last_hrtimer_id_start[cpu] = hrtimer_id

            # Start tracking the queue of the hrtimer
            # Start buffering the trace for this event.
            hrtimer_events[(cpu, hrtimer_id)] = [line]
            hrtimer_id_func[hrtimer_id] = func

        elif hrtimer_cancel_match:
            cpu, hrtimer_id = hrtimer_cancel_match.groups()
            if cpu is None or hrtimer_id is None:
                continue
            if (cpu, hrtimer_id) in hrtimer_events:
                hrtimer_events[(cpu, hrtimer_id)].append(line)

        elif hrtimer_expire_match:
            cpu, hrtimer_id = hrtimer_expire_match.groups()
            if cpu is None or hrtimer_id is None:
                continue
            if (cpu, hrtimer_id) in hrtimer_events:
                hrtimer_events[(cpu, hrtimer_id)].append(line)
                output_lines.extend(hrtimer_events[(cpu, hrtimer_id)])
                del hrtimer_events[(cpu, hrtimer_id)]

                # Count the unique stack.
                if (cpu, hrtimer_id) in last_stack_trace:
                    func = hrtimer_id_func[hrtimer_id]
                    # Remove the kernel_stack line
                    str_stack = "".join(last_stack_trace[(cpu, hrtimer_id)][1:])
                    str_stack = f"Callback: {func}\n" + str_stack
                    if str_stack in unique_stack_counts:
                        unique_stack_counts[str_stack] += 1
                    else:
                        unique_stack_counts[str_stack] = 1

        elif kernel_stack_match:
            cpu = kernel_stack_match.groups()[0]
            hrtimer_id = last_hrtimer_id_start[cpu]

            # Used by the => that follow
            last_hrtimer_stack_cpu = cpu

            if cpu is None or hrtimer_id is None:
                continue

            # Buffer this line if the hrtimer is being tracked.
            if (cpu, hrtimer_id) in hrtimer_events:
                hrtimer_events[(cpu, hrtimer_id)].append(line)
                last_stack_trace[(cpu, hrtimer_id)] = [line]

        elif stack_trace_match:
            cpu = last_hrtimer_stack_cpu
            hrtimer_id = last_hrtimer_id_start[cpu]
            if cpu is None or hrtimer_id is None:
                continue
            if (cpu, hrtimer_id) in hrtimer_events:
                hrtimer_events[(cpu, hrtimer_id)].append(line)
                last_stack_trace[(cpu, hrtimer_id)].append(line)

        else:
            last_hrtimer_stack_cpu = None
            output_lines.append(line)

    with open('filtered_' + file_path, 'w') as f:
        f.writelines(output_lines)

if __name__ == '__main__':
    if len(sys.argv) < 2:
        print("Usage: python3 filter_trace.py <trace_file>")
        sys.exit(1)

    trace_file = sys.argv[1]
    process_trace_file(trace_file)

    print("Unique stack traces and their occurrence counts:")
    sorted_unique_stacks = sorted(unique_stack_counts.items(), key=lambda x: x[1], reverse=True)
    for i, (stack, count) in enumerate(sorted_unique_stacks, start=1):
        print(f"\nStack trace {i}: occurred {count} times")
        print("".join(stack))