Merge lp:~james-w/python-oops-tools/recent-oopses into lp:python-oops-tools

Proposed by James Westby on 2012-12-06
Status: Merged
Approved by: James Westby on 2012-12-06
Approved revision: no longer in the source branch.
Merged at revision: 51
Proposed branch: lp:~james-w/python-oops-tools/recent-oopses
Merge into: lp:python-oops-tools
Diff against target: 151 lines (+114/-2)
3 files modified
src/oopstools/oops/migrations/0023_add_prefix_date_index.py (+92/-0)
src/oopstools/oops/test/test_report.py (+19/-1)
src/oopstools/oops/views.py (+3/-1)
To merge this branch: bzr merge lp:~james-w/python-oops-tools/recent-oopses
Reviewer Review Type Date Requested Status
Richard Harding (community) 2012-12-06 Approve on 2012-12-06
Review via email: mp+138356@code.launchpad.net

Commit message

Improve the query performance of the recent oopses view.

Firstly the planner was picking a difficult plan because of the join, but
we expect few prefixes per-report, so getting the prefix ids first, then
using a simple IN rather than a join leads to an easier plan.

Once the easier plan is in use the indexes still aren't that helpful, as
it chooses the index on 'date', but it still has to filter based on the
prefix, so we add an index on (prefix_id, date) so that it can select the
right rows as quickly as possible.

Lastly lazy evaluation was causing 50 queries for the 'oopsinfestation'
info, so we use select_related() to include that in the main query.

There's a test that we do 1 query for the last point, but no test for
the speed of the query.

Description of the change

Hi,

The recent oops views are performing terribly, because the production
data makes the query really slow.

Firstly, lazy evaluation means that we are doing 50 queries for the
oopsinfestation info at render time. I've added a select_related
to avoid that.

Secondly, the query is just currently slow.

We start of with a plan like: (using some data generated locally rather
than the real data, but the plan matches)

 Limit (cost=5.37..537.81 rows=50 width=2017) (actual time=0.212..145.954 rows=50 loops=1)
   -> Nested Loop (cost=5.37..214534.09 rows=20146 width=2017) (actual time=0.210..145.942 rows=50 loops=1)
         -> Nested Loop (cost=5.37..133934.13 rows=20185 width=1978) (actual time=0.175..145.566 rows=50 loops=1)
               Join Filter: (oops_prefix.id = oops_oops.prefix_id)
               -> Index Scan Backward using oops_oops_date on oops_oops (cost=0.00..115751.56 rows=1211106 width=1978) (actual time=0.049..59.086 rows=216002 loops=1)
               -> Materialize (cost=5.37..15.98 rows=1 width=8) (actual time=0.000..0.000 rows=1 loops=216002)
                     -> Hash Join (cost=5.37..15.98 rows=1 width=8) (actual time=0.109..0.111 rows=1 loops=1)
                           Hash Cond: (oops_report_prefixes.prefix_id = oops_prefix.id)
                           -> Bitmap Heap Scan on oops_report_prefixes (cost=4.33..14.88 rows=10 width=4) (actual time=0.045..0.045 rows=1 loops=1)
                                 Recheck Cond: (report_id = 7)
                                 -> Bitmap Index Scan on oops_report_prefixes_report_id (cost=0.00..4.33 rows=10 width=0) (actual time=0.018..0.018 rows=2 loops=1)
                                       Index Cond: (report_id = 7)
                           -> Hash (cost=1.02..1.02 rows=2 width=4) (actual time=0.033..0.033 rows=10 loops=1)
                                 Buckets: 1024 Batches: 1 Memory Usage: 1kB
                                 -> Seq Scan on oops_prefix (cost=0.00..1.02 rows=2 width=4) (actual time=0.017..0.022 rows=10 loops=1)
         -> Index Scan using oops_infestation_pkey on oops_infestation (cost=0.00..3.98 rows=1 width=39) (actual time=0.006..0.007 rows=1 loops=50)
               Index Cond: (id = oops_oops.oopsinfestation_id)
 Total runtime: 146.193 ms

This is doing a join that is making the plan fairly costly, but we are typically only going to
be joining for one or a few rows of the other table. If we instead issue a query for the
few rows, the use a simple IN for the foreign key relation we can get a much simpler
query (again with local data):

 Limit (cost=0.00..991.15 rows=50 width=2017) (actual time=0.061..65.703 rows=50 loops=1)
   -> Nested Loop (cost=0.00..162944.88 rows=8220 width=2017) (actual time=0.060..65.697 rows=50 loops=1)
         -> Index Scan Backward using oops_oops_date on oops_oops (cost=0.00..118756.07 rows=8236 width=1978) (actual time=0.034..65.311 rows=50 loops=1)
               Filter: (prefix_id = 9)
         -> Index Scan using oops_infestation_pkey on oops_infestation (cost=0.00..5.35 rows=1 width=39) (actual time=0.006..0.006 rows=1 loops=50)
               Index Cond: (id = oops_oops.oopsinfestation_id)
 Total runtime: 65.784 ms

which has a worse estimate, but better actual. I've tested this version of the query on production,
and it has the same characteristic (and drops the actual from 0.158..31828.728 to 80.303..459.145).

Next we see that the index scan on oops_oops_date is the majority of the time, and it has
a filter, so we try adding an index that also includes the filter criteria:

 Limit (cost=0.00..342.44 rows=50 width=2017) (actual time=0.085..0.531 rows=50 loops=1)
   -> Nested Loop (cost=0.00..56297.00 rows=8220 width=2017) (actual time=0.084..0.519 rows=50 loops=1)
         -> Index Scan Backward using oops_oops_prefix_date on oops_oops (cost=0.00..12108.20 rows=8236 width=1978) (actual time=0.059..0.153 rows=50 loops=1)
               Index Cond: (prefix_id = 9)
         -> Index Scan using oops_infestation_pkey on oops_infestation (cost=0.00..5.35 rows=1 width=39) (actual time=0.006..0.006 rows=1 loops=50)
               Index Cond: (id = oops_oops.oopsinfestation_id)
 Total runtime: 0.614 ms

This is much better, with the estimate now being lower than the starting query, and
the actual being far far quicker. I can't test this on production, so it may not
have the same effect there, but I think it's worth a try.

Overall I think these changes should significantly improve the render time on production,
and if it isn't a sufficient improvement we can see where the problem areas remain.

This is my first time trying query optimisation, so I may have made some glaring errors,
please point them out if I have.

Thanks,

James

To post a comment you must log in.
Richard Harding (rharding) :
review: Approve
51. By James Westby on 2012-12-06

Improve the query performance of the recent oopses view.

Firstly the planner was picking a difficult plan because of the join, but
we expect few prefixes per-report, so getting the prefix ids first, then
using a simple IN rather than a join leads to an easier plan.

Once the easier plan is in use the indexes still aren't that helpful, as
it chooses the index on 'date', but it still has to filter based on the
prefix, so we add an index on (prefix_id, date) so that it can select the
right rows as quickly as possible.

Lastly lazy evaluation was causing 50 queries for the 'oopsinfestation'
info, so we use select_related() to include that in the main query.

There's a test that we do 1 query for the last point, but no test for
the speed of the query.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== added file 'src/oopstools/oops/migrations/0023_add_prefix_date_index.py'
2--- src/oopstools/oops/migrations/0023_add_prefix_date_index.py 1970-01-01 00:00:00 +0000
3+++ src/oopstools/oops/migrations/0023_add_prefix_date_index.py 2012-12-06 02:00:27 +0000
4@@ -0,0 +1,92 @@
5+# encoding: utf-8
6+import datetime
7+from south.db import db
8+from south.v2 import SchemaMigration
9+from django.db import models
10+
11+
12+class Migration(SchemaMigration):
13+
14+ def forwards(self, orm):
15+
16+ # Adding index on 'Oops', fields ['prefix_id', 'date']
17+ db.create_index('oops_oops', ['prefix_id', 'date'])
18+
19+ def backwards(self, orm):
20+
21+ # Removing index on 'Oops', fields ['prefix_id', 'date']
22+ db.delete_index('oops_oops', ['prefix_id', 'date'])
23+
24+ models = {
25+ 'oops.appinstance': {
26+ 'Meta': {'object_name': 'AppInstance'},
27+ 'id': ('django.db.models.fields.AutoField', [], {'primary_key': 'True'}),
28+ 'title': ('django.db.models.fields.CharField', [], {'unique': 'True', 'max_length': '100'})
29+ },
30+ 'oops.classification': {
31+ 'Meta': {'object_name': 'Classification'},
32+ 'id': ('django.db.models.fields.AutoField', [], {'primary_key': 'True'}),
33+ 'title': ('django.db.models.fields.CharField', [], {'unique': 'True', 'max_length': '100'})
34+ },
35+ 'oops.dboopsrootdirectory': {
36+ 'Meta': {'object_name': 'DBOopsRootDirectory'},
37+ 'id': ('django.db.models.fields.AutoField', [], {'primary_key': 'True'}),
38+ 'last_date': ('django.db.models.fields.DateField', [], {'null': 'True'}),
39+ 'last_oops': ('django.db.models.fields.CharField', [], {'max_length': '200', 'null': 'True'}),
40+ 'root_dir': ('django.db.models.fields.CharField', [], {'unique': 'True', 'max_length': '200'})
41+ },
42+ 'oops.infestation': {
43+ 'Meta': {'unique_together': "(('exception_type', 'exception_value'),)", 'object_name': 'Infestation'},
44+ 'bug': ('django.db.models.fields.PositiveIntegerField', [], {'null': 'True'}),
45+ 'exception_type': ('django.db.models.fields.CharField', [], {'max_length': '100'}),
46+ 'exception_value': ('django.db.models.fields.CharField', [], {'max_length': '1000'}),
47+ 'id': ('django.db.models.fields.AutoField', [], {'primary_key': 'True'})
48+ },
49+ 'oops.oops': {
50+ 'Meta': {'object_name': 'Oops'},
51+ 'appinstance': ('django.db.models.fields.related.ForeignKey', [], {'to': "orm['oops.AppInstance']"}),
52+ 'classification': ('django.db.models.fields.related.ForeignKey', [], {'to': "orm['oops.Classification']", 'null': 'True'}),
53+ 'date': ('django.db.models.fields.DateTimeField', [], {'db_index': 'True'}),
54+ 'duration': ('django.db.models.fields.FloatField', [], {'null': 'True'}),
55+ 'http_method': ('django.db.models.fields.CharField', [], {'max_length': '10', 'null': 'True'}),
56+ 'id': ('django.db.models.fields.AutoField', [], {'primary_key': 'True'}),
57+ 'informational': ('django.db.models.fields.NullBooleanField', [], {'null': 'True', 'blank': 'True'}),
58+ 'is_bot': ('django.db.models.fields.NullBooleanField', [], {'db_index': 'True', 'null': 'True', 'blank': 'True'}),
59+ 'is_local_referrer': ('django.db.models.fields.NullBooleanField', [], {'db_index': 'True', 'null': 'True', 'blank': 'True'}),
60+ 'most_expensive_statement': ('django.db.models.fields.CharField', [], {'max_length': '200', 'null': 'True', 'db_index': 'True'}),
61+ 'oopsid': ('django.db.models.fields.CharField', [], {'unique': 'True', 'max_length': '200'}),
62+ 'oopsinfestation': ('django.db.models.fields.related.ForeignKey', [], {'to': "orm['oops.Infestation']"}),
63+ 'pageid': ('django.db.models.fields.CharField', [], {'max_length': '500'}),
64+ 'pathname': ('django.db.models.fields.CharField', [], {'unique': 'True', 'max_length': '200'}),
65+ 'prefix': ('django.db.models.fields.related.ForeignKey', [], {'to': "orm['oops.Prefix']"}),
66+ 'referrer': ('django.db.models.fields.URLField', [], {'max_length': '500', 'null': 'True'}),
67+ 'statements_count': ('django.db.models.fields.PositiveIntegerField', [], {}),
68+ 'time_is_estimate': ('django.db.models.fields.NullBooleanField', [], {'null': 'True', 'blank': 'True'}),
69+ 'total_time': ('django.db.models.fields.PositiveIntegerField', [], {}),
70+ 'url': ('django.db.models.fields.URLField', [], {'max_length': '500', 'null': 'True', 'db_index': 'True'}),
71+ 'user_agent': ('django.db.models.fields.CharField', [], {'max_length': '200', 'null': 'True'})
72+ },
73+ 'oops.prefix': {
74+ 'Meta': {'object_name': 'Prefix'},
75+ 'appinstance': ('django.db.models.fields.related.ForeignKey', [], {'to': "orm['oops.AppInstance']"}),
76+ 'id': ('django.db.models.fields.AutoField', [], {'primary_key': 'True'}),
77+ 'value': ('django.db.models.fields.CharField', [], {'unique': 'True', 'max_length': '100'})
78+ },
79+ 'oops.pruneinfo': {
80+ 'Meta': {'object_name': 'PruneInfo'},
81+ 'id': ('django.db.models.fields.AutoField', [], {'primary_key': 'True'}),
82+ 'pruned_until': ('django.db.models.fields.DateTimeField', [], {})
83+ },
84+ 'oops.report': {
85+ 'Meta': {'object_name': 'Report'},
86+ 'active': ('django.db.models.fields.BooleanField', [], {'default': 'False'}),
87+ 'id': ('django.db.models.fields.AutoField', [], {'primary_key': 'True'}),
88+ 'name': ('django.db.models.fields.CharField', [], {'unique': 'True', 'max_length': '20'}),
89+ 'prefixes': ('django.db.models.fields.related.ManyToManyField', [], {'to': "orm['oops.Prefix']", 'symmetrical': 'False'}),
90+ 'recipient': ('django.db.models.fields.EmailField', [], {'max_length': '254', 'null': 'True'}),
91+ 'summary': ('django.db.models.fields.CharField', [], {'max_length': '20'}),
92+ 'title': ('django.db.models.fields.CharField', [], {'max_length': '50'})
93+ }
94+ }
95+
96+ complete_apps = ['oops']
97
98=== modified file 'src/oopstools/oops/test/test_report.py'
99--- src/oopstools/oops/test/test_report.py 2012-12-04 15:59:12 +0000
100+++ src/oopstools/oops/test/test_report.py 2012-12-06 02:00:27 +0000
101@@ -52,11 +52,13 @@
102 infestation = Infestation.objects.create(
103 exception_type=self.getUniqueString(prefix="exc_type"),
104 exception_value=self.getUniqueString(prefix="exc_value"))
105+ oopsid = self.getUniqueString(prefix='OOPS-')
106+ pathname = self.getUniqueString(prefix='pathname')
107 return Oops.objects.create(
108 prefix=prefix, classification=classification,
109 oopsinfestation=infestation, statements_count=100,
110 appinstance=prefix.appinstance, total_time=3,
111- date=datetime.now())
112+ date=datetime.now(), oopsid=oopsid, pathname=pathname)
113
114 def make_prefix(self):
115 appinstance = AppInstance.objects.create(
116@@ -75,3 +77,19 @@
117 self.assertEqual(200, resp.status_code)
118 self.assertQuerysetEqual(
119 resp.context['recent'].object_list, [oops.pk], transform=attrgetter('pk'))
120+
121+ def test_number_of_queries(self):
122+ # We expect there to be this many queries regardless of the
123+ # number of oopses for the report
124+ expected_queries = 4
125+ report_name = 'areport'
126+ report = Report.objects.create(name=report_name, active=True)
127+ prefix = self.make_prefix()
128+ report.prefixes.add(prefix)
129+ self.make_oops(prefix)
130+ url = '/reports/%s/' % (report_name,)
131+ self.assertNumQueries(
132+ expected_queries, self.client.get, url)
133+ self.make_oops(prefix)
134+ self.assertNumQueries(
135+ expected_queries, self.client.get, url)
136
137=== modified file 'src/oopstools/oops/views.py'
138--- src/oopstools/oops/views.py 2012-11-29 21:41:40 +0000
139+++ src/oopstools/oops/views.py 2012-12-06 02:00:27 +0000
140@@ -135,8 +135,10 @@
141 dates = []
142 for day in range(1, 11):
143 dates.append(now - timedelta(day))
144+ prefix_ids = list(r.prefixes.values_list('pk', flat=True))
145 oopses = Oops.objects.filter(
146- prefix__report=r).order_by('-date')
147+ prefix__in=prefix_ids).select_related(
148+ 'oopsinfestation').order_by('-date')
149 paginator = Paginator(oopses, 50)
150 recent_oopses = get_page_from_query_args(paginator, request.GET)
151 data = {

Subscribers

People subscribed via source and target branches

to all changes: