How to profile middleware?

[joshvillbrandt]

Hi there! I've been able to install django-silk and profile some of my application layer code using the embedded profile viewer. Super neat!

Unfortunately, it looks like the majority of the time is being spent outside of my application code, so I'd like to profile the middleware. I'm attempting to utilize the dynamic profiling to hook this up. I've tried a few iterations of this; most of them look like this:

# Silk (Performance Profiling)
SILKY_AUTHENTICATION = True  # User must login
SILKY_AUTHORISATION = True  # User must have permissions
SILKY_PYTHON_PROFILER = True
SILKY_META = True
SILKY_PYTHON_PROFILER_BINARY = True
SILKY_PYTHON_PROFILER_RESULT_PATH = '/tmp/'
SILKY_INTERCEPT_PERCENT = 100
# SILKY_DYNAMIC_PROFILING = [{
#     'module': 'rest_framework.views',
#     'function': 'APIView.dispatch'
# }]
SILKY_DYNAMIC_PROFILING = [{
    'module': 'django.core.handlers.base',
    'function': 'BaseHandler.get_response'
}]

This configuration yields the following error on requests:

Traceback (most recent call last):
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/silk/profiling/profiler.py", line 158, in wrapped_target
    self._start_queries()
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/silk/profiling/profiler.py", line 79, in _start_queries
    self._queries_before = self._query_identifiers_from_collector()
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/silk/profiling/profiler.py", line 75, in _query_identifiers_from_collector
    return [x for x in DataCollector().queries]
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/silk/collector.py", line 69, in queries
    return self._get_objects(TYP_QUERIES)
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/silk/collector.py", line 79, in _get_objects
    'Attempt to access %s without initialisation.' % typ
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/silk/collector.py", line 104, in _raise_not_configured
    raise SilkNotConfigured(err + ' Is the middleware installed correctly?')
SilkNotConfigured: Attempt to access queries without initialisation. Is the middleware installed correctly?
Traceback (most recent call last):
  File "/usr/lib/python2.7/wsgiref/handlers.py", line 85, in run
    self.result = application(self.environ, self.start_response)
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/contrib/staticfiles/handlers.py", line 63, in __call__
    return self.application(environ, start_response)
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/wsgi.py", line 157, in __call__
    response = self.get_response(request)
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/silk/profiling/profiler.py", line 158, in wrapped_target
    self._start_queries()
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/silk/profiling/profiler.py", line 79, in _start_queries
    self._queries_before = self._query_identifiers_from_collector()
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/silk/profiling/profiler.py", line 75, in _query_identifiers_from_collector
    return [x for x in DataCollector().queries]
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/silk/collector.py", line 69, in queries
    return self._get_objects(TYP_QUERIES)
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/silk/collector.py", line 79, in _get_objects
    'Attempt to access %s without initialisation.' % typ
  File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/silk/collector.py", line 104, in _raise_not_configured
    raise SilkNotConfigured(err + ' Is the middleware installed correctly?')
SilkNotConfigured: Attempt to access queries without initialisation. Is the middleware installed correctly?
[28/Aug/2018 16:07:59] "GET /secret/sauce HTTP/1.1" 500 59

Actually, it seems to work once and then that error is thrown. 🤷‍♂️

I've been using a stack trace of a nominal request to try and figure out where to inject the profiling:

File "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
    self.__bootstrap_inner()
File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
File "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
File "/usr/lib/python2.7/SocketServer.py", line 596, in process_request_thread
    self.finish_request(request, client_address)
File "/usr/lib/python2.7/SocketServer.py", line 331, in finish_request
    self.RequestHandlerClass(request, client_address, self)
File "/usr/lib/python2.7/SocketServer.py", line 652, in __init__
    self.handle()
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/servers/basehttp.py", line 155, in handle
    handler.run(self.server.get_app())
File "/usr/lib/python2.7/wsgiref/handlers.py", line 85, in run
    self.result = application(self.environ, self.start_response)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/contrib/staticfiles/handlers.py", line 63, in __call__
    return self.application(environ, start_response)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/wsgi.py", line 157, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/base.py", line 124, in get_response
    response = self._middleware_chain(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/utils/deprecation.py", line 140, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/utils/deprecation.py", line 140, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/utils/deprecation.py", line 140, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/utils/deprecation.py", line 140, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/utils/deprecation.py", line 140, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/utils/deprecation.py", line 140, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/utils/deprecation.py", line 140, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/utils/deprecation.py", line 140, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/utils/deprecation.py", line 140, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/utils/deprecation.py", line 140, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/utils/deprecation.py", line 140, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/app/settings.py", line 46, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/utils/deprecation.py", line 140, in __call__
    response = self.get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/core/handlers/base.py", line 185, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/Django-1.11.13-py2.7.egg/django/views/decorators/csrf.py", line 58, in wrapped_view
    return view_func(*args, **kwargs)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/djangorestframework-3.6.2-py2.7.egg/rest_framework/viewsets.py", line 83, in view
    return self.dispatch(request, *args, **kwargs)
File "/home/josh/repos/django-app/env/local/lib/python2.7/site-packages/djangorestframework-3.6.2-py2.7.egg/rest_framework/views.py", line 480, in dispatch
    response = handler(request, *args, **kwargs)
File "/home/josh/repos/django-app/app/urls.py", line 96, in history
    for line in traceback.format_stack():
[28/Aug/2018 15:44:17] "GET /secret/sauce HTTP/1.1" 200 6200

So I'm stuck at the moment. Any suggestions on how I can profile essentially the whole request?

[joshvillbrandt]

No longer waiting on this.

[KoalaTea]

I tried this as well and ended up in the same spot. I am wondering what your solution was and how you came to figuring out where the bottleneck was.