Commits

João Pedro Francese committed a5d218f

Added profiling tools and @method_cache.

Comments (0)

Files changed (2)

inoa/utils/method_cache.py

+# -*- coding: utf-8 -*-
+
+def method_cache(seconds=0):
+    """
+    A `seconds` value of `0` means that we will not memcache it.
+    
+    If a result is cached on instance, return that first.  If that fails, check 
+    memcached. If all else fails, hit the db and cache on instance and in memcache.
+    
+    If `True` is passed to a `skip_method_cache` argument when calling the method, the cache is skipped.
+    
+    ** NOTE: Methods that return None are always "recached".
+    
+    Expanded from http://djangosnippets.org/snippets/2477/ on 2012-11-01
+    
+    
+    -----
+    Usage
+    ------
+    A very simple decorator that caches both on-class and in memcached:
+    
+    @method_cache(3600)
+    def some_intensive_method(self):
+        return # do intensive stuff`
+    Alternatively, if you just want to keep it per request and forgo memcaching, just do:
+    
+    @method_cache()
+    def some_intensive_method(self):
+        return # do intensive stuff`
+    """
+    
+    from hashlib import sha224
+    from django.core.cache import cache
+    
+    def inner_cache(method):
+        
+        def x(instance, *args, **kwargs):
+            key = sha224(str(method.__module__) + str(method.__name__) + \
+                str(instance.id) + str(args) + str(kwargs)).hexdigest()
+            
+            skip_method_cache = kwargs.pop('skip_method_cache', False)
+            if not skip_method_cache and hasattr(instance, key):
+                # has on class cache, return that
+                result = getattr(instance, key)
+            else:
+                result = cache.get(key)
+                
+                if skip_method_cache or result is None:
+                    # all caches failed, call the actual method
+                    result = method(instance, *args, **kwargs)
+                    
+                    # save to memcache and class attr
+                    if seconds and isinstance(seconds, int):
+                        cache.set(key, result, seconds)
+                    setattr(instance, key, result)
+            
+            return result
+        
+        return x
+    
+    return inner_cache

inoa/utils/profiling.py

+# -*- coding: utf-8 -*-
+
+from django.conf import settings
+from django.db import connection
+import logging
+import threading
+import time
+
+
+"""
+A collection of tools for simple profiling of blocks of code or entire methods.
+Measures elapsed time and queries performed within the block,
+and outputs to the Django built-in logging system.
+Messages are issued to the 'profiling' logger with the Debug level.
+
+Logging is disabled when DEBUG = False, unless the following entry is added to the project settings:
+ENABLE_PROFILER_IN_PRODUCTION = True
+
+If you want to send the profiler output to stdout, define a suitable logger/handler combination
+in your project settings. A minimal setup would be:
+
+LOGGING = {
+    'version': 1,
+    'handlers': {
+        'console': {
+            'level': 'DEBUG',
+            'class': 'logging.StreamHandler',
+        }
+    },
+    'loggers': {
+        'profiling': {
+            'level': 'DEBUG',
+            'handlers': ['console'],
+        },
+    },
+}
+
+"""
+
+profiler_enabled = settings.DEBUG or getattr(settings, 'ENABLE_PROFILER_IN_PRODUCTION', False)
+logger = logging.getLogger('profiling')
+
+def method_profiler(method):
+    """
+    Use as a decorator in any method. Usage:
+    
+    @method_profiler
+    def my_method(arg1, arg2):
+        ... # Do stuff you want to benchmark.
+    """
+    if not profiler_enabled:
+        return method
+    def wrapper(*args, **kwargs):
+        p = Profiler("%s.%s" % (method.__module__, method.__name__))
+        ret = method(*args, **kwargs)
+        p.stop()
+        return ret
+    wrapper.__name = method.__name__
+    wrapper.__module__ = method.__module__
+    return wrapper
+
+class Profiler(object):
+    """
+    Allows profiling of sections of code within a method. Usage:
+    
+    def my_method(arg1, arg2):
+        ... # Do stuff you don't care about.
+        profiler = Profiler()                 # Begins profiling. Note: accepts an optional name parameter.
+        ... # Do stuff you want to benchmark separately.
+        profiler.checkpoint()                 # Outputs partial time and queries.
+        ... # Do more stuff you want to benchmark separately.
+        profiler.checkpoint('Foo'd the bar')  # Outputs partial time and queries.
+        ... # Do a little bit more of stuff.
+        profiler.stop()                       # Outputs total time and queries.
+        ... # Do stuff you don't care about.
+    
+    You can obtain a reference to the latest instantiated profiler with Profiler.get_latest().
+    It creates a new profiler automatically if none exists. This is method is thread-safe.
+    """
+    local_store = threading.local()
+
+    @classmethod
+    def get_latest(cls):
+        return getattr(cls.local_store, 'latest_instance', cls())
+
+    def __init__(self, name=None):
+        self.name = name or ("profiler %s" % id(self))
+        self.start()
+
+    def start(self):
+        if not profiler_enabled:
+            return
+        self.t0 = time.time()
+        self.q0 = len(connection.queries) #@UndefinedVariable
+        self.t1, self.q1 = self.t0, self.q0
+        self.count = 0
+        self.__class__.latest_instance = self
+
+    def checkpoint(self, name=None):
+        if not profiler_enabled:
+            return
+        t2 = time.time()
+        q2 = len(connection.queries) #@UndefinedVariable
+        self.count += 1
+        name = name or self.count
+        logger.debug("Partial %s in %.04f seconds with %s queries." % (name, t2 - self.t1, q2 - self.q1))
+        self.t1, self.q1 = t2, q2
+        self.__class__.latest_instance = self
+
+    def stop(self):
+        if not profiler_enabled:
+            return
+        t2 = time.time()
+        q2 = len(connection.queries) #@UndefinedVariable
+        logger.debug("Executed %s in %.04f seconds with %s queries." % (self.name, t2 - self.t0, q2 - self.q0))