1#!/usr/bin/env python3
2
3# © 2021 Qualcomm Innovation Center, Inc. All rights reserved.
4#
5# SPDX-License-Identifier: BSD-3-Clause
6
7"""
8Convert a trace buffer binary file to text form.
9"""
10
11import os
12import struct
13import argparse
14import sys
15import tempfile
16import subprocess
17import itertools
18import math
19
20
21MAP_ID = 0x14
22UNMAP_ID = 0x15
23
24TRACE_FORMAT = 1
25
26TRACE_IDS = {
27    0: "INFO",
28    1: "WARN",
29    2: "HYPERCALL",
30    3: "DEBUG",
31    10: "PANIC",
32    11: "ASSERT_FAILED",
33    32: "VGIC_VIRQ_CHANGED",
34    33: "VGIC_DSTATE_CHANGED",
35    34: "VGIC_HWSTATE_CHANGED",
36    35: "VGIC_HWSTATE_UNCHANGED",
37    36: "VGIC_GICD_WRITE",
38    37: "VGIC_GICR_WRITE",
39    38: "VGIC_SGI",
40    39: "VGIC_ITS_COMMAND",
41    40: "VGIC_ROUTE",
42    41: "VGIC_ICC_WRITE",
43    42: "VGIC_ASYNC_EVENT",
44    48: "PSCI_PSTATE_VALIDATION",
45    49: "PSCI_VPM_STATE_CHANGED",
46    50: "PSCI_VPM_SYSTEM_SUSPEND",
47    51: "PSCI_VPM_SYSTEM_RESUME",
48    52: "PSCI_VPM_VCPU_SUSPEND",
49    53: "PSCI_VPM_VCPU_RESUME",
50    54: "PSCI_SYSTEM_SUSPEND",
51    55: "PSCI_SYSTEM_RESUME",
52    128: "WAIT_QUEUE_RESERVE",
53    129: "WAIT_QUEUE_WAKE",
54    130: "WAIT_QUEUE_WAKE_ACK",
55    131: "WAIT_QUEUE_SLEEP",
56    132: "WAIT_QUEUE_RESUME",
57    133: "WAIT_QUEUE_FREE",
58}
59
60
61def main():
62    parser = argparse.ArgumentParser()
63    parser.add_argument("input", nargs='?', type=argparse.FileType('rb'),
64                        default=sys.stdin.buffer, help="Trace binary file")
65    image_args = parser.add_mutually_exclusive_group()
66    image_args.add_argument("--elf", '-e', type=argparse.FileType('rb'),
67                            help="ELF image")
68    image_args.add_argument("--binary", '-b', type=argparse.FileType('rb'),
69                            help="Binary hypervisor image")
70    timestamp_args = parser.add_mutually_exclusive_group()
71    timestamp_args.add_argument("--freq", '-f', type=int, default=19200000,
72                                help="Timer frequency in Hz")
73    timestamp_args.add_argument("--ticks", '-t', action="store_true",
74                                help="Show time in ticks instead of seconds")
75    parser.add_argument('-T', "--time-offset", default=0, type=float,
76                        help="Offset to subtract from displayed timestamps"
77                        " (in the same units as the timestamp)")
78    format_args = parser.add_mutually_exclusive_group()
79    format_args.add_argument('-s', "--sort", action="store_const",
80                             dest='sort', const='s',
81                             help="Sort entries by timestamp")
82    format_args.add_argument('-r', "--raw", action="store_const",
83                             dest='sort', const='u',
84                             help="Entries as positioned in trace ring buffer")
85    format_args.add_argument('-m', "--merge", action="store_const",
86                             dest='sort', const='m',
87                             help="Entries merged and sorted by timestamp")
88    parser.add_argument("--show-missing", action="store_true",
89                        help="Mark invalid or overwritten log entries")
90    parser.add_argument('-o', "--output", default=sys.stdout,
91                        type=argparse.FileType('w', encoding='utf-8'),
92                        help="Output text file")
93    parser.set_defaults(sort='s')
94    args = parser.parse_args()
95
96    global image
97    image = ()
98    if args.elf is not None:
99        with tempfile.TemporaryDirectory() as tmpdir:
100            binfile = os.path.join(tmpdir, 'hyp.bin')
101            try:
102                objcopy = os.path.join(os.environ['LLVM'], 'bin',
103                                       'llvm-objcopy')
104            except KeyError:
105                try:
106                    objcopy = os.path.join(os.environ['QCOM_LLVM'], 'bin',
107                                           'llvm-objcopy')
108                except KeyError:
109                    print("Error environment var LLVM or QCOM_LLVM not set")
110                    pass
111
112            subprocess.check_call([objcopy, '-j', '.text',
113                                   '-j', '.rodata', '-O', 'binary',
114                                   args.elf.name, binfile])
115            with open(binfile, 'rb') as binfile:
116                image = binfile.read()
117    elif args.binary is not None:
118        image = args.binary.read()
119
120    entry_iter = read_all_entries(args)
121    log = prepare_log(args, entry_iter)
122    print_log(args, log)
123
124
125class Arg(int):
126
127    __cache = {}
128
129    def __new__(cls, value, strict=False):
130        if value in Arg.__cache:
131            return Arg.__cache[value]
132        self = super().__new__(cls, value)
133        self.__strict = strict
134        Arg.__cache[value] = self
135        self.__str = self.__gen_str()
136        return self
137
138    def __format__(self, format_spec):
139        if format_spec.endswith('s'):
140            return str(self).__format__(format_spec)
141        return super().__format__(format_spec)
142
143    def __gen_str(self):
144        try:
145            bs = bytearray()
146            assert (self & 0x1fffff) < len(image)
147            for i in range((self & 0x1fffff), len(image)):
148                b = image[i]
149                if b == 0:
150                    break
151                bs.append(b)
152                if len(bs) > 512:
153                    break
154            return bs.decode('utf-8')
155        except Exception:
156            if self.__strict:
157                raise
158            return '<str:{:#x}>'.format(self)
159
160    def __str__(self):
161        return self.__str
162
163
164class LogEntry:
165    def __init__(self, ticks, cpu_id, string=''):
166        self.ticks = ticks
167        self.cpu_id = cpu_id
168        self.__str = string
169
170    def __str__(self):
171        return self.__str
172
173    def set_string(self, string):
174        self.__str = string
175
176
177class Event(LogEntry):
178
179    __slots__ = ('ticks', 'trace_id', 'trace_ids', 'cpu_id', 'missing_before',
180                 'missing_after', '__str')
181
182    def __init__(self, args, info, tag, fmt_ptr, arg0, arg1, arg2, arg3, arg4):
183        if info == 0:
184            # Empty trace slot
185            raise ValueError("empty slot")
186
187        ticks = info & ((1 << 56) - 1)
188        cpu_id = info >> 56
189
190        super().__init__(ticks, cpu_id)
191
192        self.trace_id = tag & 0xffff
193
194        if TRACE_FORMAT == 1:
195            self.trace_ids = (tag >> 16) & 0xffffffff
196            vmid = self.trace_ids & 0xffff
197            vcpu = (self.trace_ids >> 16) & 0xffff
198            caller_id = '{:#04x}:{:#02d}'.format(vmid, vcpu)
199        else:
200            self.trace_ids = 0
201            caller_id = ''
202
203        if self.trace_id in TRACE_IDS:
204            trace_id = TRACE_IDS[self.trace_id]
205        else:
206            trace_id = '{:#06x}'.format(self.trace_id)
207
208        # Try to obtain a C string at the given offset
209        try:
210            fmt = str(Arg(fmt_ptr, strict=True))
211        except Exception:
212            fmt = "? fmt_ptr {:#x}".format(fmt_ptr) + \
213                " args {:#x} {:#x} {:#x} {:#x} {:#x}"
214
215        # Try to format the args using the given format string
216        try:
217            msg = fmt.format(Arg(arg0), Arg(arg1), Arg(arg2), Arg(arg3),
218                             Arg(arg4))
219        except Exception:
220            msg = ("? fmt_str {:s} args {:#x} {:#x} {:#x} {:#x} {:#x}"
221                   .format(fmt, arg0, arg1, arg2, arg3, arg4))
222
223        if args.ticks:
224            rel_time = int(self.ticks - args.time_offset)
225            abs_time = int(self.ticks)
226            if args.time_offset:
227                ts_str = "[{:12d}/{:12d}]".format(rel_time, abs_time)
228            else:
229                ts_str = "[{:12d}]".format(abs_time)
230
231        else:
232            rel_time = (float(self.ticks) / args.freq) - args.time_offset
233            abs_time = float(self.ticks) / args.freq
234            if args.time_offset:
235                ts_str = "[{:12.6f}/{:12.6f}]".format(rel_time, abs_time)
236            else:
237                ts_str = "[{:12.6f}]".format(abs_time)
238
239        self.set_string("{:s} <{:d}> {:s} {:s} {:s}\n".format(
240            ts_str, self.cpu_id, caller_id, trace_id, msg))
241
242        self.missing_before = False
243        self.missing_after = False
244
245
246def read_entries(args):
247    header = args.input.read(64)
248    if not header or (len(header) < 64):
249        # Reached end of file
250        if header:
251            print("<skipped trailing bytes>\n")
252        raise StopIteration
253
254    magic = struct.unpack('<L', header[:4])[0]
255    if magic == 0x46554236:  # 6BUF
256        endian = '<'
257    elif magic == 0x36425568:  # FUB6
258        endian = '>'
259    else:
260        print("Unexpected magic number {:#x}".format(magic))
261        raise StopIteration
262
263    cpu_mask = struct.unpack(endian + 'QQQQ', header[8:40])
264
265    cpu_mask = cpu_mask[0] | (cpu_mask[1] << 64) | (cpu_mask[2] << 128) | \
266        (cpu_mask[2] << 192)
267    global_buffer = cpu_mask == 0
268
269    cpus = ''
270    while cpu_mask != 0:
271        msb = cpu_mask.bit_length() - 1
272        cpus += '{:d}'.format(msb)
273        cpu_mask &= ~(1 << msb)
274        if cpu_mask != 0:
275            cpus += ','
276
277    if global_buffer:
278        print("Processing global buffer...")
279    else:
280        print("Processing CPU {:s} buffer...".format(cpus))
281
282    entries_max = struct.unpack(endian + 'L', header[4:8])[0]
283    head_index = struct.unpack(endian + 'L', header[40:44])[0]
284
285    # Check if this buffer has wrapped around. Since the older traces that
286    # don't implement this flag will read it as zero, to stay backwards
287    # compatible, we decode a 0 as "wrapped" and 1 as "unwrapped".
288    wrapped = True if header[44:45] == b'\x00' else False
289    # If wrapped around or old format, read the whole buffer, otherwise only
290    # read the valid entries
291    entry_count = entries_max if wrapped else head_index
292
293    if entry_count == 0:
294        # Empty buffer, skip over the unused bytes
295        print("  Empty buffer")
296        args.input.seek(entries_max * 64, 1)
297        return iter(())
298    else:
299        print("  Found {:d} entries. Wrapped: {}".format(entry_count, wrapped))
300
301    warn = True
302    entries = []
303    for i in range(entry_count):
304        trace = args.input.read(64)
305        if len(trace) < 64:
306            print("  Warning, log truncated. Read {:d} of {:d} entries".format(
307                i, entry_count))
308            break
309        try:
310            entries.append(Event(args, *struct.unpack(endian + "QQQQQQQQ",
311                                                      trace)))
312        except ValueError:
313            if warn:
314                print("  Warning, bad input. Read {:d} of {:d} entries".format(
315                    i, entry_count))
316                warn = False
317            pass
318
319    if args.sort == 'm':
320        if global_buffer:
321            header_string = "=== GLOBAL TRACES START ===\n"
322        else:
323            header_string = "=== CPU {:s} TRACES START ===\n".format(cpus)
324    else:
325        if global_buffer:
326            header_string = "=== GLOBAL TRACE ===\n"
327        else:
328            header_string = "=== CPU {:s} TRACE ===\n".format(cpus)
329
330    if not wrapped or (head_index == entries_max):
331        first_index = 0
332    else:
333        first_index = head_index
334
335    # Add the same timestamp as the first entry
336    entry_header = LogEntry(entries[first_index].ticks, 0, header_string)
337
338    if args.sort == 's':
339        # Split at the head index
340        entry_iter = itertools.chain(
341            [entry_header], entries[head_index:], entries[:head_index])
342    else:
343        entry_iter = itertools.chain([entry_header], entries)
344
345    if not wrapped:
346        # Skip over the unused bytes
347        if args.input.seekable():
348            args.input.seek((entries_max - head_index) * 64, 1)
349        else:
350            args.input.read((entries_max - head_index) * 64)
351
352    return entry_iter
353
354
355def read_all_entries(args):
356    def entry_iters():
357        if args.sort == 'm':
358            yield [LogEntry(0, 0, "==== MERGED CPU AND GLOBAL TRACES ====\n")]
359
360        while True:
361            try:
362                yield read_entries(args)
363            except StopIteration:
364                break
365
366    return itertools.chain(*entry_iters())
367
368
369def prepare_log(args, entry_iter):
370    if args.show_missing:
371        # Simple search for missing entries: look for either an invalid info
372        # field, or a timestamp jumping backwards.
373        #
374        # If the timestamp jumps backwards by less than 10 ticks, we assume
375        # that it was an out-of-order trace write due to a race to obtain a
376        # slot. This typically suppresses several false positives in any large
377        # trace buffer.
378        timestamp_slack = 10
379        last_timestamp = -math.inf
380        missing_entry = False
381        log = []
382        for entry in entry_iter:
383            if entry is None:
384                missing_entry = True
385                if log:
386                    log[-1].missing_after = True
387            else:
388                if missing_entry:
389                    entry.missing_before = True
390                    missing_entry = False
391
392                timestamp = entry.ticks
393                if timestamp + timestamp_slack < last_timestamp:
394                    entry.missing_before = True
395                    if log:
396                        log[-1].missing_after = True
397
398                last_timestamp = timestamp
399                log.append(entry)
400    else:
401        log = list(entry_iter)
402
403    if args.sort == 'm':
404        log = sorted(log, key=lambda e: e.ticks)
405
406    if len(log) == 0:
407        sys.exit(1)
408
409    return log
410
411
412def print_log(args, log):
413    prev_entry = None
414    for entry in log:
415        if args.show_missing and (prev_entry is not None and (
416                entry.missing_before or prev_entry.missing_after)):
417            args.output.write("<possible missing entries>\n")
418        args.output.write(str(entry))
419        prev_entry = entry
420
421
422if __name__ == "__main__":
423    main()
424