tools: prasetrace.py supports parsing syslog

Signed-off-by: yinshengkai <yinshengkai@xiaomi.com>

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;
     }
 

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) */

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:
+        with open(file, "rb+") as tracefile:
-            self.lines = tracefile.readlines()
+            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())
+            try:
-            if ret and ret.named["payload"]:
+                line = line.decode("utf-8")
-                self.all_trace.append(TraceModel(**ret.named))
+                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("<d", data[:length])[0]
+        return "%s", length, fmt % value
+
+    def extract_string(self, fmt, data):
+        lenght = 0
+        if fmt == "%.*s":
+            lenght = int.from_bytes(
+                data[:4], byteorder=self.elfinfo["byteorder"], signed=True
+            )
+            data = data[4:]
+        else:
+            lenght = 0
+
+        try:
+            string = data.split(b"\x00")[0].decode("utf-8")
+            if len(data.split(b"\x00")[0]) != len(string) and len(string):
+                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
+            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 __name__ == "__main__":
-    if "ascii" in file_type:
+    args = parse_arguments()
-        print("trace log type is text")
+    out = args.output if not args.output else "trace.systrace"
-        trace = Trace(args.trace)
+    logger.setLevel(logging.DEBUG if args.verbose else logging.INFO)
-        symbol = SymbolTables(args.elf)
+
-        symbol.parse_symbol()
+    if args.trace is None and args.device is None:
-        for onetrace in trace.all_trace:
+        print("error, please add trace file path or device name")
-            if isinstance(onetrace.payload, ATraceModel) and re.fullmatch(
+        print(
-                r"^0x[0-9a-fA-F]+$", onetrace.payload.func
+            "usage: parsetrace.py [-h] [-t TRACE] [-e ELF] [-d DEVICE] [-b BAUDRATE] [-v] [-o OUTPUT]"
-            ):
+        )
-                onetrace.payload.func = symbol.addr2symbol(
+        exit(1)
-                    int(onetrace.payload.func, 16)
+
-                )
+    if args.trace:
-        lines = trace.dump_trace()
+        file_type = subprocess.check_output(f"file -b {args.trace}", shell=True)
-        with open(args.out, "w") as out:
+        file_type = str(file_type, "utf-8").lower()
-            out.writelines("\n".join(lines))
+        if "ascii" in file_type:
-            print(os.path.abspath(args.out))
+            print("trace log type is text")
-    else:
+            trace = Trace(args.trace)
-        print("trace log type is binary")
+            if args.elf:
-        if args.elf:
+                symbol = SymbolTables(args.elf)
-            print(
+                symbol.parse_symbol()
-                "parse_binary_log, default config, size_long=4, config_endian_big=False, config_smp=0"
+
-            )
+                for onetrace in trace.all_trace:
-            parse_binary_log_tool = ParseBinaryLogTool(args.trace, args.elf, args.out)
+                    if isinstance(onetrace.payload, ATraceModel) and re.fullmatch(
-            parse_binary_log_tool.symbol_tables.parse_symbol()
+                        r"^0x[0-9a-fA-F]+$", onetrace.payload.func
-            parse_binary_log_tool.parse_binary_log()
+                    ):
+                        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()