#28146 closed Cleanup/optimization (invalid)
PostGIS: Django 1.11 adds two extra queries: SELECT postgis_lib_version() and SELECT version()
Reported by: | George Tantiras | Owned by: | nobody |
---|---|---|---|
Component: | GIS | Version: | 1.11 |
Severity: | Normal | Keywords: | |
Cc: | Simon Charette | Triage Stage: | Unreviewed |
Has patch: | no | Needs documentation: | no |
Needs tests: | no | Patch needs improvement: | no |
Easy pickings: | no | UI/UX: | no |
Description
- Python 3.4.2
- PostgreSQL(9.4.10)
- Database Extensions:
List of installed extensions Name | Version | Schema | Description ---------+---------+------------+--------------------------------------------------------------------- plpgsql | 1.0 | pg_catalog | PL/pgSQL procedural language postgis | 2.1.4 | public | PostGIS geometry, geography, and raster spatial types and functions (2 rows)
models.py
from django.contrib.gis.db import models class TheModel(models.Model): polygon_area = models.PolygonField() centroid = models.PointField(srid=4326)
The code needed to fetch the results:
>>> from my.models import TheModel >>> from django.contrib.gis.geos import Point >>> from django.contrib.gis.measure import D >>> from django.contrib.gis.db.models.functions import Distance >>> db.reset_queries() >>> TheModel.objects.filter(centroid__distance_lte=(Point(23.12, 37.9), D(m=3000))).annotate(distance=Distance('centroid', Point(23.12, 37.9))).order_by('polygon_area')) ... <QuerySet []> >>> print(db.connection.queries)
Django-1.11 result(4 Queries, total time 0.025):
{'time': '0.003', 'sql': 'SELECT "spatial_ref_sys"."srid", "spatial_ref_sys"."auth_name", "spatial_ref_sys"."auth_srid", "spatial_ref_sys"."srtext", "spatial_ref_sys"."proj4text" FROM "spatial_ref_sys" WHERE "spatial_ref_sys"."srid" = 4326'} {'time': '0.001', 'sql': 'SELECT version()'} {'time': '0.014', 'sql': 'SELECT postgis_lib_version()'} {'time': '0.007', 'sql': 'SELECT "my_themodel"."id", "my_themodel"."polygon_area", "my_themodel"."centroid", ST_distance_sphere("my_themodel"."centroid", ST_GeomFromEWKB(\'\\x0101000020e61000001f85eb51b81e37403333333333f34240\'::bytea)) AS "distance" FROM "my_themodel" WHERE ST_distance_sphere("my_themodel"."centroid", ST_GeomFromEWKB(\'\\x0101000020e61000001f85eb51b81e37403333333333f34240\'::bytea)) <= 3000.0 ORDER BY "my_themodel"."polygon_area" ASC LIMIT 21'}
Django-1.10.7 result (2 queries, total time 0.01):
{'time': '0.003', 'sql': 'SELECT "spatial_ref_sys"."srid", "spatial_ref_sys"."auth_name", "spatial_ref_sys"."auth_srid", "spatial_ref_sys"."srtext", "spatial_ref_sys"."proj4text" FROM "spatial_ref_sys" WHERE "spatial_ref_sys"."srid" = 4326'} {'time': '0.007', 'sql': 'SELECT "my_themodel"."id", "my_themodel"."polygon_area", "my_themodel"."centroid", ST_distance_sphere("my_themodel"."centroid", ST_GeomFromEWKB(\'\\x0101000020e61000001f85eb51b81e37403333333333f34240\'::bytea)) AS "distance" FROM "my_themodel" WHERE ST_distance_sphere("my_themodel"."centroid", ST_GeomFromEWKB(\'\\x0101000020e61000001f85eb51b81e37403333333333f34240\'::bytea)) <= 3000.0 ORDER BY "my_themodel"."polygon_area" ASC LIMIT 21'}
After upgrading to Django 1.11, Google spends around 600ms to download the page which was downloaded in 350ms using Django 1.10.7, as illustrated in the image below:
Change History (7)
comment:1 by , 8 years ago
Component: | Uncategorized → GIS |
---|---|
Type: | Uncategorized → Cleanup/optimization |
comment:2 by , 8 years ago
Yes, I will try to bisect and report the commit.
Please note that after upgrading, debug toolbar always reports those two queries.
comment:3 by , 8 years ago
This is the result of bisect:
cbae4d31847d75d889815bfe7c04af035f45e28d is the first bad commit
models.py:
from django.contrib.gis.db import models class TheModel(models.Model): polygon_area = models.PolygonField() centroid = models.PointField(srid=4326)
tests.py
from django.test import TestCase from queries.models import TheModel from django.contrib.gis.geos import Point from django.contrib.gis.measure import D from django.contrib.gis.db.models.functions import Distance class ExcessQueriesTest(TestCase): def setUp(self): pass def test_model(self): with self.assertNumQueries(2): print( TheModel.objects.filter( centroid__distance_lte=(Point(23.12, 37.9,srid=4326), D(m=3000)) ).annotate( distance=Distance('centroid', Point(23.12, 37.9,srid=4326)) ).order_by('polygon_area') )
comment:4 by , 8 years ago
Cc: | added |
---|
I would be surprised that two queries taking 15ms total to perform cause an average 250ms increase in load time.
There's no doubt that 1.11 introduced two new queries but I'm pretty sure something else is causing the slowdown here.
Is the affected page displaying any kind of form widget by any chance?
Could you try setting CONN_MAX_AGE to None
and see if that helps?
comment:5 by , 8 years ago
Thank you, I will try the CONN_MAX_AGE
setting, there is no form widget in the page.
During the refactoring and profiling of my view, which suffered one or two concurrent changes along with the 1.11 upgrade, I discovered the added queries.
It is probable that I rushed to report an apparently unjustified bug.
I paid closer attention to results of the debug toolbar:
Django 1.10: 8 queries on the first load which decrease in 6 queries on the second load. Time: 51.72ms Django 1.11: 10 queries at every load. Time: 42.28ms
The above seem to suggest that the added queries are not the issue especially if they are not unintentional.
However, the cpu time is dramatically increased from 1.10.7 to 1.11.
I post the results for the record in case they make some sense:
Django 1.10.7 Django 1.11 ------------- ----------- User CPU time 756.000 msec 1260.000 mse System CPU time 84.000 msec 172.000 msec Total CPU time 840.000 msec 1432.000 msec Elapsed time 869.506 msec 1424.191 msec Context switches 3673 voluntary, 65 involuntary 10557 voluntary, 177 involuntary Timing attribute Timeline Milliseconds since navigation start (+length) Browser timing domainLookup 4 (+0) 9(+0) connect 4 (+0) 9(+0) request 5 (+904) 11 (+414) response 909 (+0) 425 (+0) domLoading 910 (+279) 426 (+273) domInteractive 1152 662 domContentLoadedEvent 1160 (+15) 669 (+15) loadEvent 1189 (+0) 699 (+0)
comment:6 by , 8 years ago
Resolution: | → invalid |
---|---|
Status: | new → closed |
I'll close the ticket since the two queries are expected. Please open a new ticket if you identify a bug causing the increased load time.
comment:7 by , 8 years ago
Although I am still refactoring and profiling I found that as far as the local results are concerned, it seems like a big portion of the deviation in timings between the two django versions has to do with django debug toolbar.
I found the reported bug and relevant issue. Enabling only the panels that I needed (TimerPanel, SQLPanel) the differences in times scaled down.
1.11, is still somehow slower (for example while 1.10 reports 250ms, 1.11 could report 310ms) but this is something different (30% more time is a far different portion compared to 70%).
Could you bisect to find the commit where the behavior changed? It might be that there's a bug, but typically any version queries should be cached by the server so they don't run for every request.