From ef2f642ffed58ffe291c636d3c906679796d1426 Mon Sep 17 00:00:00 2001
From: nvbn <nvbn.rm@gmail.com>
Date: Thu, 23 Jul 2015 06:09:57 +0300
Subject: [PATCH] #N/A Log common operations time

---
 thefuck/logs.py | 12 +++++++++++-
 thefuck/main.py | 51 +++++++++++++++++++++++++------------------------
 2 files changed, 37 insertions(+), 26 deletions(-)

diff --git a/thefuck/logs.py b/thefuck/logs.py
index 7e98b2da..9cfdad4e 100644
--- a/thefuck/logs.py
+++ b/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)
diff --git a/thefuck/main.py b/thefuck/main.py
index 4d92fb22..3668cad5 100644
--- a/thefuck/main.py
+++ b/thefuck/main.py
@@ -80,25 +80,25 @@ 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)
 
-    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'),
-                             result.stderr.read().decode('utf-8'))
+    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'),
+                                 result.stderr.read().decode('utf-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)
-            if rule.match(command, settings):
-                return rule
+            with logs.debug_time(u'Trying rule: {};'.format(rule.name),
+                                 settings):
+                if rule.match(command, settings):
+                    return rule
         except Exception:
             logs.rule_failed(rule, sys.exc_info(), settings)
 
@@ -134,25 +134,26 @@ def main():
     colorama.init()
     user_dir = setup_user_dir()
     settings = conf.get_settings(user_dir)
-    logs.debug(u'Run with settings: {}'.format(pformat(settings)), settings)
+    with logs.debug_time('Total', settings):
+        logs.debug(u'Run with settings: {}'.format(pformat(settings)), settings)
 
-    command = get_command(settings, sys.argv)
-    if command:
-        logs.debug(u'Received stdout: {}'.format(command.stdout), settings)
-        logs.debug(u'Received stderr: {}'.format(command.stderr), settings)
+        command = get_command(settings, sys.argv)
+        if command:
+            logs.debug(u'Received stdout: {}'.format(command.stdout), settings)
+            logs.debug(u'Received stderr: {}'.format(command.stderr), settings)
 
-        rules = get_rules(user_dir, settings)
-        logs.debug(
-            u'Loaded rules: {}'.format(', '.join(rule.name for rule in rules)),
-            settings)
+            rules = get_rules(user_dir, settings)
+            logs.debug(
+                u'Loaded rules: {}'.format(', '.join(rule.name for rule in rules)),
+                settings)
 
-        matched_rule = get_matched_rule(command, rules, settings)
-        if matched_rule:
-            logs.debug(u'Matched rule: {}'.format(matched_rule.name), settings)
-            run_rule(matched_rule, command, settings)
-            return
+            matched_rule = get_matched_rule(command, rules, settings)
+            if matched_rule:
+                logs.debug(u'Matched rule: {}'.format(matched_rule.name), settings)
+                run_rule(matched_rule, command, settings)
+                return
 
-    logs.failed('No fuck given', settings)
+        logs.failed('No fuck given', settings)
 
 
 def print_alias():