Add \timing special command.

pgcli/main.py

@@ -17,7 +17,7 @@ from pygments.lexers.sql import SqlLexer
 from .packages.tabulate import tabulate
 from .packages.expanded import expanded_table
 from .packages.pgspecial import (CASE_SENSITIVE_COMMANDS,
-        NON_CASE_SENSITIVE_COMMANDS, is_expanded_output)
+        NON_CASE_SENSITIVE_COMMANDS, is_expanded_output, is_timing_enabled)
 from .pgcompleter import PGCompleter
 from .pgtoolbar import PGToolbar
 from .pgstyle import PGStyle
@@ -26,6 +26,8 @@ from .pgbuffer import PGBuffer
 from .config import write_default_config, load_config
 from .key_bindings import pgcli_bindings
 
+from time import time
+
 try:
     from urlparse import urlparse
 except ImportError:
@@ -33,9 +35,9 @@ except ImportError:
 from getpass import getuser
 from psycopg2 import OperationalError
 
-from collections import deque, namedtuple
+from collections import namedtuple
 
-#Query tuples are used for maintaining history
+# Query tuples are used for maintaining history
 Query = namedtuple('Query', ['query', 'successful', 'mutating'])
 
 class PGCli(object):
@@ -87,7 +89,7 @@ class PGCli(object):
         root_logger.setLevel(level_map[log_level.upper()])
 
         root_logger.debug('Initializing pgcli logging.')
-        root_logger.debug('Log file "%s".' % log_file)
+        root_logger.debug('Log file %r.', log_file)
 
     def connect_uri(self, uri):
         uri = urlparse(uri)
@@ -178,16 +180,22 @@ class PGCli(object):
 
                 try:
                     logger.debug('sql: %r', document.text)
+                    successful = False
+                    start = time()
                     res = pgexecute.run(document.text)
+                    duration = time() - start
                     successful = True
                     output = []
+                    total = 0
                     for rows, headers, status in res:
                         logger.debug("headers: %r", headers)
                         logger.debug("rows: %r", rows)
                         logger.debug("status: %r", status)
+                        start = time()
                         output.extend(format_output(rows, headers, status))
+                        end = time()
+                        total += end - start
                         mutating = mutating or is_mutating(status)
-                    click.echo_via_pager('\n'.join(output))
                 except KeyboardInterrupt:
                     # Restart connection to the database
                     pgexecute.connect()
@@ -197,7 +205,12 @@ class PGCli(object):
                     logger.error("sql: %r, error: %r", document.text, e)
                     logger.error("traceback: %r", traceback.format_exc())
                     click.secho(str(e), err=True, fg='red')
-                    successful = False
+                else:
+                    click.echo_via_pager('\n'.join(output))
+
+                    if is_timing_enabled():
+                        print('Command Time:', duration)
+                        print('Render  Time:', total)
 
                 # Refresh the table names and column names if necessary.
                 if need_completion_refresh(document.text):
@@ -285,7 +298,7 @@ def need_completion_refresh(sql):
 def is_mutating(status):
     if not status:
         return False
-    
+
     mutating = ['insert', 'update', 'delete', 'alter', 'create', 'drop']
     return status.split(None, 1)[0].lower() in mutating
 

pgcli/packages/expanded.py

@@ -38,5 +38,6 @@ def expanded_table(rows, headers):
     for i, result in enumerate(results):
         output.append(get_separator(i, header_len, max_row_len))
         output.append(result)
+        output.append('\n')
 
     return ''.join(output)

pgcli/packages/pgspecial.py

@@ -23,6 +23,10 @@ use_expanded_output = False
 def is_expanded_output():
     return use_expanded_output
 
+timing_enabled = False
+def is_timing_enabled():
+    return timing_enabled
+
 def parse_special_command(sql):
     command, _, arg = sql.partition(' ')
     verbose = '+' in command
@@ -775,8 +779,15 @@ def expanded_output(cur, arg, verbose):
     global use_expanded_output
     use_expanded_output = not use_expanded_output
     message = u"Expanded display is "
-    message += u"on" if use_expanded_output else u"off"
-    return [(None, None, message + u".")]
+    message += u"on." if use_expanded_output else u"off."
+    return [(None, None, message)]
+
+def toggle_timing(cur, arg, verbose):
+    global timing_enabled
+    timing_enabled = not timing_enabled
+    message = "Timing is "
+    message += "on." if timing_enabled else "off."
+    return [(None, None, message)]
 
 CASE_SENSITIVE_COMMANDS = {
             '\?': (show_help, ['\?', 'Help on pgcli commands.']),
@@ -785,6 +796,7 @@ CASE_SENSITIVE_COMMANDS = {
             '\d': (describe_table_details, ['\d [pattern]', 'list or describe tables, views and sequences.']),
             '\dn': (list_schemas, ['\dn[+] [pattern]', 'list schemas']),
             '\\x': (expanded_output, ['\\x', 'Toggle expanded output.']),
+            '\\timing': (toggle_timing, ['\\timing', 'Toggle timing of commands.']),
             '\dt': ('''SELECT n.nspname as "Schema", c.relname as "Name", CASE
             c.relkind WHEN 'r' THEN 'table' WHEN 'v' THEN 'view' WHEN 'm' THEN
             'materialized view' WHEN 'i' THEN 'index' WHEN 'S' THEN 'sequence'