#!/usr/bin/python #---------------------------------------------------------------------- # This module will enable GDB remote packet logging when the # 'start_gdb_log' command is called with a filename to log to. When the # 'stop_gdb_log' command is called, it will disable the logging and # print out statistics about how long commands took to execute and also # will primnt ou # Be sure to add the python path that points to the LLDB shared library. # # To use this in the embedded python interpreter using "lldb" just # import it with the full path using the "command script import" # command. This can be done from the LLDB command line: # (lldb) command script import /path/to/gdbremote.py # Or it can be added to your ~/.lldbinit file so this module is always # available. #---------------------------------------------------------------------- import commands import optparse import os import shlex import re import tempfile log_file = '' def start_gdb_log(debugger, command, result, dict): '''Start logging GDB remote packets by enabling logging with timestamps and thread safe logging. Follow a call to this function with a call to "stop_gdb_log" in order to dump out the commands.''' global log_file command_args = shlex.split(command) usage = "usage: start_gdb_log [options] []" description='''The command enables GDB remote packet logging with timestamps. The packets will be logged to if supplied, or a temporary file will be used. Logging stops when stop_gdb_log is called and the packet times will be aggregated and displayed.''' parser = optparse.OptionParser(description=description, prog='start_gdb_log',usage=usage) parser.add_option('-v', '--verbose', action='store_true', dest='verbose', help='display verbose debug info', default=False) try: (options, args) = parser.parse_args(command_args) except: return if log_file: result.PutCString ('error: logging is already in progress with file "%s"', log_file) else: args_len = len(args) if args_len == 0: log_file = tempfile.mktemp() elif len(args) == 1: log_file = args[0] if log_file: debugger.HandleCommand('log enable --threadsafe --timestamp --file "%s" gdb-remote packets' % log_file); result.PutCString ("GDB packet logging enable with log file '%s'\nUse the 'stop_gdb_log' command to stop logging and show packet statistics." % log_file) return result.PutCString ('error: invalid log file path') result.PutCString (usage) def stop_gdb_log(debugger, command, result, dict): '''Stop logging GDB remote packets to the file that was specified in a call to "start_gdb_log" and normalize the timestamps to be relative to the first timestamp in the log file. Also print out statistics for how long each command took to allow performance bottlenecks to be determined.''' global log_file # Any commands whose names might be followed by more valid C identifier # characters must be listed here command_args = shlex.split(command) usage = "usage: stop_gdb_log [options]" description='''The command stops a previously enabled GDB remote packet logging command. Packet logging must have been previously enabled with a call to start_gdb_log.''' parser = optparse.OptionParser(description=description, prog='stop_gdb_log',usage=usage) parser.add_option('-v', '--verbose', action='store_true', dest='verbose', help='display verbose debug info', default=False) parser.add_option('-q', '--quiet', action='store_true', dest='quiet', help='display verbose debug info', default=False) parser.add_option('-c', '--sort-by-count', action='store_true', dest='sort_count', help='display verbose debug info', default=False) try: (options, args) = parser.parse_args(command_args) except: return if not log_file: result.PutCString ('error: logging must have been previously enabled with a call to "stop_gdb_log"') elif os.path.exists (log_file): if len(args) == 0: debugger.HandleCommand('log disable gdb-remote packets'); result.PutCString ("GDB packet logging disabled. Logged packets are in '%s'" % log_file) parse_gdb_log_file (log_file, options) log_file = None else: result.PutCString (usage) else: print 'error: the GDB packet log file "%s" does not exist' % log_file def parse_gdb_log_file(file, options): '''Parse a GDB log file that was generated by enabling logging with: (lldb) log enable --threadsafe --timestamp --file gdb-remote packets This log file will contain timestamps and this fucntion will then normalize those packets to be relative to the first value timestamp that is found and show delta times between log lines and also keep track of how long it takes for GDB remote commands to make a send/receive round trip. This can be handy when trying to figure out why some operation in the debugger is taking a long time during a preset set of debugger commands.''' tricky_commands = [ 'qRegisterInfo' ] timestamp_regex = re.compile('(\s*)([1-9][0-9]+\.[0-9]+)([^0-9].*)$') packet_name_regex = re.compile('([A-Za-z_]+)[^a-z]') base_time = 0.0 last_time = 0.0 packet_send_time = 0.0 packet_name = None packet_total_times = {} packet_count = {} file = open(file) lines = file.read().splitlines() for line in lines: match = timestamp_regex.match (line) if match: curr_time = float (match.group(2)) delta = 0.0 if base_time: delta = curr_time - last_time else: base_time = curr_time idx = line.find('send packet: $') if idx >= 0: packet_send_time = curr_time packet_match = packet_name_regex.match (line[idx+14:]) if packet_match: packet_name = packet_match.group(1) for tricky_cmd in tricky_commands: if packet_name.find (tricky_cmd) == 0: packet_name = tricky_cmd elif line.find('read packet: $') >= 0 and packet_name: if packet_name in packet_total_times: packet_total_times[packet_name] += delta packet_count[packet_name] += 1 else: packet_total_times[packet_name] = delta packet_count[packet_name] = 1 packet_name = None if not options or not options.quiet: print '%s%.6f %+.6f%s' % (match.group(1), curr_time - base_time, delta, match.group(3)) last_time = curr_time else: print line if packet_total_times: total_packet_time = 0.0 total_packet_count = 0 for key, vvv in packet_total_times.items(): # print ' key = (%s) "%s"' % (type(key), key) # print 'value = (%s) %s' % (type(vvv), vvv) # if type(vvv) == 'float': total_packet_time += vvv for key, vvv in packet_count.items(): total_packet_count += vvv print '#---------------------------------------------------' print '# Packet timing summary:' print '# Totals: time - %6f count %6d' % (total_packet_time, total_packet_count) print '#---------------------------------------------------' print '# Packet Time (sec) Percent Count ' print '#------------------------- ---------- ------- ------' if options and options.sort_count: res = sorted(packet_count, key=packet_count.__getitem__, reverse=True) else: res = sorted(packet_total_times, key=packet_total_times.__getitem__, reverse=True) if last_time > 0.0: for item in res: packet_total_time = packet_total_times[item] packet_percent = (packet_total_time / total_packet_time)*100.0 if packet_percent >= 10.0: print " %24s %.6f %.2f%% %6d" % (item, packet_total_time, packet_percent, packet_count[item]) else: print " %24s %.6f %.2f%% %6d" % (item, packet_total_time, packet_percent, packet_count[item]) if __name__ == '__main__': import sys # This script is being run from the command line, create a debugger in case we are # going to use any debugger functions in our function. for file in sys.argv[1:]: print '#----------------------------------------------------------------------' print "# GDB remote log file: '%s'" % file print '#----------------------------------------------------------------------' parse_gdb_log_file (file, None) else: import lldb if lldb.debugger: # This initializer is being run from LLDB in the embedded command interpreter # Add any commands contained in this module to LLDB lldb.debugger.HandleCommand('command script add -f gdbremote.start_gdb_log start_gdb_log') lldb.debugger.HandleCommand('command script add -f gdbremote.stop_gdb_log stop_gdb_log') print 'The "start_gdb_log" and "stop_gdb_log" commands are now installed and ready for use, type "start_gdb_log --help" or "stop_gdb_log --help" for more information'