KFT python lib (#1418)

kftlib/examples/get_functions_times.py

@@ -0,0 +1,79 @@
+#!/usr/bin/env python3
+
+"""
+Example application using kftlib.
+"""
+
+import argparse
+import statistics
+import os
+
+from kftlib.elf import Elf
+from kftlib import inspect
+from kftlib.stats import get_functions_times
+
+from pathlib import Path
+
+
+def get_fn_times(events, elf, functions, out):
+    fn_pcs = list(map(lambda fn: elf.fun2pc.get(fn), functions))
+    fn_times = get_functions_times(events, fn_pcs)
+
+    sumt = 0
+    print(f"{'function':>13}: {'count':>5} {'avg time':>8}")
+    for fn, pc in zip(functions, fn_pcs):
+        if pc and pc in fn_times:
+            avg_time = statistics.mean(fn_times[pc])
+            count = len(fn_times[pc])
+            print(f"{fn:>13}: {count:>5} {avg_time:>8.0f}")
+            if fn in ["vm_map_clone", "vm_page_fault"]:
+                sumt += sum(fn_times[pc])
+            if fn in ["pmap_protect"]:
+                sumt -= sum(fn_times[pc])
+
+    print("SUM:", sumt)
+
+    os.makedirs(out, exist_ok=True)
+    for fn, pc in zip(functions, fn_pcs):
+        if not pc:
+            continue
+        with open(f"{out}/{fn}.data", "w") as f:
+            f.write("\n".join(str(t) for t in fn_times[pc]) + '\n')
+
+
+def main():
+    parser = argparse.ArgumentParser(
+        description="Launch kernel in a board simulator.")
+    parser.add_argument("kft_dump",
+                        type=Path,
+                        default=Path("dump.kft"),
+                        help="KFTrace dump to process")
+    parser.add_argument("-e", "--elf-file",
+                        type=Path,
+                        default=Path("sys/mimiker.elf"),
+                        help="Path to mimiker.elf")
+    parser.add_argument("-o", "--out",
+                        type=Path,
+                        default=Path("plot-data"))
+    args = parser.parse_args()
+
+    elf = Elf.inspect_elf_file(args.elf_file)
+    events = inspect.inspect_kft_file(args.kft_dump, elf)
+
+    functions = [
+        "vm_amap_find_anon",
+        "vm_object_find_page",
+        "vm_page_fault",
+        "pmap_protect",
+        "pmap_copy_page",
+        "vm_page_alloc",
+        "vm_map_clone",
+        "vm_amap_alloc",
+        "vm_object_alloc",
+    ]
+
+    get_fn_times(events, elf, functions, args.out)
+
+
+if __name__ == "__main__":
+    main()

kftlib/examples/tree.py

@@ -0,0 +1,84 @@
+#!/usr/bin/env python3
+import argparse
+
+from pathlib import Path
+
+from kftlib.elf import Elf
+from kftlib.event import KFTEventType
+from kftlib import inspect
+
+
+def draw_graphs(function_pc, td_events, elf, max_depth, graphs):
+    """
+    Draw call graphs for given function and save them in `graphs` list.
+    """
+    graph = ""
+    depth = 0
+    start_time = 0
+    drawing_graph = False
+    for event in td_events:
+        if not drawing_graph and event.pc != function_pc:
+            continue
+
+        if event.pc == function_pc and event.typ == KFTEventType.KFT_IN:
+            drawing_graph = True
+            start_time = event.timestamp
+            graph = ""
+
+        append = not max_depth or depth <= max_depth
+
+        time = event.timestamp - start_time
+        if event.typ == KFTEventType.KFT_IN:
+            fn_name = elf.pc2fun[event.pc]
+            line = f"{time:>4}  " + depth * "| " + fn_name + "\n"  # in
+            depth += 1
+        else:
+            depth -= 1
+            line = f"{time:>4}  " + depth * "| " + "*" + "\n"  # out
+
+        if append:
+            graph += line
+
+        if event.pc == function_pc and event.typ == KFTEventType.KFT_OUT:
+            graphs.append((time, graph))
+            drawing_graph = False
+
+
+def main():
+    parser = argparse.ArgumentParser(
+        description="Launch kernel in a board simulator."
+    )
+    parser.add_argument("function",
+                        type=str,
+                        help="Function to show call graph for.")
+    parser.add_argument("kft_dump",
+                        type=Path,
+                        default=Path("dump.kft"),
+                        help="KFTrace dump to process")
+    parser.add_argument("-e", "--elf-file",
+                        type=Path,
+                        default=Path("sys/mimiker.elf"),
+                        help="Path to mimiker.elf")
+    parser.add_argument("-d", "--max-depth",
+                        type=int)
+    parser.add_argument("-o", "--out",
+                        type=Path,
+                        default=Path("graph.txt"))
+
+    args = parser.parse_args()
+    elf = Elf.inspect_elf_file(args.elf_file)
+    events = inspect.inspect_kft_file(args.kft_dump, elf)
+
+    graphs = []
+    function_pc = elf.fun2pc[args.function]
+    for td, td_events in events.items():
+        draw_graphs(function_pc, td_events, elf, args.max_depth, graphs)
+
+    graphs = [g for _, g in sorted(graphs)]
+
+    with open(args.out, "w") as f:
+        f.write("\n\n".join(graphs))
+
+
+if __name__ == "__main__":
+    main()

kftlib/kftlib/elf.py

@@ -0,0 +1,70 @@
+from __future__ import annotations
+
+from elftools.elf.elffile import ELFFile
+from elftools.elf.sections import Section, Symbol, SymbolTableSection
+from pathlib import Path
+from typing import Dict, Tuple, Optional
+
+
+class Elf():
+    """
+    Internal representation of Elf file.
+    """
+
+    def __init__(self,
+                 elf: ELFFile,
+                 kernel_start: int,
+                 pc2fun: Dict[int, str],
+                 fun2pc: Dict[str, int]):
+        self._elf = elf
+        self.kernel_start = kernel_start
+        self.pc2fun = pc2fun
+        self.fun2pc = fun2pc
+
+    def __repr__(self) -> str:
+        return f"<Elf kernel_start {self.kernel_start:#x}>"
+
+    @staticmethod
+    def inspect_elf_file(elf_file: Path) -> Optional[Elf]:
+        """
+        Read elf file and get info about functions adresses.
+
+        Arguments:
+            elf_file
+
+        Returns:
+            Elf representation used by KFT
+        """
+        def get_symbol_table_section(elf: ELFFile) -> Section:
+            for section in elf.iter_sections():
+                if isinstance(section, SymbolTableSection):
+                    return section
+
+        def is_function(s: Symbol) -> bool:
+            return s.entry['st_info']['type'] == 'STT_FUNC'
+
+        def read_symbol(s: Symbol) -> Tuple[int, str]:
+            return (s.entry['st_value'], s.name)
+
+        with open(elf_file, 'rb') as f:
+            elf = ELFFile(f)
+
+            sym_table = get_symbol_table_section(elf)
+            if sym_table is None:
+                return None
+
+            kern_sym = sym_table.get_symbol_by_name('__kernel_start')
+            if kern_sym is None:
+                return None
+
+            kern_start = read_symbol(kern_sym[0])[0]
+
+            pc_to_fun = [read_symbol(s)
+                         for s in sym_table.iter_symbols() if is_function(s)]
+
+        pcs, fns = zip(*pc_to_fun)
+        fun_to_pc = zip(fns, pcs)
+        pc2fun = dict(pc_to_fun)
+        fun2pc = dict(fun_to_pc)
+
+        return Elf(elf, kern_start, pc2fun, fun2pc)

kftlib/kftlib/event.py

@@ -0,0 +1,58 @@
+from __future__ import annotations
+
+from enum import Enum
+from typing import Dict, List, Tuple
+
+
+class KFTEventType(Enum):
+    KFT_IN = 0
+    KFT_OUT = 1
+
+
+class KFTEvent():
+    """
+    Internal representation of KFT event
+    """
+
+    def __init__(self, typ: int, pc: int, timestamp: int):
+        self.typ = KFTEventType(typ)
+        self.pc = pc
+        self.timestamp = timestamp
+
+    def __repr__(self) -> str:
+        type = 'in' if self.typ == KFTEventType.KFT_IN else 'out'
+        return f'<{type} {self.pc:#x} {self.timestamp}>'
+
+    @staticmethod
+    def decode(v: int, kern_start: int) -> Tuple[int, KFTEvent]:
+        """
+        Decode kft event from compressed representation of the event.
+
+        Arguments:
+            v - encoded value
+            kern_start - kernel start address
+
+        Returns:
+            thread id
+            KFTEvent class
+        """
+        PC_MASK = 0xFFFFFC            # 24 bits
+        TIMESTAMP_MASK = 0x1FFFFFFFF  # 31 bits
+        THREAD_MASK = 0xFF            # 8 bits
+        TYPE_MASK = 0x1               # 1 bit
+
+        PC_SHIFT = 40
+        TIMESTAMP_SHIFT = 9
+        THREAD_SHIFT = 1
+        TYPE_SHIFT = 0
+
+        typ = (v >> TYPE_SHIFT) & TYPE_MASK
+        thread = (v >> THREAD_SHIFT) & THREAD_MASK
+        timestamp = (v >> TIMESTAMP_SHIFT) & TIMESTAMP_MASK
+        rel_pc = (v >> PC_SHIFT) & PC_MASK
+        pc = kern_start + rel_pc
+
+        return thread, KFTEvent(typ, pc, timestamp)
+
+
+TdEvents = Dict[int, List[KFTEvent]]

kftlib/kftlib/inspect.py

@@ -0,0 +1,64 @@
+from __future__ import annotations
+
+import logging
+import os
+
+from array import array
+from collections import defaultdict
+from pathlib import Path
+from typing import Dict, List
+
+from kftlib.event import KFTEvent, TdEvents
+from kftlib.elf import Elf
+
+
+def inspect_kft_file(path: Path,
+                     elf: Elf,
+                     td_max: int = 180) -> TdEvents:
+    """
+    Inspect kft dump and return events for each running thread.
+
+    Arguments:
+        path -- path to .kft file
+        kern_start -- starting address of the kernel (from elf that was run to
+                      obtain dump)
+        td_max -- maximal number of threads (default: 180)
+
+    Returns:
+        dictionary of events for each thread (indexed with thread id)
+    """
+    events: Dict[int, List[KFTEvent]] = defaultdict(list)
+    td_time = [0] * (td_max + 1)  # elapsed time
+    cur_thread = -1
+    cur_time = 0
+    switch_time = 0
+    ctx_swith_count = 0
+
+    entries = array('Q')
+    with open(path, 'rb') as f:
+        entries.frombytes(f.read())
+
+    print(f'Read {len(entries)} KFT events')
+
+    for i, v in enumerate(entries):
+        thread, event = KFTEvent.decode(v, elf.kernel_start)
+
+        if thread != cur_thread:
+            # update info about prev thread
+            td_time[cur_thread] += event.timestamp - switch_time
+
+            # save values for current thread
+            switch_time = event.timestamp
+            if thread > td_max:
+                raise IndexError('There are too many threads.'
+                                 'Try to increase td_max.')
+            cur_time = td_time[thread]
+            cur_thread = thread
+            ctx_swith_count += 1
+
+        # Update event to the time elapsed when current thread was running.
+        event.timestamp = cur_time + (event.timestamp - switch_time)
+
+        events[cur_thread].append(event)
+
+    return events