Added a 'gdbremote' python module that adds two commands: start_gdb_log and end_gdb_log.

When this is imported into your lldb using the "command script import /path/to/gdbremote.py"
these new commands are available within LLDB. 'start_gdb_log' will enable logging with 
timestamps for GDB remote packets, and 'stop_gdb_log' will then dump the details and
also a lot of packet timing data. This allows us to accurately track what packets are
taking up the most time when debugging (when using the ProcessGDBRemote debugging plug-in).

Also udpated the comments at the top of the cmdtemplate.py to show how to correctly import
the module from within LLDB.

llvm-svn: 149030

2 files changed, 188 insertions, 4 deletions

diff --git a/lldb/examples/python/cmdtemplate.py b/lldb/examples/python/cmdtemplate.py
index b7ad0a373de..33dee94fcfe 100644
--- a/lldb/examples/python/cmdtemplate.py
+++ b/lldb/examples/python/cmdtemplate.py
@@ -3,10 +3,10 @@
 #----------------------------------------------------------------------
 # Be sure to add the python path that points to the LLDB shared library.
 #
-# To use this in the embedded python interpreter using "lldb":
-#   % cd /path/containing/cmdtemplate.py
-#   % lldb
-#   (lldb) script import cmdtemplate
+# # To use this in the embedded python interpreter using "lldb" just
+# import it with the full path using the "command script import" 
+# command
+#   (lldb) command script import /path/to/cmdtemplate.py
 #
 # For the shells csh, tcsh:
 #   ( setenv PYTHONPATH /path/to/LLDB.framework/Resources/Python ; ./cmdtemplate.py )
diff --git a/lldb/examples/python/gdbremote.py b/lldb/examples/python/gdbremote.py
new file mode 100755
index 00000000000..59d7eb8082e
--- /dev/null
+++ b/lldb/examples/python/gdbremote.py
@@ -0,0 +1,184 @@
+#!/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)
+    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 = {}
+    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
+                else:
+                    packet_total_times[packet_name] = delta
+                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
+        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
+        print '#--------------------------------------------'
+        print '# Packet timing summary:'
+        print '#--------------------------------------------'
+        print '# Packet                   Time (sec) Percent'
+        print '#------------------------- ---------- -------'
+        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%%" % (item, packet_total_time, packet_percent)
+                else:
+                    print "  %24s %.6f   %.2f%%" % (item, packet_total_time, packet_percent)
+                    
+    
+    
+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'