examples/python/gdbremote.py

#!/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] [<LOGFILEPATH>]"
    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
    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 <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:
        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'