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    parser.add_option('-c', '--sort-by-count', action='store_true', dest='sort_count', help='display verbose debug info', default=False)
76    try:
77        (options, args) = parser.parse_args(command_args)
78    except:
79        return
80
81    if not log_file:
82        result.PutCString ('error: logging must have been previously enabled with a call to "stop_gdb_log"')
83    elif os.path.exists (log_file):
84        if len(args) == 0:
85            debugger.HandleCommand('log disable gdb-remote packets');
86            result.PutCString ("GDB packet logging disabled. Logged packets are in '%s'" % log_file)
87            parse_gdb_log_file (log_file, options)
88            log_file = None
89        else:
90            result.PutCString (usage)
91    else:
92        print 'error: the GDB packet log file "%s" does not exist' % log_file
93
94def parse_gdb_log_file(file, options):
95    '''Parse a GDB log file that was generated by enabling logging with:
96    (lldb) log enable --threadsafe --timestamp --file <FILE> gdb-remote packets
97    This log file will contain timestamps and this fucntion will then normalize
98    those packets to be relative to the first value timestamp that is found and
99    show delta times between log lines and also keep track of how long it takes
100    for GDB remote commands to make a send/receive round trip. This can be
101    handy when trying to figure out why some operation in the debugger is taking
102    a long time during a preset set of debugger commands.'''
103
104    tricky_commands = [ 'qRegisterInfo' ]
105    timestamp_regex = re.compile('(\s*)([1-9][0-9]+\.[0-9]+)([^0-9].*)$')
106    packet_name_regex = re.compile('([A-Za-z_]+)[^a-z]')
107    base_time = 0.0
108    last_time = 0.0
109    packet_send_time = 0.0
110    packet_name = None
111    packet_total_times = {}
112    packet_count = {}
113    file = open(file)
114    lines = file.read().splitlines()
115    for line in lines:
116        match = timestamp_regex.match (line)
117        if match:
118            curr_time = float (match.group(2))
119            delta = 0.0
120            if base_time:
121                delta = curr_time - last_time
122            else:
123                base_time = curr_time
124            idx = line.find('send packet: $')
125            if idx >= 0:
126                packet_send_time = curr_time
127                packet_match = packet_name_regex.match (line[idx+14:])
128                if packet_match:
129                    packet_name = packet_match.group(1)
130                    for tricky_cmd in tricky_commands:
131                        if packet_name.find (tricky_cmd) == 0:
132                            packet_name = tricky_cmd
133            elif line.find('read packet: $') >= 0 and packet_name:
134                if packet_name in packet_total_times:
135                    packet_total_times[packet_name] += delta
136                    packet_count[packet_name] += 1
137                else:
138                    packet_total_times[packet_name] = delta
139                    packet_count[packet_name] = 1
140                packet_name = None
141
142            if not options or not options.quiet:
143                print '%s%.6f %+.6f%s' % (match.group(1), curr_time - base_time, delta, match.group(3))
144            last_time = curr_time
145        else:
146            print line
147    if packet_total_times:
148        total_packet_time = 0.0
149        total_packet_count = 0
150        for key, vvv in packet_total_times.items():
151            # print '  key = (%s) "%s"' % (type(key), key)
152            # print 'value = (%s) %s' % (type(vvv), vvv)
153            # if type(vvv) == 'float':
154            total_packet_time += vvv
155        for key, vvv in packet_count.items():
156            total_packet_count += vvv
157
158        print '#---------------------------------------------------'
159        print '# Packet timing summary:'
160        print '# Totals: time - %6f count %6d' % (total_packet_time, total_packet_count)
161        print '#---------------------------------------------------'
162        print '# Packet                   Time (sec) Percent Count '
163        print '#------------------------- ---------- ------- ------'
164        if options and options.sort_count:
165            res = sorted(packet_count, key=packet_count.__getitem__, reverse=True)
166        else:
167            res = sorted(packet_total_times, key=packet_total_times.__getitem__, reverse=True)
168
169        if last_time > 0.0:
170            for item in res:
171                packet_total_time = packet_total_times[item]
172                packet_percent = (packet_total_time / total_packet_time)*100.0
173                if packet_percent >= 10.0:
174                    print "  %24s %.6f   %.2f%% %6d" % (item, packet_total_time, packet_percent, packet_count[item])
175                else:
176                    print "  %24s %.6f   %.2f%%  %6d" % (item, packet_total_time, packet_percent, packet_count[item])
177
178
179
180if __name__ == '__main__':
181    import sys
182    # This script is being run from the command line, create a debugger in case we are
183    # going to use any debugger functions in our function.
184    for file in sys.argv:
185        print '#----------------------------------------------------------------------'
186        print "# GDB remote log file: '%s'" % file
187        print '#----------------------------------------------------------------------'
188        parse_gdb_log_file (file, None)
189
190else:
191    import lldb
192    if lldb.debugger:
193        # This initializer is being run from LLDB in the embedded command interpreter
194        # Add any commands contained in this module to LLDB
195        lldb.debugger.HandleCommand('command script add -f gdbremote.start_gdb_log start_gdb_log')
196        lldb.debugger.HandleCommand('command script add -f gdbremote.stop_gdb_log stop_gdb_log')
197        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'
198