[gnome-music/wip/rate-limit: 5/5] Simplify logs and record elapsed time for each function

[Vadim Rutkovsky <vrutkovsky src gnome org>]

commit fbfeeae2bbd381cc86d563bd736b74a2d67a87bb
Author: Vadim Rutkovsky <vrutkovs redhat com>
Date:   Tue Jun 16 17:53:43 2015 +0200

    Simplify logs and record elapsed time for each function

 gnomemusic/__init__.py |    8 ++++++--
 1 files changed, 6 insertions(+), 2 deletions(-)
---
diff --git a/gnomemusic/__init__.py b/gnomemusic/__init__.py
index aa83295..a1af076 100644
--- a/gnomemusic/__init__.py
+++ b/gnomemusic/__init__.py
@@ -43,11 +43,15 @@ def log(fn):
         module = fn.__module__
         params = ", ".join(map(repr, chain(v, k.values())))
 
-        logger.debug("%s%s.%s(%s)", '|' * tabbing, module, name, params)
         tabbing += 1
+        start = time.time()
         retval = fn(*v, **k)
+        elapsed = time.time() - start
         tabbing -= 1
-        logger.debug("%sreturned %s", '|' * tabbing, retval)
+        elapsed_time = ''
+        if elapsed > 0.5:
+            elapsed_time = ', took %02f' % elapsed
+        logger.debug("%s%s.%s(%s), returned %s%s", '|' * tabbing, module, name, params, retval, elapsed_time)
 
         return retval
     return wrapped