Lumpiasty/llama.cpp
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

hexagon: further improved pipeline of the core bits (L2, DMA, MM, FA) (#26049)

Browse Source 
* hex-l2: use dirty ranges for flushing

* hex-l2: simplify range based flush logic

* hex-l2: optimize dirty range scans

* hex-hvx: support for reduce_max_i32

* hex-mm: optimize fused MUL_MAT+ADD to use vtcm for bias when it fits

* hex-mmid: optimize mmid row-mapping generation

* hex-mmid: optimize mmid row-mapping generation

* hex-mmid: optimize mmid row-mapping generation (round2)

* hmx-mm: optimize output proc by tiling (col-chunking)

* hex-fa: start the next q dmas a bit earlier

* hex-fa: prefetch Q even earlier

* hvx-fa: optimize softmax to keep things in hvx registers

* hex-fa: hoist const register init in softmax loop

* hmx-fa: kick off next-qkv DMAs before o-proc

* hmx-fa: hoist various checks out of the inner loop

* hmx-fa: adjust the cost model to better balance softmax work across hvx threads

* hmx-fa: overlap diag rescale build with last HMX task

* hmx-fa: optimize idx update in output proc

* hmx-fa: unroll the softmax loops for improved perf

* hmx-fa: overlap qk-dot with softmax, double-buffer p and s tiles

* hex-trace: double the default number of trace entries

* hex-trace: add trace events for opbatch and buffer mgmt

* hex-trace: overhaul tracing to simplify runtime event handling and support opbatch stats

* hex-trace: replace ascii timeline diagram with pipeline bubbles detector

* hex-trace: handle missing start/stop events

* hex-dma: always log stop/start trace events even for dummy dmas

* hex-scripts: fix flake warnings
This commit is contained in:
Max Krasnyansky
2026-07-23 19:13:03 -07:00
committed by GitHub
parent c0bc8591e8
commit 0a50d9909a
17 changed files with 1666 additions and 761 deletions
Download Patch File Download Diff File Expand all files Collapse all files
scripts/snapdragon/ggml-hexagon-profile.py
+237 -93
View File
@@ -6,6 +6,7 @@ import re
import argparse
import statistics
import logging
import bisect
from typing import Any, Dict, List, Optional
from collections import defaultdict
@@ -30,7 +31,7 @@ op_pattern = re.compile(
)
trace_pattern = re.compile(
r"trace-op\s+(?P<op_name>[A-Z_0-9+]+):\s+thread\s+(?P<thread>\d+)\s+event\s+(?P<event>[A-Z_0-9\-]+)\s+info\s+(?P<info>\d+)\s+(?P<state>start|stop)\s+(?P<cycles>\d+)"
r"trace-evt\s+(?P<event>[A-Z_0-9\-]+):\s+thread\s+(?P<thread>\d+)\s+info\s+(?P<info>\d+)\s+(?P<state>start|stop)\s+(?P<cycles>\d+)"
)
logger = logging.getLogger("ggml-hexagon-profile")
@@ -50,9 +51,13 @@ def normalize_event_name(evt_type):
class CycleUnwrapper:
def __init__(self):
self.last_raw = None
self.high_part = 0
def __init__(self, initial_val=None):
if initial_val is not None:
self.last_raw = initial_val & 0xFFFFFFFF
self.high_part = initial_val & 0xFFFFFFFF00000000
else:
self.last_raw = None
self.high_part = 0
def unwrap(self, raw):
if self.last_raw is None:
@@ -78,10 +83,12 @@ def parse_log(file_path, pmu_index=None):
sys.exit(1)
all_ops: List[Dict[str, Any]] = []
all_traces: List[Dict[str, Any]] = []
current_op: Optional[Dict[str, Any]] = None
timestamp_pattern = re.compile(r"^(?P<min>\d+)\.(?P<sec>\d+)\.(?P<ms>\d+)\.(?P<us>\d+)\s+[A-Z]\s+")
unwrapper = CycleUnwrapper()
unwrapper = None
trace_unwrapper = None
for line in f:
ts_match = timestamp_pattern.match(line)
@@ -100,6 +107,7 @@ def parse_log(file_path, pmu_index=None):
if not prefix_match:
continue
names = parts[1]
if len(parts) == 7:
dims, types, timings = parts[2], parts[3], parts[6]
elif len(parts) == 6:
@@ -120,6 +128,7 @@ def parse_log(file_path, pmu_index=None):
op_match = op_pattern.search(line)
if op_match:
op_name = op_match.group('op_name')
names = ""
dims = op_match.group('dims').strip()
types = op_match.group('types').strip()
else:
@@ -136,24 +145,31 @@ def parse_log(file_path, pmu_index=None):
except (ValueError, IndexError):
pmu_val = None
evt_raw = op_match.group('evt') if 'evt' in op_match.groupdict() else None
evt_val = None
if evt_raw:
evt_val = None
if types.startswith("evt-cnt "):
try:
evt_val = [int(x.strip()) for x in evt_raw.split(',')]
evt_val = [int(x.strip()) for x in types[8:].split(',')]
except ValueError:
evt_val = None
cycles_start_raw = op_match.group('start')
unwrapped_cycles_start = None
if cycles_start_raw:
unwrapped_cycles_start = unwrapper.unwrap(int(cycles_start_raw))
if op_name == "OPBATCH":
if cycles_start_raw:
unwrapped_cycles_start = int(cycles_start_raw)
unwrapper = CycleUnwrapper(unwrapped_cycles_start)
trace_unwrapper = CycleUnwrapper(unwrapped_cycles_start)
else:
if cycles_start_raw and unwrapper is not None:
unwrapped_cycles_start = unwrapper.unwrap(int(cycles_start_raw))
idx = line.find("profile-op ")
op_text = line[idx + 11:].strip() if idx != -1 else line.strip()
current_op = {
'name': op_name,
'names': names,
'dims': dims,
'types': types,
'op_text': op_text,
@@ -170,110 +186,239 @@ def parse_log(file_path, pmu_index=None):
continue
trace_match = trace_pattern.search(line)
if trace_match and current_op:
if trace_match.group('op_name') == current_op['name']:
raw_cyc = int(trace_match.group('cycles'))
current_op['trace_events'].append({
'thread': int(trace_match.group('thread')),
'event': trace_match.group('event'),
'info': int(trace_match.group('info')),
'cycles': raw_cyc,
'unwrapped_cycles': unwrapper.unwrap(raw_cyc),
'state': trace_match.group('state')
})
if trace_match:
raw_cyc = int(trace_match.group('cycles'))
unwrapped_cyc = None
if trace_unwrapper is not None:
unwrapped_cyc = trace_unwrapper.unwrap(raw_cyc)
all_traces.append({
'thread': int(trace_match.group('thread')),
'event': trace_match.group('event'),
'info': int(trace_match.group('info')),
'cycles': raw_cyc,
'unwrapped_cycles': unwrapped_cyc,
'state': trace_match.group('state')
})
f.close()
# Assign start/end cycles to all ops
for op in all_ops:
op['start_cycles'] = op['unwrapped_cycles_start']
op['end_cycles'] = op['start_cycles'] + op['cycles'] if op['start_cycles'] is not None else None
# Filter ops with valid start_cycles
valid_ops = [op for op in all_ops if op['start_cycles'] is not None and op['end_cycles'] is not None]
# Separate OPBATCH ops from other ops
opbatch_ops = [op for op in valid_ops if op['name'] == "OPBATCH"]
other_ops = [op for op in valid_ops if op['name'] != "OPBATCH"]
# Sort them by start_cycles to enable binary search
opbatch_ops.sort(key=lambda op: op['start_cycles'])
other_ops.sort(key=lambda op: op['start_cycles'])
opbatch_starts = [op['start_cycles'] for op in opbatch_ops]
other_starts = [op['start_cycles'] for op in other_ops]
# Map trace events to any operator whose cycles contain them
for e in all_traces:
cyc = e['unwrapped_cycles']
if cyc is None:
continue
# Map to OPBATCH
idx = bisect.bisect_right(opbatch_starts, cyc) - 1
if idx >= 0:
op = opbatch_ops[idx]
if op['start_cycles'] <= cyc <= op['end_cycles']:
op['trace_events'].append(e)
# Map to other ops
idx = bisect.bisect_right(other_starts, cyc) - 1
if idx >= 0:
op = other_ops[idx]
if op['start_cycles'] <= cyc <= op['end_cycles']:
op['trace_events'].append(e)
return all_ops
def print_ascii_timeline(op_name, dims, types, usec, cycles, events, evt_val=None):
evt_str = ""
if evt_val:
evt_str = " - evt [" + ",".join(str(x) for x in evt_val) + "]"
def print_bubbles_timeline(op):
op_name = op['name']
dims = op['dims']
types = op['types']
usec = op['usec']
cycles = op['cycles']
events = op['trace_events']
logger.info("=" * 100)
logger.info(f"{op_name} ({dims} : {types}) - {usec} usec {cycles} cycles{evt_str}")
logger.info(f"{op_name} ({dims} : {types}) - {usec} usec {cycles} cycles")
logger.info("=" * 100)
events = sorted(events, key=lambda e: e['cycles'])
if not events:
logger.info(" No trace events recorded.")
return
min_cycles = events[0]['cycles']
# Identify start and end cycles for this operator
op_start = op['start_cycles']
op_end = op['end_cycles']
if op_start is None or op_end is None:
logger.info(" Cannot analyze bubbles: missing start/end cycle counts.")
return
logger.info("Cycles %-30s" % "EventDetails" + " ".join(f"T{i:<2}" for i in range(10)) + " HMX")
logger.info("-" * 100)
thread_stacks = [[] for _ in range(11)]
batch_duration = op_end - op_start
if batch_duration <= 0:
logger.info(" Cannot analyze bubbles: batch duration is 0.")
return
# Group events by (thread, track_type)
tracks = defaultdict(list)
for e in events:
t = e['thread']
if t < 0 or t > 10:
continue
is_dma = (normalize_event_name(e['event']) == 'DMA')
track_type = 'dma' if is_dma else 'compute'
tracks[(t, track_type)].append(e)
if e['cycles'] >= min_cycles:
rel_cycles = e['cycles'] - min_cycles
else:
rel_cycles = (e['cycles'] + 0x100000000) - min_cycles
active_threads = sorted(list(set(t for (t, track_type) in tracks.keys())))
if not active_threads:
logger.info(" No active threads in trace.")
return
state = e['state']
evt_type = e['event']
bubble_threshold = 10000 # 10k cycles
# Determine char representing the event
norm_evt = normalize_event_name(evt_type)
char = '?'
if norm_evt == 'V-COMP':
char = 'V'
elif norm_evt == 'M-COMP':
char = 'H'
elif norm_evt == 'A-QUANT':
char = 'Q'
elif norm_evt == 'A-PREP':
char = 'A'
elif norm_evt == 'Q-PREP':
char = 'q'
elif norm_evt == 'K-PREP':
char = 'k'
elif norm_evt == 'V-PREP':
char = 'v'
elif norm_evt == 'W-DEQUANT':
char = 'D'
elif norm_evt == 'O-PROC':
char = 'O'
elif norm_evt == 'W-PREP':
char = 'P'
elif norm_evt == 'DMA':
char = 'M'
thread_stats = {}
for t in active_threads:
thread_stats[t] = {
'compute_idle_cycles': batch_duration,
'compute_idle_pct': 100.0,
'compute_bubbles': [],
if state == 'start':
thread_stacks[t].append(char)
elif state == 'stop':
if thread_stacks[t]:
if thread_stacks[t][-1] == char:
thread_stacks[t].pop()
elif char in thread_stacks[t]:
thread_stacks[t].remove(char)
else:
thread_stacks[t].pop()
'dma_idle_cycles': batch_duration,
'dma_idle_pct': 100.0,
'dma_bubbles': []
}
cols = []
for i in range(11):
if thread_stacks[i]:
cols.append(f"[{thread_stacks[i][-1]}]")
total_compute_idle_pct = 0.0
total_dma_idle_pct = 0.0
for t in active_threads:
for track_type in ['compute', 'dma']:
key = (t, track_type)
track_events = tracks.get(key, [])
if not track_events:
gaps = [(op_start, op_end)]
idle_cycles = batch_duration
else:
cols.append(" | ")
track_events = sorted(track_events, key=lambda e: e.get('unwrapped_cycles') or e['cycles'])
evt_desc = f"T{t}: {evt_type} {state} ({e['info']})"
logger.info(f"{rel_cycles:10d} %-30s" % evt_desc + " ".join(cols[:10]) + " " + cols[10])
active_intervals = []
active_count = 0
curr_start = None
for e in track_events:
cyc = e.get('unwrapped_cycles') or e['cycles']
cyc = max(op_start, min(op_end, cyc))
state = e['state']
if state == 'start':
if active_count == 0:
curr_start = cyc
active_count += 1
elif state == 'stop':
if active_count > 0:
active_count -= 1
if active_count == 0:
active_intervals.append((curr_start, cyc))
else:
active_intervals.append((op_start, cyc))
if active_count > 0 and curr_start is not None:
active_intervals.append((curr_start, op_end))
# Merge intervals
active_intervals.sort(key=lambda x: x[0])
merged_intervals = []
for start, end in active_intervals:
if not merged_intervals:
merged_intervals.append([start, end])
else:
last_start, last_end = merged_intervals[-1]
if start <= last_end:
merged_intervals[-1][1] = max(last_end, end)
else:
merged_intervals.append([start, end])
# Calculate gaps
gaps = []
curr_time = op_start
for start, end in merged_intervals:
if start > curr_time:
gaps.append((curr_time, start))
curr_time = max(curr_time, end)
if curr_time < op_end:
gaps.append((curr_time, op_end))
idle_cycles = sum(end - start for start, end in gaps)
idle_pct = (idle_cycles / batch_duration) * 100.0
bubbles = []
for start, end in gaps:
dur = end - start
if dur >= bubble_threshold:
bubbles.append((start, end, dur))
if track_type == 'compute':
thread_stats[t]['compute_idle_cycles'] = idle_cycles
thread_stats[t]['compute_idle_pct'] = idle_pct
thread_stats[t]['compute_bubbles'] = bubbles
total_compute_idle_pct += idle_pct
else:
thread_stats[t]['dma_idle_cycles'] = idle_cycles
thread_stats[t]['dma_idle_pct'] = idle_pct
thread_stats[t]['dma_bubbles'] = bubbles
total_dma_idle_pct += idle_pct
avg_compute_idle = total_compute_idle_pct / len(active_threads)
avg_dma_idle = total_dma_idle_pct / len(active_threads)
logger.info(" Combined Idle Statistics:")
logger.info(f" Active Threads : {', '.join(str(t) for t in active_threads)}")
logger.info(f" Avg Thread Compute IDLE : {avg_compute_idle:.1f}%")
logger.info(f" Avg Thread DMA IDLE : {avg_dma_idle:.1f}%")
logger.info("-" * 100)
logger.info(" Per-Thread Idle Analysis:")
for t in active_threads:
stats = thread_stats[t]
thread_name = f"Thread {t:<2} (HVX)" if t != 10 else "Thread 10 (HMX)"
logger.info(f" {thread_name} -> Compute Idle: {stats['compute_idle_pct']:.1f}% | DMA Idle: {stats['dma_idle_pct']:.1f}%")
def print_ascii_summary(op_name, dims, types, usec, cycles, events, evt_val=None):
evt_str = ""
if evt_val:
evt_str = " - evt [" + ",".join(str(x) for x in evt_val) + "]"
all_bubbles = []
for t in active_threads:
stats = thread_stats[t]
for start, end, dur in stats['compute_bubbles']:
pct = (dur / batch_duration) * 100.0
all_bubbles.append((dur, f"Thread {t} Compute: bubble of {dur} cycles ({pct:.1f}%) at {start - op_start} to {end - op_start}"))
for start, end, dur in stats['dma_bubbles']:
pct = (dur / batch_duration) * 100.0
all_bubbles.append((dur, f"Thread {t} DMA : bubble of {dur} cycles ({pct:.1f}%) at {start - op_start} to {end - op_start}"))
if all_bubbles:
logger.info("-" * 100)
logger.info(f" Significant Bubbles (>= {bubble_threshold} cycles):")
all_bubbles.sort(key=lambda x: x[0], reverse=True)
for dur, desc in all_bubbles[:15]:
logger.info(f" {desc}")
else:
logger.info("-" * 100)
logger.info(f" No significant bubbles detected (all idle gaps < {bubble_threshold} cycles).")
def print_ascii_summary(op_name, dims, types, usec, cycles, events):
logger.info("=" * 100)
logger.info(f"{op_name} ({dims} : {types}) - {usec} usec {cycles} cycles{evt_str}")
logger.info(f"{op_name} ({dims} : {types}) - {usec} usec {cycles} cycles")
logger.info("=" * 100)
events = sorted(events, key=lambda e: e['cycles'])
@@ -415,8 +560,8 @@ def main():
parser.add_argument("--pmu-index", type=int)
parser.add_argument("--pmu-name", type=str)
parser.add_argument("--width", action='append', default=['dims:40'], help="Override column width, e.g. --width dims:50")
parser.add_argument("--timeline", type=str, nargs='?', const='summary', choices=["summary", "diagram"],
help="Output ASCII art event summary or timing diagram (default: summary)")
parser.add_argument("--timeline", type=str, nargs='?', const='summary', choices=["summary", "bubbles"],
help="Output ASCII art event summary or thread idle bubble analysis (default: summary)")
parser.add_argument("--filter", type=str, help="Regex filter matching against the original profile-op line")
group = parser.add_mutually_exclusive_group()
@@ -457,12 +602,11 @@ def main():
ops = ops[-args.tail:]
if args.timeline:
logger.info(f"\n# ASCII Timing {args.timeline.capitalize()}\n")
for op in ops:
if args.timeline == "summary":
print_ascii_summary(op['name'], op['dims'], op['types'], op['usec'], op['cycles'], op['trace_events'], op.get('evt_val'))
elif args.timeline == "diagram":
print_ascii_timeline(op['name'], op['dims'], op['types'], op['usec'], op['cycles'], op['trace_events'], op.get('evt_val'))
print_ascii_summary(op['name'], op['dims'], op['types'], op['usec'], op['cycles'], op['trace_events'])
elif args.timeline == "bubbles":
print_bubbles_timeline(op)
else:
generate_report(ops, args.top, overrides, args.sort, pmu_name=final_pmu_name)
scripts/snapdragon/ggml-hexagon-trace.py
+130 -40
View File
@@ -6,6 +6,7 @@ import re
import argparse
import statistics
import logging
import bisect
from typing import Any, Dict, List, Optional
from collections import defaultdict
@@ -16,11 +17,11 @@ op_pattern = re.compile(
)
trace_pattern = re.compile(
r"trace-op\s+(?P<op_name>[A-Z_0-9+]+):\s+thread\s+(?P<thread>\d+)\s+event\s+(?P<event>[A-Z_0-9\-]+)\s+info\s+(?P<info>\d+)\s+(?P<state>start|stop)\s+(?P<cycles>\d+)"
r"trace-evt\s+(?P<event>[A-Z_0-9\-]+):\s+thread\s+(?P<thread>\d+)\s+info\s+(?P<info>\d+)\s+(?P<state>start|stop)\s+(?P<cycles>\d+)"
)
def normalize_event_name(evt_type):
def normalize_event_name(evt_type, info=0):
if evt_type == "HVX_COMP":
return "V-COMP"
if evt_type == "HMX_COMP":
@@ -32,9 +33,13 @@ def normalize_event_name(evt_type):
class CycleUnwrapper:
def __init__(self):
self.last_raw = None
self.high_part = 0
def __init__(self, initial_val=None):
if initial_val is not None:
self.last_raw = initial_val & 0xFFFFFFFF
self.high_part = initial_val & 0xFFFFFFFF00000000
else:
self.last_raw = None
self.high_part = 0
def unwrap(self, raw):
if self.last_raw is None:
@@ -60,8 +65,10 @@ def parse_log(file_path):
sys.exit(1)
all_ops: List[Dict[str, Any]] = []
all_traces: List[Dict[str, Any]] = []
current_op: Optional[Dict[str, Any]] = None
unwrapper = CycleUnwrapper()
unwrapper = None
trace_unwrapper = None
line_idx = 0
for line in f:
@@ -73,6 +80,7 @@ def parse_log(file_path):
if not prefix_match:
continue
names = parts[1]
if len(parts) == 7:
dims, types, strides, params, timings = parts[2], parts[3], parts[4], parts[5], parts[6]
elif len(parts) == 6:
@@ -93,6 +101,7 @@ def parse_log(file_path):
op_match = op_pattern.search(line)
if op_match:
op_name = op_match.group('op_name')
names = ""
dims = op_match.group('dims').strip() if op_match.group('dims') else ''
types = op_match.group('types').strip() if op_match.group('types') else ''
strides = op_match.group('strides').strip() if op_match.group('strides') else ''
@@ -103,18 +112,30 @@ def parse_log(file_path):
if op_match:
cycles_start_raw = op_match.group('start')
unwrapped_cycles_start = None
if cycles_start_raw:
unwrapped_cycles_start = unwrapper.unwrap(int(cycles_start_raw))
if op_name == "OPBATCH":
if cycles_start_raw:
unwrapped_cycles_start = int(cycles_start_raw)
unwrapper = CycleUnwrapper(unwrapped_cycles_start)
trace_unwrapper = CycleUnwrapper(unwrapped_cycles_start)
else:
if cycles_start_raw and unwrapper is not None:
unwrapped_cycles_start = unwrapper.unwrap(int(cycles_start_raw))
idx = line.find("profile-op ")
op_text = line[idx + 11:].strip() if idx != -1 else line.strip()
evt_str = None
if types.startswith("evt-cnt "):
evt_str = types[8:].strip()
current_op = {
'name': op_name,
'names': names,
'dims': dims,
'types': types,
'strides': strides,
'params': params,
'evt': evt_str,
'op_text': op_text,
'usec': int(op_match.group('usec')),
'cycles': int(op_match.group('cycles')),
@@ -127,20 +148,22 @@ def parse_log(file_path):
continue
trace_match = trace_pattern.search(line)
if trace_match and current_op:
if trace_match.group('op_name') == current_op['name']:
raw_cyc = int(trace_match.group('cycles'))
current_op['trace_events'].append({
'thread': int(trace_match.group('thread')),
'event': trace_match.group('event'),
'info': int(trace_match.group('info')),
'cycles': raw_cyc,
'unwrapped_cycles': unwrapper.unwrap(raw_cyc),
'state': trace_match.group('state')
})
if trace_match:
raw_cyc = int(trace_match.group('cycles'))
unwrapped_cyc = None
if trace_unwrapper is not None:
unwrapped_cyc = trace_unwrapper.unwrap(raw_cyc)
all_traces.append({
'thread': int(trace_match.group('thread')),
'event': trace_match.group('event'),
'info': int(trace_match.group('info')),
'cycles': raw_cyc,
'unwrapped_cycles': unwrapped_cyc,
'state': trace_match.group('state')
})
f.close()
return all_ops
return all_ops, all_traces
# --- Simple protobuf encoder ---
@@ -246,7 +269,7 @@ def write_trace_packet_to_file(f, packet_bytes):
# --- End Protobuf Encoder ---
def generate_perfetto_trace(filtered_ops, output_path):
def generate_perfetto_trace(filtered_ops, trace_events, output_path):
if not filtered_ops:
logger.warning("No operators found after filtering.")
return
@@ -269,14 +292,12 @@ def generate_perfetto_trace(filtered_ops, output_path):
# Process events
completed_events = []
for op in filtered_ops:
events = op['trace_events']
if not events:
continue
events = sorted(events, key=lambda e: e['unwrapped_cycles'])
if trace_events:
trace_events = sorted(trace_events, key=lambda e: e['unwrapped_cycles'])
one_usec_cycles = max(avg_freq_mhz, 1.0)
active_starts = {}
for e in events:
for e in trace_events:
t = e['thread']
evt = e['event']
info = e['info']
@@ -285,6 +306,17 @@ def generate_perfetto_trace(filtered_ops, output_path):
key = (t, evt, info)
if state == 'start':
# Handle missing stop (start followed by another start)
if key in active_starts:
prev_start = active_starts[key]
completed_events.append({
'thread': t,
'event': evt,
'info': info,
'start_cyc': prev_start,
'end_cyc': prev_start + one_usec_cycles,
'missing_stop': True,
})
active_starts[key] = cyc
elif state == 'stop':
if key in active_starts:
@@ -296,8 +328,29 @@ def generate_perfetto_trace(filtered_ops, output_path):
'info': info,
'start_cyc': start_cyc,
'end_cyc': cyc,
'op_name': op['name']
})
else:
# Handle missing start (stop without start)
completed_events.append({
'thread': t,
'event': evt,
'info': info,
'start_cyc': cyc - one_usec_cycles,
'end_cyc': cyc,
'missing_start': True,
})
# Clear remaining unmatched starts
for key, start_cyc in active_starts.items():
t, evt, info = key
completed_events.append({
'thread': t,
'event': evt,
'info': info,
'start_cyc': start_cyc,
'end_cyc': start_cyc + one_usec_cycles,
'missing_stop': True,
})
completed_events.sort(key=lambda e: e['start_cyc'])
@@ -316,7 +369,7 @@ def generate_perfetto_trace(filtered_ops, output_path):
ts = e['ts_ns']
dur = e['dur_ns']
norm_evt = normalize_event_name(evt)
norm_evt = normalize_event_name(evt, e['info'])
if norm_evt == "DMA":
track_key = (t, "DMA")
elif t == 10:
@@ -343,7 +396,7 @@ def generate_perfetto_trace(filtered_ops, output_path):
evt = e['event']
slot = e['slot']
norm_evt = normalize_event_name(evt)
norm_evt = normalize_event_name(evt, e['info'])
if norm_evt == "DMA":
track_evt = "DMA"
evt_id = 1
@@ -421,18 +474,26 @@ def generate_perfetto_trace(filtered_ops, output_path):
for op in filtered_ops:
op_start_ns = int(round(((op['start_cycles'] - global_min_cyc) / avg_freq_mhz) * 1000))
op_dur_ns = int(round((op['cycles'] / avg_freq_mhz) * 1000))
if op_start_ns < last_op_end_ns:
op_start_ns = last_op_end_ns
clamped_dur = max(op_dur_ns, 100) # Clamp to 100ns (0.1us)
if op['name'] != "OPBATCH":
if op_start_ns < last_op_end_ns:
op_start_ns = last_op_end_ns
clamped_dur = max(op_dur_ns, 100) # Clamp to 100ns (0.1us)
last_op_end_ns = op_start_ns + clamped_dur
else:
clamped_dur = max(op_dur_ns, 100)
# Debug annotations for Ops
debug_annots = []
if 'line_num' in op:
debug_annots.append(make_debug_annotation("line", int_val=op['line_num']))
if 'strides' in op and op['strides']:
if 'names' in op and op['names'] and op['names'] != '----':
debug_annots.append(make_debug_annotation("names", string_val=op['names']))
if 'strides' in op and op['strides'] and op['strides'] != '----':
debug_annots.append(make_debug_annotation("strides", string_val=op['strides']))
if 'params' in op and op['params'] and op['params'] != '----':
debug_annots.append(make_debug_annotation("params", string_val=op['params']))
if 'evt' in op and op['evt']:
debug_annots.append(make_debug_annotation("evt", string_val=op['evt']))
# Slice Begin
evt_begin = make_track_event(1, 2, name=f"{op['name']} ({op['dims']})", category="operator", debug_annotations=debug_annots)
@@ -444,15 +505,21 @@ def generate_perfetto_trace(filtered_ops, output_path):
packet_end = make_trace_packet(op_start_ns + clamped_dur, track_event=evt_end)
write_trace_packet_to_file(f, packet_end)
last_op_end_ns = op_start_ns + clamped_dur
# Emit Thread Trace Events
for e in completed_events:
norm_name = normalize_event_name(e['event'])
norm_name = normalize_event_name(e['event'], e['info'])
name = f"DMA {e['info']}" if norm_name == "DMA" else norm_name
if e.get('missing_start') or e.get('missing_stop'):
name += "!"
debug_annots = []
if e.get('missing_start'):
debug_annots.append(make_debug_annotation("missing_start", string_val="true"))
if e.get('missing_stop'):
debug_annots.append(make_debug_annotation("missing_stop", string_val="true"))
# Slice Begin
evt_begin = make_track_event(1, e['uuid'], name=name, category="trace")
evt_begin = make_track_event(1, e['uuid'], name=name, category="trace", debug_annotations=debug_annots if debug_annots else None)
packet_begin = make_trace_packet(e['ts_ns'], track_event=evt_begin)
write_trace_packet_to_file(f, packet_begin)
@@ -477,7 +544,7 @@ def main():
args = parser.parse_args()
logging.basicConfig(level=logging.INFO, format='%(message)s')
ops = parse_log(args.logfile)
ops, traces = parse_log(args.logfile)
if args.filter:
try:
@@ -492,7 +559,30 @@ def main():
elif args.tail is not None:
ops = ops[-args.tail:]
generate_perfetto_trace(ops, args.output)
if args.filter or args.head is not None or args.tail is not None:
valid_ranges = []
for op in ops:
start_cyc = op['unwrapped_cycles_start']
end_cyc = start_cyc + op['cycles'] if start_cyc is not None else None
if start_cyc is not None and end_cyc is not None:
valid_ranges.append((start_cyc, end_cyc))
valid_ranges.sort(key=lambda r: r[0])
range_starts = [r[0] for r in valid_ranges]
filtered_traces = []
for e in traces:
cyc = e['unwrapped_cycles']
if cyc is None:
continue
idx = bisect.bisect_right(range_starts, cyc) - 1
if idx >= 0:
start, end = valid_ranges[idx]
if start <= cyc <= end:
filtered_traces.append(e)
traces = filtered_traces
generate_perfetto_trace(ops, traces, args.output)
if __name__ == "__main__":