0

I'm using Ubuntu 16.04 with PostgreSQL 9.5 and Django 1.11

My website has been suffering from super long ajax calls (2-20 seconds). The same ajax calls take about 100-500ms in development. The problem doesn't seem to be a server or code issue, so it is most likely the database.

The main difference between my development & production environment is that I use Windows for development, Ubuntu 16.04 for production.

What I noticed is that the server would experience super high disk I/O, with just a couple of queries.

Here is a photo Here is a photo.

As you can see, a couple of queries can drive the disk I/O to 40MB/s. That doesn't seem normal.

The databases has indexes for fields that could queried.

It seems plausible the slow ajax calls are correlated with abnormally high disk I/O. What could be causing this?

EDIT:

A query statement that consistently takes 25 seconds:

EXPLAIN (ANALYZE, BUFFERS)
SELECT COUNT(*) AS "__count" FROM "map_listing" 
WHERE ("map_listing"."lo" <  -79.32516245458987 AND "map_listing"."la" > 43.640279060122346
AND "map_listing"."lo" >  -79.60531382177737 AND "map_listing"."transaction_type" = 'Sale'
AND "map_listing"."la" < 43.774544561921296 
AND NOT ("map_listing"."status" = 'Sld' AND "map_listing"."sold_date" < '2018-01-21'::date
AND "map_listing"."sold_date" IS NOT NULL)
AND NOT (("map_listing"."status" = 'Ter' OR "map_listing"."status" = 'Exp'))
AND NOT (("map_listing"."property_type" = 'Parking Space' OR "map_listing"."property_type" = 'Locker')));

Result from pg_stat_statements:

userid              | 16385
dbid                | 19402
queryid             | 116800687
query               | SELECT COUNT(*) AS "__count" FROM "map_listing" WHERE ("map_listing"."lo" <  ? AND "map_listing"."la" > ? AND "map_listing"."lo" >  ? AND "map_listing"."transaction_type" = ? AND "map_listing"."la" < ? AND NOT ("map_listing"."status" = ? AND "map_listing"."sold_date" < ?::date AND "map_listing"."sold_date" IS NOT NULL) AND NOT (("map_listing"."status" = ? OR "map_listing"."status" = ?)) AND NOT (("map_listing"."property_type" = ? OR "map_listing"."property_type" = ?)))
calls               | 4
total_time          | 51397.771
min_time            | 277.512
max_time            | 25313.785
mean_time           | 12849.44275
stddev_time         | 11364.6279845798
rows                | 4
shared_blks_hit     | 31954
shared_blks_read    | 147159
shared_blks_dirtied | 0
shared_blks_written | 0
local_blks_hit      | 0
local_blks_read     | 0
local_blks_dirtied  | 0
local_blks_written  | 0
temp_blks_read      | 0
temp_blks_written   | 0
blk_read_time       | 0
blk_write_time      | 0

Result of EXPLAIN (ANALYZE, BUFFERS) ..statement..:

 Aggregate  (cost=89924.55..89924.56 rows=1 width=0) (actual time=27318.859..27318.860 rows=1 loops=1)
   Buffers: shared read=73424
   ->  Bitmap Heap Scan on map_listing  (cost=4873.96..89836.85 rows=35079 width=0) (actual time=6061.214..27315.183 rows=3228 loops=1)
         Recheck Cond: ((la > 43.640279060122346) AND (la < 43.774544561921296))
         Rows Removed by Index Recheck: 86733
         Filter: ((lo < '-79.32516245458987'::numeric) AND (lo > '-79.60531382177737'::numeric) AND ((status)::text <> 'Ter'::text) AND ((status)::text <> 'Exp'::text) AND ((property_type)::text <> 'Parking Space'::text) AND ((property_type)::text <> 'Locker'::text) AND ((transaction_type)::text = 'Sale'::text) AND (((status)::text <> 'Sld'::text) OR (sold_date >= '2018-01-21'::date) OR (sold_date IS NULL)))
         Rows Removed by Filter: 190108
         Heap Blocks: exact=46091 lossy=26592
         Buffers: shared read=73424
         ->  Bitmap Index Scan on map_listing_la_88ca396c  (cost=0.00..4865.19 rows=192477 width=0) (actual time=156.964..156.964 rows=194434 loops=1)
               Index Cond: ((la > 43.640279060122346) AND (la < 43.774544561921296))
               Buffers: shared read=741
 Planning time: 0.546 ms
 Execution time: 27318.926 ms
(14 rows)
Jack
  • 417
  • 2
  • 5
  • 16

1 Answers1

0

Use pg_stat_statements to find the queries that take the most time. Use EXPLAIN (ANALYZE, BUFFERS) to find out why a query takes long.

Laurenz Albe
  • 209,280
  • 17
  • 206
  • 263
  • I tried those commands in the postgres shell (`sudo -u postgres psql`) and nothing was returned. Am I supposed to enter them in the shell or elsewhere? – Jack Feb 20 '18 at 23:00
  • 1
    You are supposed to read them up in the documentation. I cannot provide a course in PostgreSQL performance tuning in one Stackoverflow answer ... – Laurenz Albe Feb 21 '18 at 04:12
  • You are right. I should've did my own research first. I followed your instructions and did the testing. I chose a particular query that always take ~25 seconds. I'm not sure how to interpret the data. Any pointers on how I should proceed troubleshooting? – Jack Feb 22 '18 at 02:31
  • Open a new question for that query. Include `EXPLAIN (ANALYZE, BUFFERS)` output in the question. – Laurenz Albe Feb 22 '18 at 04:16
  • https://stackoverflow.com/questions/48920097/postgres-queries-in-production-results-in-abnormally-high-disk-read-i-o Done – Jack Feb 22 '18 at 05:14