trace.py
1 import argparse 2 import shlex 3 import struct 4 import sys 5 from collections import namedtuple 6 7 if sys.version_info.major > 2: 8 from builtins import range 9 10 # Used for reading struct from memory 11 eventStruct = namedtuple("event", "timestamp eventType arg") 12 13 14 class Trace(gdb.Command): 15 """Prints the captured trace 16 Usage: in gdb `source /path/to/trace.py` 17 `trace` or `trace verbose` 18 """ 19 20 def _loadTaskInfo(self, tcbAddr): 21 if tcbAddr not in self.tcbs: 22 TCB_t = gdb.lookup_type("TCB_t") 23 task = gdb.Value(tcbAddr).cast(TCB_t.pointer()).dereference() 24 self.tcbs[tcbAddr] = task["pcTaskName"].string() 25 26 def _getTaskName(self, tcbAddr): 27 if tcbAddr not in self.tcbs: 28 self._loadTaskInfo(tcbAddr) 29 30 return self.tcbs[tcbAddr] 31 32 def _getFunctionName(self, addr): 33 if addr not in self.functions: 34 block = gdb.block_for_pc(addr) 35 self.functions[addr] = block.function.print_name 36 37 return self.functions[addr] 38 39 def _getSerialDeviceName(self, addr): 40 if addr not in self.serial_devices: 41 SerialHandle_t = gdb.lookup_type("SerialHandle_t") 42 serialHandle = gdb.Value(addr).cast(SerialHandle_t.pointer()).dereference() 43 self.serial_devices[addr] = str(serialHandle["name"].string()) 44 45 return self.serial_devices[addr] 46 47 def _processTaskStart(self, event, verbose=False): 48 self.taskStartTime = event["timestamp"] 49 self.taskRunning = event["arg"] 50 self._loadTaskInfo(event["arg"]) 51 52 if verbose: 53 self._print( 54 "{:010d}: {} Task Started ({} since last event)".format( 55 event["timestamp"], 56 self._getTaskName(event["arg"]), 57 (int(event["timestamp"]) - self.lastEventTime), 58 ) 59 ) 60 61 def _processTaskStop(self, event, verbose=False): 62 63 if self.taskStartTime is not None: 64 duration = int(event["timestamp"]) - self.taskStartTime 65 else: 66 duration = "N/A" 67 68 if verbose: 69 self._print( 70 "{:010d}: {} Task Finished - Duration: {}".format( 71 event["timestamp"], self._getTaskName(event["arg"]), duration 72 ) 73 ) 74 else: 75 if self.taskRunning: 76 taskName = self._getTaskName(self.taskRunning) 77 else: 78 taskName = self._getTaskName(event["arg"]) 79 self._print("{: >30}: {}".format(taskName, duration)) 80 81 # Clear task tracking variables 82 self.taskStartTime = None 83 self.taskRunning = None 84 85 def _processISRStart(self, event, verbose=False): 86 fnAddr = event["arg"] 87 fnName = self._getFunctionName(fnAddr) 88 self.isrStartTimes[fnName] = event["timestamp"] 89 90 if verbose: 91 self._print( 92 "{:010d}: {} Started ({} since last event)".format( 93 event["timestamp"], 94 fnName, 95 (int(event["timestamp"]) - self.lastEventTime), 96 ) 97 ) 98 99 def _processISRStop(self, event, verbose=False): 100 fnAddr = event["arg"] 101 fnName = self._getFunctionName(fnAddr) 102 103 if fnName not in self.isrStartTimes or self.isrStartTimes[fnName] is None: 104 duration = "N/A" 105 else: 106 duration = int(event["timestamp"]) - self.isrStartTimes[fnName] 107 108 if verbose: 109 self._print( 110 "{:010d}: {} Finished - Duration: {}".format( 111 event["timestamp"], fnName, duration 112 ) 113 ) 114 else: 115 self._print("{: >30}: {}".format(fnName, duration)) 116 self.isrStartTimes[fnName] = None 117 118 def _processSDStart(self, event, rw, verbose=False): 119 self.sdSector = event["arg"] 120 self.sdStart = event["timestamp"] 121 122 if verbose: 123 self._print( 124 "{:010d}: SD {} Started [sector {:08X}] ({} since last event)".format( 125 event["timestamp"], 126 rw, 127 self.sdSector, 128 (int(event["timestamp"]) - self.lastEventTime), 129 ) 130 ) 131 132 def _processSDStop(self, event, rw, err=False, verbose=False): 133 134 if self.sdStart: 135 duration = event["timestamp"] - self.sdStart 136 else: 137 duration = "N/A" 138 139 if err: 140 errStr = "[ERR] " 141 else: 142 errStr = "" 143 144 if verbose: 145 self._print( 146 "{:010d}: SD {} {}Finished - Duration {} [count {}]".format( 147 event["timestamp"], rw, errStr, duration, event["arg"] 148 ) 149 ) 150 else: 151 actionStr = "SD {}".format(rw) 152 self._print( 153 "{: >30}: {} [Sector: {:08X} Count: {}]".format( 154 actionStr, duration, self.sdSector, event["arg"] 155 ) 156 ) 157 158 self.sdSector = 0xFFFFFFFF 159 self.sdStart = None 160 161 def _processSDReadStart(self, event, verbose=False): 162 self._processSDStart(event, "Read", verbose) 163 164 def _processSDReadStop(self, event, verbose=False): 165 self._processSDStop(event, "Read", False, verbose) 166 167 def _processSDReadErr(self, event, verbose=False): 168 self._processSDStop(event, "Read", True, verbose) 169 170 def _processSDWriteStart(self, event, verbose=False): 171 self._processSDStart(event, "Write", verbose) 172 173 def _processSDWriteStop(self, event, verbose=False): 174 self._processSDStop(event, "Write", False, verbose) 175 176 def _processSDWriteErr(self, event, verbose=False): 177 self._processSDStop(event, "Write", True, verbose) 178 179 def _processSerialByte(self, event, verbose=False): 180 181 handle_raw = event["arg"] & 0xFFFF 182 handle = self._getSerialDeviceName(handle_raw + 0x20000000) 183 184 byte = (event["arg"] >> 24) & 0xFF 185 if byte == 0x0A: 186 byte_str = "\\n" 187 elif byte == 0x0D: 188 byte_str = "\\r" 189 elif byte > 0x20 and byte < 0x7E: 190 byte_str = chr(byte) 191 else: 192 byte_str = "" 193 194 if (event["arg"] >> 16) & 1: 195 direction = "TX" 196 else: 197 direction = "RX" 198 199 if (event["arg"] >> 17) & 1: 200 isr = "ISR" 201 else: 202 isr = "" 203 204 self._print( 205 "{:>10} {} {:>3} {:02X} {}".format(handle, direction, isr, byte, byte_str) 206 ) 207 208 def _processEvent(self, event, verbose=False): 209 evt = { 210 "eventType": str(event["eventType"]), 211 "timestamp": int(event["timestamp"]), 212 "arg": int(event["arg"]), 213 } 214 215 if self.lastEventTime is None: 216 self.lastEventTime = int(event["timestamp"]) 217 218 if evt["eventType"] in self.eventDecoders: 219 self.eventDecoders[evt["eventType"]](evt, verbose) 220 else: 221 self._print(evt["eventType"]) 222 223 # Update last event time 224 self.lastEventTime = int(event["timestamp"]) 225 226 def __init__(self): 227 super(Trace, self).__init__("trace", gdb.COMMAND_USER) 228 229 # Register decoders 230 self.eventDecoders = {} 231 self.eventDecoders["kTraceEventTaskStart"] = self._processTaskStart 232 self.eventDecoders["kTraceEventTaskStop"] = self._processTaskStop 233 self.eventDecoders["kTraceEventISRStart"] = self._processISRStart 234 self.eventDecoders["kTraceEventISRStop"] = self._processISRStop 235 self.eventDecoders["kTraceEventSDReadStart"] = self._processSDReadStart 236 self.eventDecoders["kTraceEventSDReadStop"] = self._processSDReadStop 237 self.eventDecoders["kTraceEventSDReadErr"] = self._processSDReadErr 238 self.eventDecoders["kTraceEventSDWriteStart"] = self._processSDWriteStart 239 self.eventDecoders["kTraceEventSDWriteStop"] = self._processSDWriteStop 240 self.eventDecoders["kTraceEventSDWriteErr"] = self._processSDWriteErr 241 self.eventDecoders["kTraceEventSerialByte"] = self._processSerialByte 242 243 def _getEventFromBuff(self, buff, idx): 244 eventDict = eventStruct._asdict( 245 eventStruct._make( 246 struct.unpack_from( 247 self.eventStructFormat, buff, idx * self.eventStructSize 248 ) 249 ) 250 ) 251 252 eventDict["eventType"] = self.traceEventTypes[eventDict["eventType"]] 253 254 return eventDict 255 256 def _process_trace(self, verbose=False): 257 try: 258 traceEvent_t = gdb.lookup_type("traceEvent_t") 259 print("Loading traceEvents") 260 traceEvents = gdb.parse_and_eval("traceEvents") 261 except gdb.error as err: 262 print(err) 263 print("ERROR: Firmware was not compiled with trace support!") 264 return 265 266 traceEventSize = int(traceEvents.type.sizeof / traceEvent_t.sizeof) 267 traceEventIdx = int(gdb.parse_and_eval("traceEventIdx")) 268 269 if str(traceEvents[traceEventSize - 1]["eventType"]) == "kTraceEventUnknown": 270 indices = list(range(0, traceEventIdx)) 271 self._print("total traceEvents: " + str(traceEventIdx)) 272 else: 273 # Create index list wrapping around circular buffer 274 indices = list(range(traceEventIdx, traceEventSize)) + list( 275 range(0, traceEventIdx) 276 ) 277 self._print("total traceEvents: " + str(traceEventSize)) 278 279 self._print("traceEventIdx: " + str(traceEventIdx)) 280 281 start_time = int(traceEvents[indices[0]]["timestamp"]) 282 end_time = int(traceEvents[indices[-1]]["timestamp"]) 283 284 # The function traceEnable is only defined when using the ARM coreDebug clock 285 traceEnable, _ = gdb.lookup_symbol("traceEnable") 286 287 # Default to 1kHz ticks 288 traceClockHz = 1000 289 290 # If we're using CoreDebug clock, use system clock speed 291 if traceEnable: 292 traceClockHz = float(gdb.parse_and_eval("SystemCoreClock")) 293 294 self._print( 295 "trace duration: {:0.6f} s".format( 296 ((end_time - start_time) & 0xFFFFFFFF) / traceClockHz, 297 ) 298 ) 299 300 print( 301 "Reading traceEvents buffer ({} bytes)...".format( 302 int(traceEvents.type.sizeof) 303 ) 304 ) 305 306 # Read entire traceEventsBuffer at once in a single transaction 307 # This is WAY faster than reading each item individually 308 traceEventsBuff = ( 309 gdb.inferiors()[0] 310 .read_memory(int(traceEvents.address), int(traceEvents.type.sizeof)) 311 .tobytes() 312 ) 313 # traceEventsBuff = gdb.inferiors()[0].read_memory(int(traceEvents.address),64).tobytes() 314 print("Done reading buffer") 315 316 for idx in indices: 317 # This is the old "slow" way of processing events, lots of GDB transactions 318 # but is agnostic to struct formatting 319 # self._processEvent(traceEvents[i], verbose) 320 321 # This is the fast way! (It does require that the decoding struct is correct) 322 # Need to update if TRACE_FAST is defined 323 self._processEvent(self._getEventFromBuff(traceEventsBuff, idx), verbose) 324 325 # Print to console or file, depending on configuration 326 def _print(self, *args): 327 if self.file: 328 self.file.write("".join(args) + "\n") 329 else: 330 print(*args) 331 332 def invoke(self, args, from_tty): 333 self.taskRunning = None 334 self.taskStartTime = None 335 self.sdSector = 0xFFFFFFFF 336 self.sdStart = None 337 self.tcbs = {} 338 self.functions = {} 339 self.serial_devices = {} 340 self.isrStartTimes = {} 341 self.lastEventTime = None 342 self.eventStructFormat = "<LBL" # Change this accordingly if using TRACE_FAST 343 self.eventStructSize = struct.calcsize(self.eventStructFormat) 344 345 # Get event types from enum 346 eventTypes = gdb.types.make_enum_dict(gdb.lookup_type("enum traceEventType")) 347 348 # Swap key/values since make_enum_dict returns "enumStr":val 349 self.traceEventTypes = dict((v, k) for k, v in eventTypes.items()) 350 351 # Use argparse so we can call `trace --verbose` or 352 # `trace --filename somefile.txt` within GDB 353 parser = argparse.ArgumentParser() 354 parser.add_argument("--verbose", action="store_true") 355 parser.add_argument("--filename", help="save trace to file") 356 args = parser.parse_args(shlex.split(args)) 357 358 self.file = None 359 360 if args.filename: 361 self.file = open(args.filename, "w") 362 print(f"Writing trace to {args.filename}") 363 364 self._process_trace(args.verbose) 365 366 if self.file: 367 self.file.close() 368 print(f"{args.filename} closed") 369 370 371 # Do the thing! 372 Trace()