#N/A Log common operations time

thefuck/logs.py

@@ -1,4 +1,5 @@
-from pprint import pformat
+from contextlib import contextmanager
+from datetime import datetime
 import sys
 from traceback import format_exception
 import colorama
@@ -62,3 +63,12 @@ def debug(msg, settings):
             reset=color(colorama.Style.RESET_ALL, settings),
             blue=color(colorama.Fore.BLUE, settings),
             bold=color(colorama.Style.BRIGHT, settings)))
+
+
+@contextmanager
+def debug_time(msg, settings):
+    started = datetime.now()
+    try:
+        yield
+    finally:
+        debug('{} took: {}'.format(msg, datetime.now() - started), settings)

thefuck/main.py

@@ -80,12 +80,11 @@ def get_command(settings, args):
         return
 
     script = shells.from_shell(script)
-    logs.debug(u'Call: {}'.format(script), settings)
-
     env = dict(os.environ)
     env.update(settings.env)
-    logs.debug(u'Executing with env: {}'.format(env), settings)
 
+    with logs.debug_time(u'Call: {}; with env: {};'.format(script, env),
+                         settings):
         result = Popen(script, shell=True, stdout=PIPE, stderr=PIPE, env=env)
         if wait_output(settings, result):
             return types.Command(script, result.stdout.read().decode('utf-8'),
@@ -96,7 +95,8 @@ def get_matched_rule(command, rules, settings):
     """Returns first matched rule for command."""
     for rule in rules:
         try:
-            logs.debug(u'Trying rule: {}'.format(rule.name), settings)
+            with logs.debug_time(u'Trying rule: {};'.format(rule.name),
+                                 settings):
                 if rule.match(command, settings):
                     return rule
         except Exception:
@@ -134,6 +134,7 @@ def main():
     colorama.init()
     user_dir = setup_user_dir()
     settings = conf.get_settings(user_dir)
+    with logs.debug_time('Total', settings):
         logs.debug(u'Run with settings: {}'.format(pformat(settings)), settings)
 
         command = get_command(settings, sys.argv)