char-fork/llama.cpp

git clone https://git.t4t.associates/char-fork/llama.cpp

Max Krasnyanskyhexagon: support for multi-NPU devices (IQ9, IQ10) and fully asynchronous backend (#26501)192067b72

char/aliceai-t5-moe
brancheschar/aliceai-t5-moeall refs →
31.5 KiB818 linesraw
1#!/usr/bin/env python3
2
3import sys
4import os
5import re
6import argparse
7import statistics
8import logging
9import bisect
10from typing import Any, Dict, List, Optional
11from collections import defaultdict
12
13logger = logging.getLogger("ggml-hexagon-trace")
14
15op_pattern = re.compile(
16    r"profile-op\s+(?P<op_name>[A-Z_0-9+]+):\s+.*?\s+:\s+(?P<dims>[\d:x\s\->!]+)\s+:\s+(?P<types>[a-z\d_\s\->x]+)\s+:\s+(?P<strides>[\d:x\s\->!]+?)\s+:\s+(?:(?P<params>.*?)\s+:\s+)?(?:op-)?usec\s+(?P<usec>\d+)\s+(?:op-)?cycles\s+(?P<cycles>\d+)(?:\s+start\s+(?P<start>\d+))?(?:\s+mhz\s+(?P<mhz>[\d.]+))?(?:\s+pmu\s+\[(?P<pmu>[\d,\s]+)\])?(?:\s+evt\s+\[(?P<evt>[\d,\s]+)\])?"
17)
18
19trace_pattern = re.compile(
20    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+)"
21)
22
23device_pattern = re.compile(r"\b(HTP\d+(?::\d+)?)\s+(?:profile-op|trace-evt)\b")
24
25
26def extract_device(line):
27    m = device_pattern.search(line)
28    if m:
29        return m.group(1)
30    return "HTP0"
31
32
33def device_matches(record_device, target_device):
34    targets = [t.strip() for t in target_device.split(',')]
35    for target in targets:
36        if record_device == target:
37            return True
38        if record_device.startswith(target + ":"):
39            return True
40    return False
41
42
43def get_split_output_path(base_path, device_name):
44    safe_device = device_name.replace(':', '_')
45    root, ext = os.path.splitext(base_path)
46    return f"{root}-{safe_device}{ext}"
47
48
49def normalize_event_name(evt_type, info=0):
50    if evt_type == "HVX_COMP":
51        return "V-COMP"
52    if evt_type == "HMX_COMP":
53        return "M-COMP"
54    name = evt_type
55    if name.startswith("HVX_") or name.startswith("HMX_"):
56        name = name[4:]
57    return name.replace("_", "-")
58
59
60class CycleUnwrapper:
61    def __init__(self, initial_val=None):
62        if initial_val is not None:
63            self.last_raw = initial_val & 0xFFFFFFFF
64            self.high_part = initial_val & 0xFFFFFFFF00000000
65        else:
66            self.last_raw = None
67            self.high_part = 0
68
69    def unwrap(self, raw):
70        if self.last_raw is None:
71            self.last_raw = raw
72            return raw
73        diff = raw - self.last_raw
74        if diff < -0x80000000:
75            self.high_part += 0x100000000
76        elif diff > 0x80000000:
77            self.high_part -= 0x100000000
78        self.last_raw = raw
79        return raw + self.high_part
80
81
82class DeviceTimeMapper:
83    def __init__(self, dev, ops):
84        self.dev = dev
85        self.batches = []
86        for op in ops:
87            if op.get('device') == dev and op.get('name') == 'OPBATCH' and op.get('unwrapped_cycles_start') is not None:
88                cycles = op.get('cycles', 0)
89                usec = op.get('usec', 0)
90                start_cyc = op['unwrapped_cycles_start']
91                freq = (cycles / usec) if usec > 0 and cycles > 0 else 1000.0
92                if freq <= 0:
93                    freq = 1000.0
94                self.batches.append({
95                    'start_cycles': start_cyc,
96                    'cycles': cycles,
97                    'end_cycles': start_cyc + cycles,
98                    'usec': usec,
99                    'dur_ns': usec * 1000,
100                    'freq_mhz': freq,
101                })
102
103        self.batches.sort(key=lambda b: b['start_cycles'])
104
105        for i, b in enumerate(self.batches):
106            if i == 0:
107                b['start_time_ns'] = 0
108            else:
109                prev = self.batches[i - 1]
110                idle_cyc = max(0, b['start_cycles'] - prev['end_cycles'])
111                idle_ns = int(round((idle_cyc / prev['freq_mhz']) * 1000))
112                b['start_time_ns'] = prev['start_time_ns'] + prev['dur_ns'] + idle_ns
113
114        self.batch_starts = [b['start_cycles'] for b in self.batches]
115
116        valid_starts = [op['unwrapped_cycles_start'] for op in ops if op.get('device') == dev and op.get('unwrapped_cycles_start') is not None]
117        self.min_cyc = min(valid_starts) if valid_starts else 0
118        if self.batches:
119            self.default_freq = self.batches[0]['freq_mhz']
120        else:
121            freqs = [op['cycles'] / op['usec'] for op in ops if op.get('device') == dev and op.get('usec', 0) > 0 and op.get('cycles', 0) > 0]
122            self.default_freq = statistics.mean(freqs) if freqs else 1000.0
123
124    def get_batch(self, cyc):
125        if not self.batches:
126            return None
127        idx = bisect.bisect_right(self.batch_starts, cyc) - 1
128        if idx >= 0:
129            return self.batches[idx]
130        return self.batches[0]
131
132    def get_freq(self, cyc=None):
133        if cyc is not None:
134            b = self.get_batch(cyc)
135            if b is not None:
136                return b['freq_mhz']
137        return self.default_freq
138
139    def cycle_to_ns(self, cyc):
140        if cyc is None:
141            return 0
142        b = self.get_batch(cyc)
143        if b is not None:
144            return b['start_time_ns'] + int(round(((cyc - b['start_cycles']) / b['freq_mhz']) * 1000))
145        return int(round(((cyc - self.min_cyc) / self.default_freq) * 1000))
146
147    def dur_cycles_to_ns(self, cyc_start, cyc_dur):
148        if cyc_dur is None:
149            return 0
150        freq = self.get_freq(cyc_start)
151        return int(round((cyc_dur / freq) * 1000))
152
153
154def parse_log(file_path, limit=None, device_filter=None, op_filter_re=None):
155    try:
156        if file_path != "-":
157            f = open(file_path, 'r', encoding='utf-8', errors='ignore')
158        else:
159            f = os.fdopen(0, 'r', encoding='utf-8', errors='ignore')
160    except FileNotFoundError:
161        logger.error(f"file '{file_path}' not found.")
162        sys.exit(1)
163
164    all_ops: List[Dict[str, Any]] = []
165    all_traces: List[Dict[str, Any]] = []
166    current_op: Optional[Dict[str, Any]] = None
167    ops_count_per_device = {}
168    if device_filter is not None:
169        for target in device_filter.split(','):
170            ops_count_per_device[target.strip()] = 0
171    limit_reached = False
172    unwrappers = {}
173    last_batch_start = {}
174    trace_unwrappers = {}
175    line_idx = 0
176
177    for line in f:
178        line_idx += 1
179        if "profile-op" not in line and "trace-evt" not in line:
180            continue
181        device = extract_device(line)
182
183        idx = line.find("profile-op")
184        if idx != -1 and "|" in line[idx:]:
185            parts = [p.strip() for p in line[idx:].split("|")]
186            prefix = parts[0]
187            prefix_match = re.search(r"profile-op\s+(?P<op_name>[A-Z_0-9+]+)", prefix)
188            if not prefix_match:
189                continue
190
191            names = parts[1]
192            if len(parts) == 7:
193                dims, types, strides, params, timings = parts[2], parts[3], parts[4], parts[5], parts[6]
194            elif len(parts) == 6:
195                dims, types, strides, params, timings = parts[2], parts[3], parts[4], "", parts[5]
196            else:
197                continue
198
199            timing_match = re.search(
200                r"(?:op-)?usec\s+(?P<usec>\d+)\s+(?:op-)?cycles\s+(?P<cycles>\d+)(?:\s+start\s+(?P<start>\d+))?(?:\s+mhz\s+(?P<mhz>[\d.]+))?(?:\s+pmu\s+\[(?P<pmu>[\d,\s]+)\])?(?:\s+evt\s+\[(?P<evt>[\d,\s]+)\])?",
201                timings
202            )
203            if not timing_match:
204                continue
205
206            op_match = timing_match
207            op_name = prefix_match.group("op_name")
208        else:
209            op_match = op_pattern.search(line)
210            if op_match:
211                op_name = op_match.group('op_name')
212                names = ""
213                dims = op_match.group('dims').strip() if op_match.group('dims') else ''
214                types = op_match.group('types').strip() if op_match.group('types') else ''
215                strides = op_match.group('strides').strip() if op_match.group('strides') else ''
216                params = op_match.group('params').strip() if ('params' in op_match.groupdict() and op_match.group('params')) else ''
217            else:
218                op_match = None
219
220        if op_match:
221            cycles_start_raw = op_match.group('start')
222            unwrapped_cycles_start = None
223            if op_name == "OPBATCH":
224                if cycles_start_raw:
225                    unwrapped_cycles_start = int(cycles_start_raw)
226                    unwrappers[device] = CycleUnwrapper(unwrapped_cycles_start)
227                    last_batch_start[device] = unwrapped_cycles_start
228                    for k in list(trace_unwrappers.keys()):
229                        if k[0] == device:
230                            del trace_unwrappers[k]
231            else:
232                if cycles_start_raw:
233                    device_unwrapper = unwrappers.get(device)
234                    if device_unwrapper is not None:
235                        unwrapped_cycles_start = device_unwrapper.unwrap(int(cycles_start_raw))
236
237            op_text = re.sub(r"^profile-op\s+", "", line[idx:]).strip() if idx != -1 else line.strip()
238
239            evt_str = None
240            if types.startswith("evt-cnt "):
241                evt_str = types[8:].strip()
242
243            current_op = {
244                'name':         op_name,
245                'names':        names,
246                'dims':         dims,
247                'types':        types,
248                'strides':      strides,
249                'params':       params,
250                'evt':          evt_str,
251                'op_text':      op_text,
252                'usec':         int(op_match.group('usec')),
253                'cycles':       int(op_match.group('cycles')),
254                'cycles_start': int(cycles_start_raw) if cycles_start_raw else None,
255                'unwrapped_cycles_start': unwrapped_cycles_start,
256                'trace_events': [],
257                'line_num':     line_idx,
258                'device':       device
259            }
260            all_ops.append(current_op)
261
262            # Check if matching early exit criteria
263            matched = False
264            matched_target = None
265            if device_filter is not None:
266                targets = [t.strip() for t in device_filter.split(',')]
267                for target in targets:
268                    if device == target or device.startswith(target + ":"):
269                        matched = True
270                        matched_target = target
271                        break
272            else:
273                matched = True
274                matched_target = device
275
276            if op_filter_re is not None and not op_filter_re.search(op_text):
277                matched = False
278
279            if matched:
280                if matched_target not in ops_count_per_device:
281                    ops_count_per_device[matched_target] = 0
282                ops_count_per_device[matched_target] += 1
283
284            if limit is not None and len(ops_count_per_device) > 0 and all(count >= limit for count in ops_count_per_device.values()):
285                limit_reached = True
286
287            if limit_reached and op_name == "OPBATCH":
288                break
289            continue
290
291        trace_match = trace_pattern.search(line)
292        if trace_match:
293            thread = int(trace_match.group('thread'))
294            raw_cyc = int(trace_match.group('cycles'))
295            unwrapped_cyc = None
296            th_key = (device, thread)
297            if th_key not in trace_unwrappers:
298                batch_start = last_batch_start.get(device)
299                trace_unwrappers[th_key] = CycleUnwrapper(batch_start)
300            unwrapped_cyc = trace_unwrappers[th_key].unwrap(raw_cyc)
301            all_traces.append({
302                'thread': thread,
303                'event':  trace_match.group('event'),
304                'info':   int(trace_match.group('info')),
305                'cycles': raw_cyc,
306                'unwrapped_cycles': unwrapped_cyc,
307                'state':  trace_match.group('state'),
308                'line_num': line_idx,
309                'device': device
310            })
311
312    f.close()
313    return all_ops, all_traces
314
315# --- Simple protobuf encoder ---
316
317
318def write_varint(val):
319    if val < 0:
320        val = (1 << 64) + val
321    res = bytearray()
322    while True:
323        towrite = val & 0x7f
324        val >>= 7
325        if val > 0:
326            res.append(towrite | 0x80)
327        else:
328            res.append(towrite)
329            break
330    return bytes(res)
331
332
333def pb_field(num, wire, data):
334    return write_varint((num << 3) | wire) + data
335
336
337def pb_varint(num, val):
338    return pb_field(num, 0, write_varint(val))
339
340
341def pb_length_delimited(num, data):
342    return pb_field(num, 2, write_varint(len(data)) + data)
343
344
345def pb_string(num, text):
346    return pb_length_delimited(num, text.encode('utf-8'))
347
348
349# Message Encoders
350def make_process_descriptor(pid, name):
351    return pb_varint(1, pid) + pb_string(6, name)
352
353
354def make_thread_descriptor(pid, tid, name, sort_index=None):
355    payload = pb_varint(1, pid) + pb_varint(2, tid) + pb_string(5, name)
356    if sort_index is not None:
357        payload += pb_varint(3, sort_index)
358    return payload
359
360
361def make_track_descriptor(uuid, name=None, parent_uuid=None, thread=None, process=None, sibling_merge_behavior=None, child_ordering=None, sibling_order_rank=None):
362    payload = pb_varint(1, uuid)
363    if name is not None:
364        payload += pb_string(2, name)
365    if parent_uuid is not None:
366        payload += pb_varint(5, parent_uuid)
367    if process is not None:
368        payload += pb_length_delimited(3, process)
369    if thread is not None:
370        payload += pb_length_delimited(4, thread)
371    if sibling_merge_behavior is not None:
372        payload += pb_varint(15, sibling_merge_behavior)
373    if child_ordering is not None:
374        payload += pb_varint(11, child_ordering)
375    if sibling_order_rank is not None:
376        payload += pb_varint(12, sibling_order_rank)
377    return payload
378
379
380def make_debug_annotation(name, string_val=None, int_val=None):
381    payload = pb_string(10, name)
382    if string_val is not None:
383        payload += pb_string(6, string_val)
384    elif int_val is not None:
385        payload += pb_varint(4, int_val)
386    return payload
387
388
389def make_track_event(event_type, track_uuid, name=None, category=None, debug_annotations=None):
390    payload = pb_varint(9, event_type)
391    payload += pb_varint(11, track_uuid)
392    if name is not None:
393        payload += pb_string(23, name)
394    if category is not None:
395        payload += pb_string(22, category)
396    if debug_annotations is not None:
397        for da in debug_annotations:
398            payload += pb_length_delimited(4, da)
399    return payload
400
401
402def make_trace_packet(timestamp, track_event=None, track_descriptor=None, seq_id=1):
403    payload = pb_varint(8, timestamp)
404    payload += pb_varint(10, seq_id)
405    if track_event is not None:
406        payload += pb_length_delimited(11, track_event)
407    if track_descriptor is not None:
408        payload += pb_length_delimited(60, track_descriptor)
409    return payload
410
411
412def write_trace_packet_to_file(f, packet_bytes):
413    # Write as field 1 of top-level Trace message
414    f.write(pb_length_delimited(1, packet_bytes))
415
416# --- End Protobuf Encoder ---
417
418
419def generate_perfetto_trace(filtered_ops, trace_events, output_path):
420    if not filtered_ops:
421        logger.warning("No operators found after filtering.")
422        return
423
424    # Assign start and end cycles to each operator
425    for op in filtered_ops:
426        op['start_cycles'] = op['unwrapped_cycles_start']
427        op['end_cycles'] = op['start_cycles'] + op['cycles'] if op['start_cycles'] is not None else None
428
429    # Get list of unique devices present in the operations
430    unique_devices = sorted(list(set(op['device'] for op in filtered_ops)))
431    device_to_idx = {dev: idx for idx, dev in enumerate(unique_devices)}
432    time_mappers = {dev: DeviceTimeMapper(dev, filtered_ops) for dev in unique_devices}
433
434    # Process events
435    completed_events = []
436    if trace_events:
437        trace_events = sorted(trace_events, key=lambda e: e['unwrapped_cycles'])
438
439        one_usec_cycles = {}
440        for dev in unique_devices:
441            one_usec_cycles[dev] = max(time_mappers[dev].get_freq(), 1.0)
442
443        active_starts = {}
444        for e in trace_events:
445            t = e['thread']
446            evt = e['event']
447            info = e['info']
448            state = e['state']
449            cyc = e['unwrapped_cycles']
450            dev = e['device']
451
452            key = (dev, t, evt, info)
453            if state == 'start':
454                # Handle missing stop (start followed by another start)
455                if key in active_starts:
456                    prev_e = active_starts[key]
457                    completed_events.append({
458                        'thread': t,
459                        'event': evt,
460                        'info': info,
461                        'start_cyc': prev_e['unwrapped_cycles'],
462                        'end_cyc': prev_e['unwrapped_cycles'] + one_usec_cycles.get(dev, 1000.0),
463                        'line_num': prev_e.get('line_num'),
464                        'missing_stop': True,
465                        'device': dev
466                    })
467                active_starts[key] = e
468            elif state == 'stop':
469                if key in active_starts:
470                    prev_e = active_starts[key]
471                    del active_starts[key]
472                    completed_events.append({
473                        'thread': t,
474                        'event': evt,
475                        'info': info,
476                        'start_cyc': prev_e['unwrapped_cycles'],
477                        'end_cyc': cyc,
478                        'line_num': prev_e.get('line_num'),
479                        'device': dev
480                    })
481                else:
482                    # Handle missing start (stop without start)
483                    completed_events.append({
484                        'thread': t,
485                        'event': evt,
486                        'info': info,
487                        'start_cyc': cyc - one_usec_cycles.get(dev, 1000.0),
488                        'end_cyc': cyc,
489                        'line_num': e.get('line_num'),
490                        'missing_start': True,
491                        'device': dev
492                    })
493
494        # Clear remaining unmatched starts
495        for key, prev_e in active_starts.items():
496            dev, t, evt, info = key
497            completed_events.append({
498                'thread': t,
499                'event': evt,
500                'info': info,
501                'start_cyc': prev_e['unwrapped_cycles'],
502                'end_cyc': prev_e['unwrapped_cycles'] + one_usec_cycles.get(dev, 1000.0),
503                'line_num': prev_e.get('line_num'),
504                'missing_stop': True,
505                'device': dev
506            })
507
508    completed_events.sort(key=lambda e: e['start_cyc'])
509
510    # Convert event times to nanoseconds using per-device / per-batch time mapper
511    for e in completed_events:
512        dev = e['device']
513        tm = time_mappers[dev]
514        e['ts_ns'] = tm.cycle_to_ns(e['start_cyc'])
515        dur_ns = tm.dur_cycles_to_ns(e['start_cyc'], e['end_cyc'] - e['start_cyc'])
516        e['dur_ns'] = max(dur_ns, 100)
517
518    # Allocate slots (sub-tracks) to prevent overlaps on same virtual track
519    active_slots = defaultdict(list)
520    for e in completed_events:
521        t = e['thread']
522        evt = e['event']
523        ts = e['ts_ns']
524        dur = e['dur_ns']
525        dev = e['device']
526
527        norm_evt = normalize_event_name(evt, e['info'])
528        if norm_evt == "DMA":
529            track_key = (dev, t, "DMA")
530        elif t == 10:
531            track_key = (dev, t, "HMX")
532        else:
533            track_key = (dev, t, "HVX")
534
535        slots = active_slots[track_key]
536        allocated_slot = -1
537        for idx, slot_end_ns in enumerate(slots):
538            if ts >= slot_end_ns:
539                slots[idx] = ts + dur
540                allocated_slot = idx
541                break
542        if allocated_slot == -1:
543            slots.append(ts + dur)
544            allocated_slot = len(slots) - 1
545        e['slot'] = allocated_slot
546
547    # Generate Track IDs and track definitions
548    used_tracks = {}
549    for e in completed_events:
550        t = e['thread']
551        evt = e['event']
552        slot = e['slot']
553        dev = e['device']
554
555        norm_evt = normalize_event_name(evt, e['info'])
556        if norm_evt == "DMA":
557            track_evt = "DMA"
558            evt_id = 1
559        elif t == 10:
560            track_evt = "HMX"
561            evt_id = 3
562        else:
563            track_evt = "HVX"
564            evt_id = 2
565
566        t_sort = 1 if t == 10 else t + 2
567        dev_idx = device_to_idx[dev]
568
569        # Unique UUID for each sub-track
570        if t == 10:
571            uuid = dev_idx * 10000000 + 20  # HMX thread track UUID
572        else:
573            uuid = int(dev_idx * 10000000 + t_sort * 1000000 + evt_id * 1000 + slot)
574        e['uuid'] = uuid
575        used_tracks[uuid] = (dev, t, track_evt, slot)
576
577    with open(output_path, "wb") as f:
578        for dev in unique_devices:
579            dev_idx = device_to_idx[dev]
580            pid = dev_idx + 1
581            proc_uuid = dev_idx * 10000000 + 1
582
583            # Define Process with EXPLICIT child sorting
584            proc_name = dev
585            proc_desc = make_process_descriptor(pid, proc_name)
586            proc_packet = make_trace_packet(0, track_descriptor=make_track_descriptor(proc_uuid, process=proc_desc, child_ordering=3))
587            write_trace_packet_to_file(f, proc_packet)
588
589            # Define Operators Track as a thread track
590            op_track_uuid = dev_idx * 10000000 + 2
591            op_tid = pid * 100 + 8
592            op_thread_desc = make_thread_descriptor(pid, op_tid, "Ops", sort_index=1)
593            op_packet = make_trace_packet(0, track_descriptor=make_track_descriptor(op_track_uuid, parent_uuid=proc_uuid, thread=op_thread_desc))
594            write_trace_packet_to_file(f, op_packet)
595
596            # Define HMX Thread Track at rank 2
597            hmx_track_uuid = dev_idx * 10000000 + 20
598            hmx_tid = pid * 100 + 9
599            hmx_thread_desc = make_thread_descriptor(pid, hmx_tid, "HMX", sort_index=2)
600            hmx_packet = make_trace_packet(0, track_descriptor=make_track_descriptor(hmx_track_uuid, parent_uuid=proc_uuid, thread=hmx_thread_desc))
601            write_trace_packet_to_file(f, hmx_packet)
602
603            # Define Thread Tracks (T0, T1, ..., T9) for this device
604            dev_used_tracks = {uuid: val for uuid, val in used_tracks.items() if val[0] == dev}
605            unique_threads = sorted(list(set(t for (_, t, _, _) in dev_used_tracks.values() if t != 10)))
606            for t in unique_threads:
607                thread_uuid = dev_idx * 10000000 + 10 + t
608                thread_name = f"T{t}"
609                sort_index = 3 + t
610                tid = pid * 100 + 10 + t
611                thread_desc = make_thread_descriptor(pid, tid, thread_name, sort_index=sort_index)
612                thread_packet = make_trace_packet(0, track_descriptor=make_track_descriptor(
613                    thread_uuid,
614                    parent_uuid=proc_uuid,
615                    thread=thread_desc,
616                    sibling_order_rank=sort_index,
617                    child_ordering=3  # Explicit child sorting for sub-tracks
618                ))
619                write_trace_packet_to_file(f, thread_packet)
620
621        # Define Track descriptors for sub-tracks parented to thread tracks
622        for uuid in sorted(used_tracks.keys()):
623            dev, t, evt, slot = used_tracks[uuid]
624            dev_idx = device_to_idx[dev]
625            if t == 10:
626                continue
627            name = f"T{t} {evt}"
628            rank = 0 if evt == "HVX" else 1
629            parent_thread_uuid = dev_idx * 10000000 + 10 + t
630            # Sibling merge behavior: 1 (SIBLING_MERGE_BEHAVIOR_BY_TRACK_NAME)
631            track_desc = make_track_descriptor(
632                uuid=uuid,
633                name=name,
634                parent_uuid=parent_thread_uuid,
635                sibling_merge_behavior=1,
636                sibling_order_rank=rank
637            )
638            track_packet = make_trace_packet(0, track_descriptor=track_desc)
639            write_trace_packet_to_file(f, track_packet)
640
641        # Emit Operators
642        last_op_end_ns = defaultdict(int)
643        for op in filtered_ops:
644            dev = op['device']
645            dev_idx = device_to_idx[dev]
646            tm = time_mappers[dev]
647            op_start_ns = tm.cycle_to_ns(op['start_cycles'])
648            op_dur_ns = tm.dur_cycles_to_ns(op['start_cycles'], op['cycles'])
649            if op['name'] != "OPBATCH":
650                if op_start_ns < last_op_end_ns[dev]:
651                    op_start_ns = last_op_end_ns[dev]
652                clamped_dur = max(op_dur_ns, 100) # Clamp to 100ns (0.1us)
653                last_op_end_ns[dev] = op_start_ns + clamped_dur
654            else:
655                clamped_dur = max(op_dur_ns, 100)
656
657            # Debug annotations for Ops
658            debug_annots = []
659            if 'line_num' in op:
660                debug_annots.append(make_debug_annotation("line", int_val=op['line_num']))
661            if 'names' in op and op['names'] and op['names'] != '----':
662                debug_annots.append(make_debug_annotation("names", string_val=op['names']))
663            if 'strides' in op and op['strides'] and op['strides'] != '----':
664                debug_annots.append(make_debug_annotation("strides", string_val=op['strides']))
665            if 'params' in op and op['params'] and op['params'] != '----':
666                debug_annots.append(make_debug_annotation("params", string_val=op['params']))
667            if 'evt' in op and op['evt']:
668                debug_annots.append(make_debug_annotation("evt", string_val=op['evt']))
669
670            op_track_uuid = dev_idx * 10000000 + 2
671
672            # Slice Begin
673            evt_begin = make_track_event(1, op_track_uuid, name=f"{op['name']} ({op['dims']})", category="operator", debug_annotations=debug_annots)
674            packet_begin = make_trace_packet(op_start_ns, track_event=evt_begin)
675            write_trace_packet_to_file(f, packet_begin)
676
677            # Slice End
678            evt_end = make_track_event(2, op_track_uuid)
679            packet_end = make_trace_packet(op_start_ns + clamped_dur, track_event=evt_end)
680            write_trace_packet_to_file(f, packet_end)
681
682        # Emit Thread Trace Events
683        for e in completed_events:
684            norm_name = normalize_event_name(e['event'], e['info'])
685            if norm_name == "DMA":
686                name = f"DMA {e['info']}"
687            elif norm_name == "FENCE":
688                name = f"FENCE {e['info']}" if e.get('info') is not None and e['info'] != 0 else "FENCE"
689            else:
690                name = norm_name
691
692            if e.get('missing_start') or e.get('missing_stop'):
693                name += "!"
694
695            debug_annots = []
696            if 'line_num' in e and e['line_num'] is not None:
697                debug_annots.append(make_debug_annotation("line", int_val=e['line_num']))
698            if norm_name == "FENCE" and e.get('info') is not None:
699                debug_annots.append(make_debug_annotation("seq", int_val=e['info']))
700            elif norm_name == "DMA" and e.get('info') is not None:
701                debug_annots.append(make_debug_annotation("channel", int_val=e['info']))
702            elif e.get('info') is not None and e['info'] != 0:
703                debug_annots.append(make_debug_annotation("info", int_val=e['info']))
704
705            if e.get('missing_start'):
706                debug_annots.append(make_debug_annotation("missing_start", string_val="true"))
707            if e.get('missing_stop'):
708                debug_annots.append(make_debug_annotation("missing_stop", string_val="true"))
709
710            # Slice Begin
711            evt_begin = make_track_event(1, e['uuid'], name=name, category="trace", debug_annotations=debug_annots if debug_annots else None)
712            packet_begin = make_trace_packet(e['ts_ns'], track_event=evt_begin)
713            write_trace_packet_to_file(f, packet_begin)
714
715            # Slice End
716            evt_end = make_track_event(2, e['uuid'])
717            packet_end = make_trace_packet(e['ts_ns'] + e['dur_ns'], track_event=evt_end)
718            write_trace_packet_to_file(f, packet_end)
719
720    logger.info(f"Successfully generated Perfetto trace at {output_path}")
721
722
723def main():
724    parser = argparse.ArgumentParser(description="Convert Hexagon Op profile logs to native Perfetto Protobuf traces.")
725    parser.add_argument("logfile", help="Path to hex-log profile file")
726    parser.add_argument("-o", "--output", default="optrace.perfetto-trace", help="Output trace file path (default: optrace.perfetto-trace)")
727    parser.add_argument("--filter", type=str, help="Regex filter matching against the original profile-op line")
728    parser.add_argument("--device", type=str, help="Device to filter by (e.g. HTP0, HTP0:0) or 'split' to generate separate files per device")
729
730    group = parser.add_mutually_exclusive_group()
731    group.add_argument("--head", type=int, help="Limit to first N ops")
732    group.add_argument("--tail", type=int, help="Limit to last N ops")
733
734    args = parser.parse_args()
735    logging.basicConfig(level=logging.INFO, format='%(message)s')
736
737    op_filter_re = None
738    if args.filter:
739        try:
740            op_filter_re = re.compile(args.filter)
741        except re.error as e:
742            logger.error(f"Invalid regex filter: {e}")
743            sys.exit(1)
744
745    limit = args.head if args.head is not None else None
746    device_filter = args.device if (args.device and args.device != "split") else None
747    ops, traces = parse_log(args.logfile, limit=limit, device_filter=device_filter, op_filter_re=op_filter_re)
748
749    if args.device and args.device != "split":
750        ops = [op for op in ops if device_matches(op['device'], args.device)]
751        traces = [t for t in traces if device_matches(t['device'], args.device)]
752
753    if args.filter:
754        try:
755            filter_re = re.compile(args.filter)
756        except re.error as e:
757            logger.error(f"Invalid regex filter: {e}")
758            sys.exit(1)
759        ops = [op for op in ops if filter_re.search(op['op_text'])]
760
761    if args.head is not None or args.tail is not None:
762        ops_by_dev = defaultdict(list)
763        for op in ops:
764            ops_by_dev[op['device']].append(op)
765
766        filtered_ops = []
767        for dev in sorted(ops_by_dev.keys()):
768            dev_ops = ops_by_dev[dev]
769            if args.head is not None:
770                dev_ops = dev_ops[:args.head]
771            elif args.tail is not None:
772                dev_ops = dev_ops[-args.tail:]
773            filtered_ops.extend(dev_ops)
774        ops = filtered_ops
775
776    if args.filter or args.head is not None or args.tail is not None:
777        # Group valid ranges by device
778        valid_ranges_by_dev = defaultdict(list)
779        for op in ops:
780            start_cyc = op['unwrapped_cycles_start']
781            end_cyc = start_cyc + op['cycles'] if start_cyc is not None else None
782            if start_cyc is not None and end_cyc is not None:
783                valid_ranges_by_dev[op['device']].append((start_cyc, end_cyc))
784
785        for dev in valid_ranges_by_dev:
786            valid_ranges_by_dev[dev].sort(key=lambda r: r[0])
787
788        range_starts_by_dev = {dev: [r[0] for r in ranges] for dev, ranges in valid_ranges_by_dev.items()}
789
790        filtered_traces = []
791        for e in traces:
792            cyc = e['unwrapped_cycles']
793            if cyc is None:
794                continue
795            dev = e['device']
796            range_starts = range_starts_by_dev.get(dev)
797            if not range_starts:
798                continue
799            idx = bisect.bisect_right(range_starts, cyc) - 1
800            if idx >= 0:
801                start, end = valid_ranges_by_dev[dev][idx]
802                if start <= cyc <= end:
803                    filtered_traces.append(e)
804        traces = filtered_traces
805
806    if args.device == "split":
807        unique_devices = sorted(list(set(op['device'] for op in ops)))
808        for dev in unique_devices:
809            dev_ops = [op for op in ops if device_matches(op['device'], dev)]
810            dev_traces = [t for t in traces if device_matches(t['device'], dev)]
811            out_path = get_split_output_path(args.output, dev)
812            generate_perfetto_trace(dev_ops, dev_traces, out_path)
813    else:
814        generate_perfetto_trace(ops, traces, args.output)
815
816
817if __name__ == "__main__":
818    main()