From ec691cc5e4f3876a0267f140216d8bba97f5aa9c Mon Sep 17 00:00:00 2001 From: yinshengkai Date: Sun, 24 Dec 2023 23:44:46 +0800 Subject: [PATCH] tools: prasetrace.py supports parsing syslog Signed-off-by: yinshengkai --- drivers/note/note_driver.c | 7 +- include/nuttx/sched_note.h | 2 - tools/parsetrace.py | 426 +++++++++++++++++++++++++++++++++---- 3 files changed, 383 insertions(+), 52 deletions(-) diff --git a/drivers/note/note_driver.c b/drivers/note/note_driver.c index ced795ec4d..f9bed9bee1 100644 --- a/drivers/note/note_driver.c +++ b/drivers/note/note_driver.c @@ -239,21 +239,16 @@ static void note_common(FAR struct tcb_s *tcb, note->nc_length = length; note->nc_type = type; + note->nc_cpu = this_cpu(); if (tcb == NULL) { note->nc_priority = CONFIG_INIT_PRIORITY; -#ifdef CONFIG_SMP - note->nc_cpu = 0; -#endif note->nc_pid = 0; } else { note->nc_priority = tcb->sched_priority; -#ifdef CONFIG_SMP - note->nc_cpu = tcb->cpu; -#endif note->nc_pid = tcb->pid; } diff --git a/include/nuttx/sched_note.h b/include/nuttx/sched_note.h index 959efc6bbf..44cad9b739 100644 --- a/include/nuttx/sched_note.h +++ b/include/nuttx/sched_note.h @@ -318,9 +318,7 @@ struct note_common_s uint8_t nc_length; /* Length of the note */ uint8_t nc_type; /* See enum note_type_e */ uint8_t nc_priority; /* Thread/task priority */ -#ifdef CONFIG_SMP uint8_t nc_cpu; /* CPU thread/task running on */ -#endif pid_t nc_pid; /* ID of the thread/task */ /* Time when note was buffered (sec) */ diff --git a/tools/parsetrace.py b/tools/parsetrace.py index bb2899a6ae..3c758e4bc1 100755 --- a/tools/parsetrace.py +++ b/tools/parsetrace.py @@ -23,14 +23,18 @@ import argparse import bisect +import logging import os import re +import struct import subprocess from typing import Union try: + import colorlog import cxxfilt import parse + import serial from elftools.elf.elffile import ELFFile from elftools.elf.sections import SymbolTableSection from pycstruct import pycstruct @@ -38,16 +42,47 @@ try: except ModuleNotFoundError: print("Please execute the following command to install dependencies:") - print("pip install pyelftools cxxfilt pydantic parse pycstruct") + print("pip install pyelftools cxxfilt pydantic parse pycstruct colorlog serial") exit(1) +logger = logging.getLogger(__name__) +logger.setLevel(logging.INFO) + +stream_handler = logging.StreamHandler() +formatter = colorlog.ColoredFormatter( + "%(log_color)s %(message)s", + log_colors={ + "DEBUG": "light_black", + "INFO": "white", + "WARNING": "yellow", + "ERROR": "red", + }, +) + +stream_handler.setFormatter(formatter) +logger.addHandler(stream_handler) + class SymbolTables(object): def __init__(self, file): elffile = open(file, "rb") self.elffile = ELFFile(elffile) + self.elfinfo = dict() + self.typeinfo = dict() self.symbol_dict = dict() self.addr_list = list() + self.__parse_header() + self.parse_symbol() + + def __parse_header(self): + elf_header = self.elffile.header + bitness = elf_header["e_ident"]["EI_CLASS"] + self.elfinfo["bitwides"] = 32 if bitness == "ELFCLASS32" else 64 + endianness = elf_header["e_ident"]["EI_DATA"] + self.elfinfo["byteorder"] = "little" if endianness == "ELFDATA2LSB" else "big" + self.typeinfo["size_t"] = "uint%d" % self.elfinfo["bitwides"] + self.typeinfo["long"] = "int%d" % self.elfinfo["bitwides"] + self.typeinfo["pid_t"] = "int32" def __symbol_filter(self, symbol): if symbol["st_info"]["type"] != "STT_FUNC": @@ -79,10 +114,58 @@ class SymbolTables(object): symtable = self.__get_symtable() for nsym, symbol in enumerate(symtable.iter_symbols()): if self.__symbol_filter(symbol) is not None: - symbol_name = cxxfilt.demangle(symbol.name) + try: + symbol_name = cxxfilt.demangle(symbol.name) + except Exception: + symbol_name = symbol.name self.symbol_dict[symbol["st_value"] & ~0x01] = symbol_name self.addr_list = sorted(self.symbol_dict) + def get_typesize(self, type_name): + if not self.elffile.has_dwarf_info(): + raise ValueError("not found dwarf info!") + + dwarfinfo = self.elffile.get_dwarf_info() + for CU in dwarfinfo.iter_CUs(): + for DIE in CU.iter_DIEs(): + if DIE.tag == "DW_TAG_typedef": + name = DIE.attributes["DW_AT_name"].value.decode("utf-8") + if name == type_name: + if "DW_AT_type" in DIE.attributes: + type_attr = DIE.attributes["DW_AT_type"] + base_type_die = dwarfinfo.get_DIE_from_refaddr( + type_attr.value + CU.cu_offset + ) + if base_type_die.tag == "DW_TAG_base_type": + size = base_type_die.attributes["DW_AT_byte_size"].value + elif base_type_die.tag == "DW_TAG_typedef": + type_name = base_type_die.attributes[ + "DW_AT_name" + ].value.decode("utf-8") + continue + else: + size = DIE.attributes["DW_AT_byte_size"].value + return size + raise ValueError("not found type") + + def readstring(self, addr): + data = b"" + while True: + data += self.read(addr, 256) + data = data.split(b"\x00")[0] + if len(data) < 256: + break + return data.decode("utf-8") + + def read(self, addr, size): + for segment in self.elffile.iter_segments(): + seg_addr = segment["p_paddr"] + seg_size = min(segment["p_memsz"], segment["p_filesz"]) + if addr >= seg_addr and addr + size <= seg_addr + seg_size: + data = segment.data() + start = addr - seg_addr + return data[start : start + size] + def addr2symbol(self, addr: int): index = bisect.bisect(self.addr_list, addr) if index != -1: @@ -154,8 +237,9 @@ class Trace(object): return trace def __init__(self, file): - with open(file, "r") as tracefile: - self.lines = tracefile.readlines() + with open(file, "rb+") as tracefile: + self.lines = tracefile.read() + self.lines = self.lines.split(b"\n") self.all_trace = list() self.parse() @@ -166,15 +250,21 @@ class Trace(object): ) for line in self.lines: - ret = header_pattern.parse(line.strip()) - if ret and ret.named["payload"]: - self.all_trace.append(TraceModel(**ret.named)) + try: + line = line.decode("utf-8") + ret = header_pattern.parse(line.strip()) + if ret and ret.named["payload"]: + self.all_trace.append(TraceModel(**ret.named)) + except Exception: + continue - def dump_trace(self): + def dump_trace(self, output="trace.systrace"): formatted = ["# tracer: nop", "#"] for trace in self.all_trace: formatted.append(trace.dump_one_trace()) - return formatted + with open(output, "w") as fp: + fp.writelines("\n".join(formatted)) + return output class ParseBinaryLogTool: @@ -185,7 +275,6 @@ class ParseBinaryLogTool: out_path=None, size_long=4, config_endian_big=False, - config_smp=0, ): self.binary_log_path = binary_log_path self.elf_nuttx_path = elf_nuttx_path @@ -199,7 +288,6 @@ class ParseBinaryLogTool: self.size_long = size_long self.size_note_common = 3 + size_long * 3 self.config_endian_big = config_endian_big - self.config_smp = config_smp def parse_by_endian(self, lis): res = [hex(e)[2:] for e in lis] # strip prefix "0x" @@ -216,8 +304,7 @@ class ParseBinaryLogTool: one.add("uint8", "nc_length") one.add("uint8", "nc_type") one.add("uint8", "nc_priority") - if self.config_smp > 0: - one.add("uint8", "nc_cpu") + one.add("uint8", "nc_cpu") one.add("uint8", "nc_pid", self.size_long) one.add("uint8", "nc_systime_sec", self.size_long) one.add("uint8", "nc_systime_nsec", self.size_long) @@ -313,44 +400,295 @@ class ParseBinaryLogTool: print(f"debug, dump one={mod.dump_one_trace()}") -if __name__ == "__main__": +class TraceDecoder(SymbolTables): + def __init__(self, elffile): + super().__init__(elffile) + self.data = b"" + self.typeinfo["time_t"] = "int%d" % (self.get_typesize("time_t") * 8) + + def note_common_define(self): + note_common = pycstruct.StructDef(alignment=4) + note_common.add("uint8", "nc_length") + note_common.add("uint8", "nc_type") + note_common.add("uint8", "nc_priority") + note_common.add("uint8", "nc_cpu") + note_common.add(self.typeinfo["pid_t"], "nc_pid") + note_common.add(self.typeinfo["time_t"], "nc_systime_sec") + note_common.add(self.typeinfo["long"], "nc_systime_nsec") + return note_common + + def note_printf_define(self, length): + struct_def = pycstruct.StructDef(alignment=4) + struct_def.add(self.note_common_define(), "npt_cmn") + struct_def.add(self.typeinfo["size_t"], "npt_ip") + struct_def.add(self.typeinfo["size_t"], "npt_fmt") + struct_def.add("uint32", "npt_type") + if length > 0: + struct_def.add("uint8", "npt_data", length=length) + return struct_def + + def extract_int(self, fmt, data): + pattern = re.match( + r"%([-+ #0]*)?(\d+|\*)?(\.)?(\d+|\*)?([hljzt]|ll|hh)?([diuxXop])", fmt + ).groups() + format = "%" if pattern[0] is None else "%" + pattern[0] + + if pattern[4] == "l" or pattern[4] == "z" or pattern[4] == "t": + length = 4 if self.typeinfo["size_t"] == "int32" else 8 + elif pattern[4] == "ll": + length = 8 + elif pattern[4] == "h": + length = 2 + elif pattern[4] == "hh": + length = 1 + else: + length = 4 + + width = 0 + if pattern[1] == "*": + width = int.from_bytes( + data[:4], byteorder=self.elfinfo["byteorder"], signed=True + ) + data = data[4:] + format += str(width) + elif pattern[1] is not None: + width = int(pattern[1]) + format += pattern[1] + + format += pattern[5] + if pattern[5] == "d" or pattern[5] == "i": + value = int.from_bytes( + data[:length], byteorder=self.elfinfo["byteorder"], signed=True + ) + elif ( + pattern[5] == "u" + or pattern[5] == "x" + or pattern[5] == "X" + or pattern[5] == "o" + or pattern[5] == "O" + ): + value = int.from_bytes( + data[:length], byteorder=self.elfinfo["byteorder"], signed=False + ) + + value = format % value + return "%s", length, value + + def extract_float(self, fmt, data): + pattern = re.match( + r"%([-+ #0]*)?(\d+|\*)?(\.)?(\d+|\*)?(L)?([fFeEgGaA])", fmt + ).groups() + if pattern[4] == "L": + length = 16 + else: + length = 8 + value = struct.unpack(">" + lenght += size + else: + lenght += len(string) + 1 + except Exception: + size = 4 if self.typeinfo["size_t"] == "uint32" else 8 + address = int.from_bytes( + data[:size], byteorder=self.elfinfo["byteorder"], signed=False + ) + string = f"<<0x{address}>>" + lenght += size + return "%s", lenght, string + + def extract_point(self, fmt, data): + length = 4 if self.typeinfo["size_t"] == "int32" else 8 + value = int.from_bytes( + data[:length], byteorder=self.elfinfo["byteorder"], signed=False + ) + return "%s", length, f"{value:x}" + + conversions = { + r"%p": extract_point, + r"%c": lambda _0, _1, data: ("%c", 1, chr(data[0])), + r"%([-+ #0]*)?(\d+|\*)?(\.)?(\d+|\*)?(L)?([fFeEgGaA])": extract_float, + r"%([-+ #0]*)?(\d+|\*)?(\.)?(\d+|\*)?([hljzt]|ll|hh)?([diuxXop])": extract_int, + r"%([ ]*)?([\d+|\*])?(\.)?([\d+|\*])?s": extract_string, + } + + patterns = {re.compile(pattern): func for pattern, func in conversions.items()} + + def printf(self, format, data): + try: + fmt = [] + values = [] + + parts = [ + part + for part in re.split( + r"(%[-+#0\s]*[\d|\*]*(?:\.[\d|\*])?[lhjztL]?[diufFeEgGxXoscpn%])", + format, + ) + ] + for part in parts: + if "%" not in part: + fmt.append(part) + continue + + for pattern, handler in self.patterns.items(): + if pattern.match(part): + part, length, value = handler(self, part, data) + values.append(value) + fmt.append(part) + data = data[length:] + break + else: + fmt.append(part) + + return "".join(fmt) % tuple(values) + except Exception as e: + logger.error(f"format failed: {e}") + + def print_format(self, note): + payload = dict() + payload["time"] = ( + note["npt_cmn"]["nc_systime_sec"] + + note["npt_cmn"]["nc_systime_nsec"] / 1000000000 + ) + payload["pid"] = note["npt_cmn"]["nc_pid"] + payload["cpu"] = ( + 0 if "nc_cpu" not in note["npt_cmn"] else note["npt_cmn"]["nc_cpu"] + ) + payload["format"] = self.readstring(note["npt_fmt"]) + prefix = "[{time:.9f}] [{pid}] [CPU{cpu}]: ".format(**payload) + string = self.printf(payload["format"], note["npt_data"]).rstrip("\n") + logger.info(prefix + string) + + def parse_note(self, rawdata=None): + while len(self.data) > 0: + data = self.data if rawdata is None else rawdata + try: + common_struct = self.note_common_define() + if len(data) < common_struct.size(): + return + common_note = common_struct.deserialize(data) + nc_length = common_note["nc_length"] + if nc_length < common_struct.size(): + raise ValueError("Invalid note length") + + if common_note["nc_type"] == 24: + note_struct = self.note_printf_define(0) + length = nc_length - note_struct.size() + note = note_struct.deserialize(data) + note["npt_data"] = data[ + note_struct.size() : note_struct.size() + length + ] + self.print_format(note) + else: + raise ValueError("Invalid note type") + except Exception as e: + logger.debug(f"skip one byte, data: {hex(self.data[0])} {e}") + self.data = data[1:] + continue + + self.data = data[nc_length:] + + def tty_received(self): + while True: + data = ser.read(16384) + if len(data) == 0: + continue + self.data += data + logger.debug(f"serial buffer data: {self.data.hex()}") + decode.parse_note() + + +def parse_arguments(): parser = argparse.ArgumentParser() - parser.add_argument("-t", "--trace", help="original trace file", required=True) + parser.add_argument("-t", "--trace", help="original trace file") parser.add_argument("-e", "--elf", help="elf file") + parser.add_argument("-d", "--device", help="Physical serial device name") + parser.add_argument( + "-b", "--baudrate", help="Physical serial device baud rate", default=115200 + ) + parser.add_argument("-v", "--verbose", help="verbose output", action="store_true") parser.add_argument( "-o", - "--out", + "--output", help="filtered trace file, default output trace.systrace", default="trace.systrace", ) - args = parser.parse_args() + return parser.parse_args() - file_type = subprocess.check_output(f"file -b {args.trace}", shell=True) - file_type = str(file_type, "utf-8").lower() - if "ascii" in file_type: - print("trace log type is text") - trace = Trace(args.trace) - symbol = SymbolTables(args.elf) - symbol.parse_symbol() - for onetrace in trace.all_trace: - if isinstance(onetrace.payload, ATraceModel) and re.fullmatch( - r"^0x[0-9a-fA-F]+$", onetrace.payload.func - ): - onetrace.payload.func = symbol.addr2symbol( - int(onetrace.payload.func, 16) - ) - lines = trace.dump_trace() - with open(args.out, "w") as out: - out.writelines("\n".join(lines)) - print(os.path.abspath(args.out)) - else: - print("trace log type is binary") - if args.elf: - print( - "parse_binary_log, default config, size_long=4, config_endian_big=False, config_smp=0" - ) - parse_binary_log_tool = ParseBinaryLogTool(args.trace, args.elf, args.out) - parse_binary_log_tool.symbol_tables.parse_symbol() - parse_binary_log_tool.parse_binary_log() + +if __name__ == "__main__": + args = parse_arguments() + out = args.output if not args.output else "trace.systrace" + logger.setLevel(logging.DEBUG if args.verbose else logging.INFO) + + if args.trace is None and args.device is None: + print("error, please add trace file path or device name") + print( + "usage: parsetrace.py [-h] [-t TRACE] [-e ELF] [-d DEVICE] [-b BAUDRATE] [-v] [-o OUTPUT]" + ) + exit(1) + + if args.trace: + file_type = subprocess.check_output(f"file -b {args.trace}", shell=True) + file_type = str(file_type, "utf-8").lower() + if "ascii" in file_type: + print("trace log type is text") + trace = Trace(args.trace) + if args.elf: + symbol = SymbolTables(args.elf) + symbol.parse_symbol() + + for onetrace in trace.all_trace: + if isinstance(onetrace.payload, ATraceModel) and re.fullmatch( + r"^0x[0-9a-fA-F]+$", onetrace.payload.func + ): + onetrace.payload.func = symbol.addr2symbol( + int(onetrace.payload.func, 16) + ) + + lines = trace.dump_trace() + with open(args.out, "w") as out: + out.writelines("\n".join(lines)) + print(os.path.abspath(args.out)) else: + print("trace log type is binary") + if args.elf: + print( + "parse_binary_log, default config, size_long=4, config_endian_big=False, config_smp=0" + ) + parse_binary_log_tool = ParseBinaryLogTool( + args.trace, args.elf, args.out + ) + parse_binary_log_tool.symbol_tables.parse_symbol() + parse_binary_log_tool.parse_binary_log() + else: + print("error, please add elf file path") + + if args.device: + if args.elf is None: print("error, please add elf file path") + exit(1) + + decode = TraceDecoder(args.elf) + with serial.Serial(args.device, baudrate=args.baudrate) as ser: + ser.timeout = 0 + decode.tty_received()