timeout caused by long-running SummaryView queries

[smcoll]

Requests to the summary url were timing out, and i found that the culprit was some long-running queries. In my particular case, there are over 9000 Request records and approximately 79,000 SQLQuery records. i did a simple inspection on how long each part of the template context took to compute in this particular case, and pasted the results here:

• num_requests: (9357) 0.004221200942993164 seconds
• num_profiles: (1903) 0.0025479793548583984 seconds
• avg_num_queries: (8.44) 65.66700839996338 seconds
• avg_time_spent_on_queries: (417) 65.6366651058197 seconds
• avg_overall_time: (985) 0.011739730834960938 seconds
• longest_queries_by_view: 0.030451536178588867 seconds
• most_time_spent_in_db: 262.45237922668457 seconds
• most_queries: 327.8772532939911 seconds

As you can see, some of the computations were very expensive. Perhaps there are more efficient ways of getting the same results.

Methodology:

>>> import time
>>> from silk.views.summary import *
>>> filters = []
>>> class Timer:
...     def __enter__(self):
...         self.start = time.time()
...         return self
...     
...     def __exit__(self, *args):
...         self.end = time.time()
...         self.interval = self.end - self.start
...         print('{} seconds'.format(self.interval))
... 
>>> with Timer() as t:
...     models.Request.objects.filter(*filters).count()
... 
9357
0.004221200942993164 seconds
>>> with Timer() as t:
...     models.Profile.objects.filter(*filters).count()
... 
1903
0.0025479793548583984 seconds
>>> with Timer() as t:
...     taken__aggregate = models.Request.objects.filter(*filters).annotate(time_spent=Sum('queries__time_taken')).aggregate(num=Avg('time_spent'))
...     print(queries__aggregate['num'])
... 
417.649274277396
65.6366651058197 seconds
>>> with Timer() as t:
...     queries__aggregate = models.Request.objects.filter(*filters).annotate(num_queries=Count('queries')).aggregate(num=Avg('num_queries'))
...     print(taken__aggregate['num'])
... 
8.445287454584314
65.6499011516571 seconds
>>> with Timer() as t:
...     taken__aggregate = models.Request.objects.filter(*filters).annotate(time_spent=Sum('time_taken')).aggregate(num=Avg('time_spent'))
...     print(taken__aggregate['num'])
... 
985.539336600959
0.011739730834960938 seconds
>>> with Timer() as t:
...     values_list = models.Request.objects.filter(*filters).values_list("view_name").annotate(max=Max('time_taken')).order_by('-max')[:5]
...     requests = []
...     for view_name, _ in values_list:
...         request = models.Request.objects.filter(view_name=view_name, *filters).order_by('-time_taken')[0]
...         requests.append(request)
... 
0.030451536178588867 seconds
>>> with Timer() as t:
...     values_list = models.Request.objects.filter(*filters).values_list('view_name').annotate(t=Sum('queries__time_taken')).filter(t__gte=0).order_by('-t')[:5]
...     requests = []
...     for view, _ in values_list:
...         r = models.Request.objects.filter(view_name=view, *filters).annotate(t=Sum('queries__time_taken')).order_by('-t')[0]
...         requests.append(r)
... 
262.45237922668457 seconds
>>> with Timer() as t:
...     queryset = models.Request.objects.filter(*filters).values_list('view_name').annotate(t=Count('queries')).order_by('-t')[:5]
...     views = [r[0] for r in queryset[:6]]
...     requests = []
...     for view in views:
...         try:
...             r = models.Request.objects.filter(view_name=view, *filters).annotate(t=Count('queries')).order_by('-t')[0]
...             requests.append(r)
...         except IndexError:
...             pass
... 
327.8772532939911 seconds
>>>