|
1 | 1 | import re |
2 | 2 | import time |
3 | 3 | from pymongo import ASCENDING |
| 4 | +from pymongo.cursor import Cursor |
4 | 5 | from django.conf import settings |
5 | 6 | from django.db.backends.util import logger |
6 | 7 |
|
@@ -39,29 +40,56 @@ def __init__(self, collection, db_alias): |
39 | 40 | def __getattr__(self, attr): |
40 | 41 | return getattr(self.collection, attr) |
41 | 42 |
|
42 | | - def logging_wrapper(method, npositional=1): |
| 43 | + def profile_call(self, func, args=(), kwargs={}): |
| 44 | + start = time.time() |
| 45 | + retval = func(*args, **kwargs) |
| 46 | + duration = time.time() - start |
| 47 | + return duration, retval |
| 48 | + |
| 49 | + def log(self, op, duration, args, kwargs=None): |
| 50 | + args = ' '.join(str(arg) for arg in args) |
| 51 | + msg = '%s.%s (%.2f) %s' % (self.collection.name, op, duration, args) |
| 52 | + kwargs = dict((k, v) for k, v in kwargs.iteritems() if v) |
| 53 | + if kwargs: |
| 54 | + msg += ' %s' % kwargs |
| 55 | + if len(settings.DATABASES) > 1: |
| 56 | + msg = self.alias + '.' + msg |
| 57 | + logger.debug(msg, extra={'duration' : duration}) |
| 58 | + |
| 59 | + def find(self, *args, **kwargs): |
| 60 | + if not 'slave_okay' in kwargs and self.collection.slave_okay: |
| 61 | + kwargs['slave_okay'] = True |
| 62 | + return DebugCursor(self, self.collection, *args, **kwargs) |
| 63 | + |
| 64 | + def logging_wrapper(method): |
43 | 65 | def wrapper(self, *args, **kwargs): |
44 | | - if npositional is not None: |
45 | | - assert len(args) == npositional |
46 | | - start = time.time() |
47 | | - try: |
48 | | - result = getattr(self.collection, method)(*args, **kwargs) |
49 | | - finally: |
50 | | - duration = time.time() - start |
51 | | - msg = '%s.%s (%.3f) %s' % (self.collection.name, method, duration, |
52 | | - ' '.join(str(arg) for arg in args)) |
53 | | - if any(kwargs.itervalues()): |
54 | | - msg += ' %s' % kwargs |
55 | | - if len(settings.DATABASES) > 1: |
56 | | - msg = self.alias + '.' + msg |
57 | | - logger.debug(msg, extra={'duration' : duration}) |
58 | | - return result |
| 66 | + func = getattr(self.collection, method) |
| 67 | + duration, retval = self.profile_call(func, args, kwargs) |
| 68 | + self.log(method, duration, args, kwargs) |
| 69 | + return retval |
59 | 70 | return wrapper |
60 | 71 |
|
61 | | - find = logging_wrapper('find') |
62 | 72 | save = logging_wrapper('save') |
63 | 73 | remove = logging_wrapper('remove') |
64 | | - update = logging_wrapper('update', npositional=2) |
65 | | - map_reduce = logging_wrapper('map_reduce', npositional=None) |
| 74 | + update = logging_wrapper('update') |
| 75 | + map_reduce = logging_wrapper('map_reduce') |
| 76 | + inline_map_reduce = logging_wrapper('inline_map_reduce') |
66 | 77 |
|
67 | 78 | del logging_wrapper |
| 79 | + |
| 80 | +class DebugCursor(Cursor): |
| 81 | + def __init__(self, collection_wrapper, *args, **kwargs): |
| 82 | + self.collection_wrapper = collection_wrapper |
| 83 | + super(DebugCursor, self).__init__(*args, **kwargs) |
| 84 | + |
| 85 | + def _refresh(self): |
| 86 | + super_meth = super(DebugCursor, self)._refresh |
| 87 | + if self._Cursor__id is not None: |
| 88 | + return super_meth() |
| 89 | + # self.__id is None: first time the .find() iterator is entered. |
| 90 | + # find() profiling happens here. |
| 91 | + duration, retval = self.collection_wrapper.profile_call(super_meth) |
| 92 | + kwargs = {'limit': self._Cursor__limit, 'skip': self._Cursor__skip, |
| 93 | + 'sort': self._Cursor__ordering} |
| 94 | + self.collection_wrapper.log('find', duration, [self._Cursor__spec], kwargs) |
| 95 | + return retval |
0 commit comments