From 5ab117ffd2624068f8643982442b5f324eb0dc11 Mon Sep 17 00:00:00 2001 From: Anas Nashif Date: Thu, 20 Aug 2020 16:19:08 -0400 Subject: [PATCH] tracing: scripts: add scripts for parsing ctf data Generate trace using samples/subsys/tracing for example: west build -b qemu_x86 samples/subsys/tracing -t run \ -- -DCONF_FILE=prj_uart_ctf.conf mkdir ctf cp build/channel0_0 ctf/ cp subsys/tracing/ctf/tsdl/metadata ctf/ ./scripts/tracing/parse_ctf.py -t ctf 1969-12-31 19:00:00.001779 (+0.000000 s): thread_create: thread_a 1969-12-31 19:00:00.001915 (+0.000136 s): thread_info (Stack size: 1024) 1969-12-31 19:00:00.002021 (+0.000107 s): thread_ready: thread_a 1969-12-31 19:00:00.002287 (+0.000265 s): thread_switched_out: main 1969-12-31 19:00:00.002320 (+0.000033 s): thread_switched_in: main 1969-12-31 19:00:00.002585 (+0.000265 s): thread_abort: main 1969-12-31 19:00:00.002730 (+0.000145 s): thread_switched_out: main 1969-12-31 19:00:00.002762 (+0.000032 s): thread_switched_in: thread_a 1969-12-31 19:00:00.002829 (+0.000067 s): thread_create: 1130656 1969-12-31 19:00:00.002860 (+0.000031 s): thread_info (Stack size: 1024) 1969-12-31 19:00:00.002911 (+0.000052 s): thread_ready: 1130656 1969-12-31 19:00:00.003033 (+0.000121 s): thread_name_set 1969-12-31 19:00:00.003132 (+0.000100 s): semaphore_take (1140992) 1969-12-31 19:00:00.003201 (+0.000069 s): end_call 38 (SEMA_TAKE) 1969-12-31 19:00:00.003330 (+0.000128 s): start_call 39 (SLEEP) 1969-12-31 19:00:00.003721 (+0.000391 s): thread_suspend: thread_a 1969-12-31 19:00:00.003802 (+0.000081 s): thread_switched_out: thread_a 1969-12-31 19:00:00.003834 (+0.000032 s): thread_switched_in: thread_b 1969-12-31 19:00:00.003872 (+0.000038 s): semaphore_take (1141016) 1969-12-31 19:00:00.003976 (+0.000103 s): thread_pending: thread_b 1969-12-31 19:00:00.004095 (+0.000119 s): thread_switched_out: thread_b 1969-12-31 19:00:00.004127 (+0.000032 s): thread_switched_in: idle 00 1969-12-31 19:00:00.004232 (+0.000105 s): idle 1969-12-31 19:00:00.510848 (+0.506616 s): isr_enter 1969-12-31 19:00:00.511664 (+0.000816 s): thread_resume: thread_a 1969-12-31 19:00:00.511947 (+0.000283 s): thread_ready: thread_a 1969-12-31 19:00:00.512385 (+0.000438 s): isr_exit 1969-12-31 19:00:00.512570 (+0.000186 s): thread_switched_out: idle 00 1969-12-31 19:00:00.512689 (+0.000119 s): thread_switched_in: thread_a 1969-12-31 19:00:00.512869 (+0.000180 s): end_call 39 (SLEEP) Signed-off-by: Anas Nashif --- scripts/tracing/parse_ctf.py | 142 +++++++++++++++++++++++++++++++++++ 1 file changed, 142 insertions(+) create mode 100644 scripts/tracing/parse_ctf.py diff --git a/scripts/tracing/parse_ctf.py b/scripts/tracing/parse_ctf.py new file mode 100644 index 00000000000..5b52bffa332 --- /dev/null +++ b/scripts/tracing/parse_ctf.py @@ -0,0 +1,142 @@ +#!/usr/bin/env python3 +# +# Copyright (c) 2020 Intel Corporation. +# +# SPDX-License-Identifier: Apache-2.0 +""" +Script to parse CTF data and print to the screen in a custom and colorful +format. + +Generate trace using samples/subsys/tracing for example: + + west build -b qemu_x86 samples/subsys/tracing -t run \ + -- -DCONF_FILE=prj_uart_ctf.conf + + mkdir ctf + cp build/channel0_0 ctf/ + cp subsys/tracing/ctf/tsdl/metadata ctf/ + ./scripts/tracing/parse_ctf.py -t ctf +""" + +import sys +import datetime +from colorama import Fore +import argparse +try: + import bt2 +except ImportError: + sys.exit("Missing dependency: You need to install python bindings of babletrace.") + +def parse_args(): + parser = argparse.ArgumentParser( + description=__doc__, + formatter_class=argparse.RawDescriptionHelpFormatter) + parser.add_argument("-t", "--trace", + required=True, + help="tracing data (directory with metadata and trace file)") + args = parser.parse_args() + return args + +def main(): + args = parse_args() + + msg_it = bt2.TraceCollectionMessageIterator(args.trace) + last_event_ns_from_origin = None + timeline = [] + + def get_thread(name): + for t in timeline: + if t.get('name', None) == name and t.get('in', 0 ) != 0 and not t.get('out', None): + return t + return {} + + for msg in msg_it: + + if not isinstance(msg, bt2._EventMessageConst): + continue + + ns_from_origin = msg.default_clock_snapshot.ns_from_origin + event = msg.event + # Compute the time difference since the last event message. + diff_s = 0 + + if last_event_ns_from_origin is not None: + diff_s = (ns_from_origin - last_event_ns_from_origin) / 1e9 + + dt = datetime.datetime.fromtimestamp(ns_from_origin / 1e9) + + if event.name in [ + 'thread_switched_out', + 'thread_switched_in', + 'thread_pending', + 'thread_ready', + 'thread_resume', + 'thread_suspend', + 'thread_create', + 'thread_abort' + ]: + + cpu = event.payload_field.get("cpu", None) + thread_id = event.payload_field.get("thread_id", None) + thread_name = event.payload_field.get("name", None) + + th = {} + if event.name in ['thread_switched_out', 'thread_switched_in'] and cpu is not None: + cpu_string = f"(cpu: {cpu})" + else: + cpu_string = "" + + if thread_name: + print(f"{dt} (+{diff_s:.6f} s): {event.name}: {thread_name} {cpu_string}") + elif thread_id: + print(f"{dt} (+{diff_s:.6f} s): {event.name}: {thread_id} {cpu_string}") + else: + print(f"{dt} (+{diff_s:.6f} s): {event.name}") + + if event.name in ['thread_switched_out', 'thread_switched_in']: + if thread_name: + th = get_thread(thread_name) + if not th: + th['name'] = thread_name + else: + th = get_thread(thread_id) + if not th: + th['name'] = thread_id + + if event.name in ['thread_switched_out']: + th['out'] = ns_from_origin + tin = th.get('in', None) + tout = th.get('out', None) + if tout is not None and tin is not None: + diff = (tout - tin) + th['runtime'] = diff + elif event.name in ['thread_switched_in']: + th['in'] = ns_from_origin + + timeline.append(th) + + elif event.name in ['thread_info']: + stack_size = event.payload_field['stack_size'] + print(f"{dt} (+{diff_s:.6f} s): {event.name} (Stack size: {stack_size})") + elif event.name in ['start_call', 'end_call']: + if event.payload_field['id'] == 39: + c = Fore.GREEN + elif event.payload_field['id'] in [37, 38]: + c = Fore.CYAN + else: + c = Fore.YELLOW + print(c + f"{dt} (+{diff_s:.6f} s): {event.name} {event.payload_field['id']}" + Fore.RESET) + elif event.name in ['semaphore_init', 'semaphore_take', 'semaphore_give']: + c = Fore.CYAN + print(c + f"{dt} (+{diff_s:.6f} s): {event.name} ({event.payload_field['id']})" + Fore.RESET) + elif event.name in ['mutex_init', 'mutex_take', 'mutex_give']: + c = Fore.MAGENTA + print(c + f"{dt} (+{diff_s:.6f} s): {event.name} ({event.payload_field['id']})" + Fore.RESET) + + else: + print(f"{dt} (+{diff_s:.6f} s): {event.name}") + + last_event_ns_from_origin = ns_from_origin + +if __name__=="__main__": + main()