def log(self, type, message, *args):
if type != 'info':
return super(SlimWSGIRequestHandler, self).log(type, message,
*args)
duration = datetime.now() - self._start_request
env = self.make_environ()
for url in (getattr(settings, 'STATIC_URL', None), settings.MEDIA_URL):
if not url:
continue
if self.path.startswith(url):
return
elif url.startswith('http:'):
if (('http://%s%s' % (env['HTTP_HOST'], self.path))
.startswith(url)):
return
for path in getattr(settings, 'DEVSERVER_IGNORED_PREFIXES', []):
if self.path.startswith(path):
return
format = ' (time: %.2fs; sql: %dms (%dq))'
queries = [
q for alias in connections
for q in connections[alias].queries
]
message += format % (
ms_from_timedelta(duration) / 1000,
sum(float(c.get('time', 0)) for c in queries) * 1000,
len(queries),
)
return super(SlimWSGIRequestHandler, self).log(type, message, *args)
def run(self, func, key, *args, **kwargs):
"""Profile a function and store its information."""
start_time = datetime.now()
value = func(*args, **kwargs)
end_time = datetime.now()
this_time = ms_from_timedelta(end_time - start_time)
values = {
'args': args,
'kwargs': kwargs,
'count': 0,
'hits': 0,
'time': 0.0
}
row = self.grouped.setdefault(key, {}).setdefault(func.__name__, values)
row['count'] += 1
row['time'] += this_time
if value is not None:
row['hits'] += 1
self.calls.setdefault(key, []).append({
'func': func,
'args': args,
'kwargs': kwargs,
'time': this_time,
'hit': value is not None,
#'stack': [s[1:] for s in inspect.stack()[2:]],
})
row = self.summary.setdefault(key, {'count': 0, 'time': 0.0, 'hits': 0})
row['count'] += 1
row['time'] += this_time
if value is not None:
row['hits'] += 1
return value
def log_message(self, format, *args):
duration = datetime.now() - self._start_request
env = self.get_environ()
for url in (getattr(settings, "STATIC_URL", None), settings.MEDIA_URL):
if not url:
continue
if self.path.startswith(url):
return
elif url.startswith("http:"):
if ("http://%s%s" % (env["HTTP_HOST"], self.path)).startswith(url):
return
for path in getattr(settings, "DEVSERVER_IGNORED_PREFIXES", []):
if self.path.startswith(path):
return
format += " (time: %.2fs; sql: %dms (%dq))"
args = list(args) + [
ms_from_timedelta(duration) / 1000,
sum(float(c.get("time", 0)) for c in connection.queries) * 1000,
len(connection.queries),
]
return WSGIRequestHandler.log_message(self, format, *args)
def execute(self, sql, params=()):
formatted_sql = sql % (params if isinstance(params, dict) else tuple(params))
if self.logger:
message = formatted_sql
if settings.DEVSERVER_FILTER_SQL:
if any(filter_.search(message) for filter_ in settings.DEVSERVER_FILTER_SQL):
message = None
if message is not None:
if settings.DEVSERVER_TRUNCATE_SQL:
message = truncate_sql(message, aggregates=settings.DEVSERVER_TRUNCATE_AGGREGATES)
message = sqlparse.format(message, reindent=True, keyword_case='upper')
self.logger.debug(message)
start = datetime.now()
try:
return super(DatabaseStatTracker, self).execute(sql, params)
finally:
stop = datetime.now()
duration = ms_from_timedelta(stop - start)
if self.logger and (not settings.DEVSERVER_SQL_MIN_DURATION
or duration > settings.DEVSERVER_SQL_MIN_DURATION):
if self.cursor.rowcount >= 0 and message is not None:
self.logger.debug('Found %s matching rows', self.cursor.rowcount, duration=duration)
if not (debug_toolbar or django_settings.DEBUG):
self.db.queries.append({
'sql': formatted_sql,
'time': duration,
})
def log_message(self, format, *args):
duration = datetime.now() - self._start_request
env = self.get_environ()
for url in (getattr(settings, 'STATIC_URL', None), settings.MEDIA_URL):
if not url:
continue
if self.path.startswith(url):
return
elif url.startswith('http:'):
if ('http://%s%s' % (env['HTTP_HOST'], self.path)).startswith(url):
return
for path in getattr(settings, 'DEVSERVER_IGNORED_PREFIXES', []):
if self.path.startswith(path):
return
format += " (time: %.2fs; sql: %dms (%dq))"
queries = [
q for alias in connections
for q in connections[alias].queries
]
args = list(args) + [
ms_from_timedelta(duration) / 1000,
sum(float(c.get('time', 0)) for c in queries) * 1000,
len(queries),
]
return WSGIRequestHandler.log_message(self, format, *args)
def executemany(self, sql, param_list):
start = datetime.now()
try:
return super(DatabaseStatTracker,
self).executemany(sql, param_list)
finally:
stop = datetime.now()
duration = ms_from_timedelta(stop - start)
if self.logger:
message = sqlparse.format(sql,
reindent=True,
keyword_case='upper')
message = 'Executed %s times\n%s' % message
self.logger.debug(message, duration=duration)
self.logger.debug('Found %s matching rows',
self.cursor.rowcount,
duration=duration,
id='query')
if not (debug_toolbar or settings.DEBUG):
self.db.queries.append({
'sql':
'%s times: %s' % (len(param_list), sql),
'time':
duration,
})
def log_message(self, format, *args):
duration = datetime.now() - self._start_request
env = self.get_environ()
for url in (getattr(settings, 'STATIC_URL', None), settings.MEDIA_URL):
if not url:
continue
if self.path.startswith(url):
return
elif url.startswith('http:'):
if ('http://%s%s' %
(env['HTTP_HOST'], self.path)).startswith(url):
return
for path in getattr(settings, 'DEVSERVER_IGNORED_PREFIXES', []):
if self.path.startswith(path):
return
format += " (time: %.2fs; sql: %dms (%dq))"
queries = [
q for alias in connections for q in connections[alias].queries
]
args = list(args) + [
ms_from_timedelta(duration) / 1000,
sum(float(c.get('time', 0)) for c in queries) * 1000,
len(queries),
]
return WSGIRequestHandler.log_message(self, format, *args)
def execute(self, sql, params=()):
formatted_sql = sql % (params if isinstance(params, dict) else tuple(params))
if self.logger:
message = formatted_sql
if settings.DEVSERVER_FILTER_SQL:
if any(filter_.search(message) for filter_ in settings.DEVSERVER_FILTER_SQL):
message = None
if message is not None:
if settings.DEVSERVER_TRUNCATE_SQL:
message = truncate_sql(message, aggregates=settings.DEVSERVER_TRUNCATE_AGGREGATES)
message = sqlparse.format(message, reindent=True, keyword_case='upper')
self.logger.debug(message)
start = datetime.now()
try:
return super(DatabaseStatTracker, self).execute(sql, params)
finally:
stop = datetime.now()
duration = ms_from_timedelta(stop - start)
if self.logger and (not settings.DEVSERVER_SQL_MIN_DURATION
or duration > settings.DEVSERVER_SQL_MIN_DURATION):
if self.cursor.rowcount >= 0 and message is not None:
self.logger.debug('Found %s matching rows', self.cursor.rowcount, duration=duration)
if not (debug_toolbar or django_settings.DEBUG):
self.db.queries.append({
'sql': formatted_sql,
'time': duration,
})
def execute(self, sql, params=()):
formatted_sql = sql % (params
if isinstance(params, dict) else tuple(params))
if self.logger and (not settings.DEVSERVER_SQL_MIN_DURATION
or duration > settings.DEVSERVER_SQL_MIN_DURATION):
message = formatted_sql
if settings.DEVSERVER_TRUNCATE_SQL:
message = truncate_sql(
message, aggregates=settings.DEVSERVER_TRUNCATE_AGGREGATES)
message = sqlparse.format(message,
reindent=True,
keyword_case='upper')
self.logger.debug(message)
start = datetime.now()
try:
return self.cursor.execute(sql, params)
finally:
stop = datetime.now()
duration = ms_from_timedelta(stop - start)
# stacktrace = tidy_stacktrace(traceback.extract_stack())
# template_info = None
# # TODO: can probably move this into utils
# cur_frame = sys._getframe().f_back
# try:
# while cur_frame is not None:
# if cur_frame.f_code.co_name == 'render':
# node = cur_frame.f_locals['self']
# if isinstance(node, Node):
# template_info = get_template_info(node.source)
# break
# cur_frame = cur_frame.f_back
# except:
# pass
# del cur_frame
if self.logger and (
not settings.DEVSERVER_SQL_MIN_DURATION
or duration > settings.DEVSERVER_SQL_MIN_DURATION):
if self.cursor.rowcount >= 0:
self.logger.debug('Found %s matching rows',
self.cursor.rowcount,
duration=duration)
self.db.queries.append({
'sql': formatted_sql,
'time': duration,
})
def run(self, func, key, logger, *args, **kwargs):
"""Profile a function and store its information."""
start_time = datetime.now()
value = func(*args, **kwargs)
end_time = datetime.now()
this_time = ms_from_timedelta(end_time - start_time)
values = {
'args': args,
'kwargs': kwargs,
'count': 0,
'hits': 0,
'time': 0.0
}
row = self.grouped.setdefault(key,
{}).setdefault(func.__name__, values)
row['count'] += 1
row['time'] += this_time
if value is not None:
row['hits'] += 1
self.calls.setdefault(key, []).append({
'func': func,
'args': args,
'kwargs': kwargs,
'time': this_time,
'hit': value is not None,
#'stack': [s[1:] for s in inspect.stack()[2:]],
})
row = self.summary.setdefault(key, {
'count': 0,
'time': 0.0,
'hits': 0
})
row['count'] += 1
row['time'] += this_time
if value is not None:
row['hits'] += 1
if logger:
logger.debug('%s("%s") %s (%s)',
func.__name__,
args[0],
'Miss' if value is None else 'Hit',
row['hits'],
duration=this_time)
return value
def log_message(self, format, *args):
duration = datetime.now() - self._start_request
# if self.path.startswith(settings.MEDIA_URL):
# return
for path in getattr(settings, 'DEVSERVER_IGNORED_PREFIXES', []):
if self.path.startswith(path):
return
format += " (time: %.2fs; sql: %dms (%dq))"
args = list(args) + [
ms_from_timedelta(duration) / 1000,
sum(float(c.get('time', 0)) for c in connection.queries) * 1000,
len(connection.queries),
]
return WSGIRequestHandler.log_message(self, format, *args)
def log_message(self, format, *args):
duration = datetime.now() - self._start_request
# if self.path.startswith(settings.MEDIA_URL):
# return
for path in getattr(settings, 'DEVSERVER_IGNORED_PREFIXES', []):
if self.path.startswith(path):
return
format += " (time: %.2fs; sql: %dms (%dq))"
args = list(args) + [
ms_from_timedelta(duration) / 1000,
sum(float(c.get('time', 0)) for c in connection.queries) * 1000,
len(connection.queries),
]
return WSGIRequestHandler.log_message(self, format, *args)
def run(self, func, key, logger, args, kwargs):
"""Profile a function and store its information."""
start_time = datetime.now()
value = func(*args, **kwargs)
end_time = datetime.now()
this_time = ms_from_timedelta(end_time - start_time)
values = {
'args': args,
'kwargs': kwargs,
'count': 0,
'hits': 0,
'time': 0.0
}
row = self.grouped.setdefault(key, {}).setdefault(func.__name__, values)
row['count'] += 1
row['time'] += this_time
if value is not None:
row['hits'] += 1
self.calls.setdefault(key, []).append({
'func': func,
'args': args,
'kwargs': kwargs,
'time': this_time,
'hit': value is not None,
#'stack': [s[1:] for s in inspect.stack()[2:]],
})
row = self.summary.setdefault(key, {'count': 0, 'time': 0.0, 'hits': 0})
row['count'] += 1
row['time'] += this_time
if value is not None:
row['hits'] += 1
if logger:
# Combine args and kwargs in a readable string.
formatted_args = ', '.join(repr(arg) for arg in args)
formatted_args += ', '.join(['{}={}'.format(name, truncatechars(repr(val), 150)) for name, val in kwargs.items()])
logger.debug('%s(%s) %s (%s)', func.__name__, formatted_args, 'Miss' if value is None else 'Hit', row['hits'], duration=this_time)
return value
def executemany(self, sql, param_list):
start = datetime.now()
try:
return self.cursor.executemany(sql, param_list)
finally:
stop = datetime.now()
duration = ms_from_timedelta(stop - start)
if self.logger:
message = sqlparse.format(sql, reindent=True, keyword_case='upper')
message = 'Executed %s times\n%s' % message
self.logger.debug(message, duration=duration)
self.logger.debug('Found %s matching rows', self.cursor.rowcount, duration=duration, id='query')
self.db.queries.append({
'sql': '%s times: %s' % (len(param_list), sql),
'time': duration,
})
def execute(self, sql, params=()):
formatted_sql = sql % (params if isinstance(params, dict) else tuple(params))
if self.logger and (not settings.DEVSERVER_SQL_MIN_DURATION
or duration > settings.DEVSERVER_SQL_MIN_DURATION):
message = formatted_sql
if settings.DEVSERVER_TRUNCATE_SQL:
message = truncate_sql(message, aggregates=settings.DEVSERVER_TRUNCATE_AGGREGATES)
message = sqlparse.format(message, reindent=True, keyword_case='upper')
self.logger.debug(message)
start = datetime.now()
try:
return self.cursor.execute(sql, params)
finally:
stop = datetime.now()
duration = ms_from_timedelta(stop - start)
# stacktrace = tidy_stacktrace(traceback.extract_stack())
# template_info = None
# # TODO: can probably move this into utils
# cur_frame = sys._getframe().f_back
# try:
# while cur_frame is not None:
# if cur_frame.f_code.co_name == 'render':
# node = cur_frame.f_locals['self']
# if isinstance(node, Node):
# template_info = get_template_info(node.source)
# break
# cur_frame = cur_frame.f_back
# except:
# pass
# del cur_frame
if self.logger and (not settings.DEVSERVER_SQL_MIN_DURATION
or duration > settings.DEVSERVER_SQL_MIN_DURATION):
if self.cursor.rowcount >= 0:
self.logger.debug('Found %s matching rows', self.cursor.rowcount, duration=duration)
self.db.queries.append({
'sql': formatted_sql,
'time': duration,
})
def executemany(self, sql, param_list):
start = datetime.now()
try:
return super(DatabaseStatTracker, self).executemany(sql, param_list)
finally:
stop = datetime.now()
duration = ms_from_timedelta(stop - start)
if self.logger:
message = sqlparse.format(sql, reindent=True, keyword_case='upper')
message = 'Executed %s times\n' % message
self.logger.debug(message, duration=duration)
self.logger.debug('Found %s matching rows', self.cursor.rowcount, duration=duration, id='query')
if version >= 1.6 or not (debug_toolbar or settings.DEBUG):
self.db.queries_log.append({
'sql': '%s times: %s' % (len(param_list), sql),
'time': duration,
})
def process_complete(self, request):
duration = datetime.now() - self.start
self.logger.info('Total time to render was %.2fs',
ms_from_timedelta(duration) / 1000)
def process_complete(self, request):
duration = datetime.now() - self.start
self.logger.info('Total time to render was %.2fs', ms_from_timedelta(duration) / 1000)
