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 <anas.nashif@intel.com>
diff --git a/scripts/tracing/parse_ctf.py b/scripts/tracing/parse_ctf.py
new file mode 100644
index 0000000..5b52bff
--- /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()
