utils: Add time_logger() context manager

mopidy_spotify/library.py

@@ -1,14 +1,13 @@
 from __future__ import unicode_literals
 
 import logging
-import time
 import urllib
 
 from mopidy import backend, models
 
 import spotify
 
-from mopidy_spotify import countries, translator
+from mopidy_spotify import countries, translator, utils
 
 
 logger = logging.getLogger(__name__)
@@ -146,7 +145,8 @@ def lookup(self, uri):
             elif sp_link.type is spotify.LinkType.ALBUM:
                 return list(self._lookup_album(sp_link))
             elif sp_link.type is spotify.LinkType.ARTIST:
-                return list(self._lookup_artist(sp_link))
+                with utils.time_logger('Artist lookup'):
+                    return list(self._lookup_artist(sp_link))
             elif sp_link.type is spotify.LinkType.PLAYLIST:
                 return list(self._lookup_playlist(sp_link))
             elif sp_link.type is spotify.LinkType.STARRED:
@@ -178,8 +178,6 @@ def _lookup_album(self, sp_link):
                 yield track
 
     def _lookup_artist(self, sp_link):
-        start = time.time()
-
         sp_artist = sp_link.as_artist()
         sp_artist_browser = sp_artist.browse(
             type=spotify.ArtistBrowserType.NO_TRACKS)
@@ -204,8 +202,6 @@ def _lookup_artist(self, sp_link):
                 if track is not None:
                     yield track
 
-        logger.debug('Artists looked up in %.3fs', time.time() - start)
-
     def _lookup_playlist(self, sp_link):
         sp_playlist = sp_link.as_playlist()
         sp_playlist.load()

mopidy_spotify/playlists.py

@@ -1,13 +1,12 @@
 from __future__ import unicode_literals
 
 import logging
-import time
 
 from mopidy import backend
 
 import spotify
 
-from mopidy_spotify import translator
+from mopidy_spotify import translator, utils
 
 
 logger = logging.getLogger(__name__)
@@ -58,12 +57,10 @@ def playlists(self):
         # XXX We should just return light-weight Ref objects here, but Mopidy's
         # core and backend APIs must be changed first.
 
-        start = time.time()
-        result = (
-            list(self._get_starred_playlist()) +
-            list(self._get_flattened_playlists()))
-        logger.debug('Playlists fetched in %.3fs', time.time() - start)
-        return result
+        with utils.time_logger('Playlist fetch'):
+            return (
+                list(self._get_starred_playlist()) +
+                list(self._get_flattened_playlists()))
 
     def _get_starred_playlist(self):
         if self._backend._session is None:

mopidy_spotify/utils.py

@@ -0,0 +1,15 @@
+from __future__ import unicode_literals
+
+import contextlib
+import logging
+import time
+
+
+logger = logging.getLogger(__name__)
+
+
+@contextlib.contextmanager
+def time_logger(name):
+    start = time.time()
+    yield
+    logger.debug('%s took %dms', name, (time.time() - start) * 1000)

tests/test_utils.py

@@ -0,0 +1,12 @@
+from __future__ import unicode_literals
+
+import re
+
+from mopidy_spotify import utils
+
+
+def test_time_logger(caplog):
+    with utils.time_logger('task'):
+        pass
+
+    assert re.match('.*task took \d+ms.*', caplog.text())