1#!/usr/bin/python 2 3#---------------------------------------------------------------------- 4# This module will enable GDB remote packet logging when the 5# 'start_gdb_log' command is called with a filename to log to. When the 6# 'stop_gdb_log' command is called, it will disable the logging and 7# print out statistics about how long commands took to execute and also 8# will primnt ou 9# Be sure to add the python path that points to the LLDB shared library. 10# 11# To use this in the embedded python interpreter using "lldb" just 12# import it with the full path using the "command script import" 13# command. This can be done from the LLDB command line: 14# (lldb) command script import /path/to/gdbremote.py 15# Or it can be added to your ~/.lldbinit file so this module is always 16# available. 17#---------------------------------------------------------------------- 18 19import commands 20import optparse 21import os 22import shlex 23import re 24import tempfile 25 26log_file = '' 27 28def start_gdb_log(debugger, command, result, dict): 29 '''Start logging GDB remote packets by enabling logging with timestamps and 30 thread safe logging. Follow a call to this function with a call to "stop_gdb_log" 31 in order to dump out the commands.''' 32 global log_file 33 command_args = shlex.split(command) 34 usage = "usage: start_gdb_log [options] [<LOGFILEPATH>]" 35 description='''The command enables GDB remote packet logging with timestamps. The packets will be logged to <LOGFILEPATH> if supplied, or a temporary file will be used. Logging stops when stop_gdb_log is called and the packet times will 36 be aggregated and displayed.''' 37 parser = optparse.OptionParser(description=description, prog='start_gdb_log',usage=usage) 38 parser.add_option('-v', '--verbose', action='store_true', dest='verbose', help='display verbose debug info', default=False) 39 try: 40 (options, args) = parser.parse_args(command_args) 41 except: 42 return 43 44 if log_file: 45 result.PutCString ('error: logging is already in progress with file "%s"', log_file) 46 else: 47 args_len = len(args) 48 if args_len == 0: 49 log_file = tempfile.mktemp() 50 elif len(args) == 1: 51 log_file = args[0] 52 53 if log_file: 54 debugger.HandleCommand('log enable --threadsafe --timestamp --file "%s" gdb-remote packets' % log_file); 55 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) 56 return 57 58 result.PutCString ('error: invalid log file path') 59 result.PutCString (usage) 60 61def stop_gdb_log(debugger, command, result, dict): 62 '''Stop logging GDB remote packets to the file that was specified in a call 63 to "start_gdb_log" and normalize the timestamps to be relative to the first 64 timestamp in the log file. Also print out statistics for how long each 65 command took to allow performance bottlenecks to be determined.''' 66 global log_file 67 # Any commands whose names might be followed by more valid C identifier 68 # characters must be listed here 69 command_args = shlex.split(command) 70 usage = "usage: stop_gdb_log [options]" 71 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.''' 72 parser = optparse.OptionParser(description=description, prog='stop_gdb_log',usage=usage) 73 parser.add_option('-v', '--verbose', action='store_true', dest='verbose', help='display verbose debug info', default=False) 74 parser.add_option('-q', '--quiet', action='store_true', dest='quiet', help='display verbose debug info', default=False) 75 try: 76 (options, args) = parser.parse_args(command_args) 77 except: 78 return 79 80 if not log_file: 81 result.PutCString ('error: logging must have been previously enabled with a call to "stop_gdb_log"') 82 elif os.path.exists (log_file): 83 if len(args) == 0: 84 debugger.HandleCommand('log disable gdb-remote packets'); 85 result.PutCString ("GDB packet logging disabled. Logged packets are in '%s'" % log_file) 86 parse_gdb_log_file (log_file, options) 87 log_file = None 88 else: 89 result.PutCString (usage) 90 else: 91 print 'error: the GDB packet log file "%s" does not exist' % log_file 92 93def parse_gdb_log_file(file, options): 94 '''Parse a GDB log file that was generated by enabling logging with: 95 (lldb) log enable --threadsafe --timestamp --file <FILE> gdb-remote packets 96 This log file will contain timestamps and this fucntion will then normalize 97 those packets to be relative to the first value timestamp that is found and 98 show delta times between log lines and also keep track of how long it takes 99 for GDB remote commands to make a send/receive round trip. This can be 100 handy when trying to figure out why some operation in the debugger is taking 101 a long time during a preset set of debugger commands.''' 102 103 tricky_commands = [ 'qRegisterInfo' ] 104 timestamp_regex = re.compile('(\s*)([1-9][0-9]+\.[0-9]+)([^0-9].*)$') 105 packet_name_regex = re.compile('([A-Za-z_]+)[^a-z]') 106 base_time = 0.0 107 last_time = 0.0 108 packet_send_time = 0.0 109 packet_name = None 110 packet_total_times = {} 111 file = open(file) 112 lines = file.read().splitlines() 113 for line in lines: 114 match = timestamp_regex.match (line) 115 if match: 116 curr_time = float (match.group(2)) 117 delta = 0.0 118 if base_time: 119 delta = curr_time - last_time 120 else: 121 base_time = curr_time 122 idx = line.find('send packet: $') 123 if idx >= 0: 124 packet_send_time = curr_time 125 packet_match = packet_name_regex.match (line[idx+14:]) 126 if packet_match: 127 packet_name = packet_match.group(1) 128 for tricky_cmd in tricky_commands: 129 if packet_name.find (tricky_cmd) == 0: 130 packet_name = tricky_cmd 131 elif line.find('read packet: $') >= 0 and packet_name: 132 if packet_name in packet_total_times: 133 packet_total_times[packet_name] += delta 134 else: 135 packet_total_times[packet_name] = delta 136 packet_name = None 137 138 if not options or not options.quiet: 139 print '%s%.6f %+.6f%s' % (match.group(1), curr_time - base_time, delta, match.group(3)) 140 last_time = curr_time 141 else: 142 print line 143 if packet_total_times: 144 total_packet_time = 0.0 145 for key, vvv in packet_total_times.items(): 146 # print ' key = (%s) "%s"' % (type(key), key) 147 # print 'value = (%s) %s' % (type(vvv), vvv) 148 # if type(vvv) == 'float': 149 total_packet_time += vvv 150 print '#--------------------------------------------' 151 print '# Packet timing summary:' 152 print '#--------------------------------------------' 153 print '# Packet Time (sec) Percent' 154 print '#------------------------- ---------- -------' 155 res = sorted(packet_total_times, key=packet_total_times.__getitem__, reverse=True) 156 if last_time > 0.0: 157 for item in res: 158 packet_total_time = packet_total_times[item] 159 packet_percent = (packet_total_time / total_packet_time)*100.0 160 if packet_percent >= 10.0: 161 print " %24s %.6f %.2f%%" % (item, packet_total_time, packet_percent) 162 else: 163 print " %24s %.6f %.2f%%" % (item, packet_total_time, packet_percent) 164 165 166 167if __name__ == '__main__': 168 import sys 169 # This script is being run from the command line, create a debugger in case we are 170 # going to use any debugger functions in our function. 171 for file in sys.argv: 172 print '#----------------------------------------------------------------------' 173 print "# GDB remote log file: '%s'" % file 174 print '#----------------------------------------------------------------------' 175 parse_gdb_log_file (file, None) 176 177else: 178 import lldb 179 if lldb.debugger: 180 # This initializer is being run from LLDB in the embedded command interpreter 181 # Add any commands contained in this module to LLDB 182 lldb.debugger.HandleCommand('command script add -f gdbremote.start_gdb_log start_gdb_log') 183 lldb.debugger.HandleCommand('command script add -f gdbremote.stop_gdb_log stop_gdb_log') 184 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' 185