PostGIS: Django 1.11 adds two extra queries: SELECT postgis_lib_version() and SELECT version()

[George Tantiras]

• 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:

[Tim Graham]

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.

[George Tantiras]

Yes, I will try to bisect and report the commit.

Please note that after upgrading, debug toolbar always reports those two queries.

[George Tantiras]

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')
            )

[Simon Charette]

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?

[George Tantiras]

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 the 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)

[Tim Graham]

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.

[George Tantiras]

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%).