[mapserver-users] postgis layer draws much slower than psql select statement

Tue Dec 3 08:45:16 PST 2013

I am having a problem with the draw time of the following layer.

LAYER
NAME "Daily Precip"
CONNECTION "user=XXXXXX password=XXXXXX dbname=swc host=www.fakepg.com port=5432"
CONNECTIONTYPE postgis
DATA "the_geom from (select (count(*)/((date '8-31-2013'- date '4-1-2013')+1)::numeric>=0.98) as list, round(sum(p.amount)::numeric,2) as label,s.site_id,s.the_geom,round(sum(p.amount)::numeric,2) as amount from precip.station s join precip.precip_data p on p.site_id=s.site_id where the_geom is not null and p.measDate >= date '4-1-2013' and p.measDate <= date '8-31-2013' group by s.site_id,s.the_geom) as foo2 using SRID=2266 USING UNIQUE site_id"
GROUP "Water Resources"
TYPE POINT
STATUS ON
CLASS
NAME "0"
STATUS ON
STYLE
SYMBOL 'circle'
COLOR 0 0 0
SIZE 8
END
LABEL
FONT helvetica
TYPE TRUETYPE
SIZE 8
COLOR 0 0 0
ANGLE AUTO
POSITION AUTO
END
END
END

The following command
shp2img -m precip.map -o ~/precip.png
produces an image after 20+ seconds.

The debug output from mapserver is below.

[Tue Dec  3 08:53:02 2013].705076 msDrawMap(): rendering using outputformat named AGG_PNG (AGG/PNG).
[Tue Dec  3 08:53:02 2013].705678 msDrawMap(): WMS/WFS set-up and query, 0.000s
[Tue Dec  3 08:53:02 2013].715428 msDrawMap(): Layer 0 (North Dakota), 0.010s
[Tue Dec  3 08:53:02 2013].756964 msDrawMap(): Layer 1 (General Hydrography), 0.042s
[Tue Dec  3 08:53:02 2013].804922 msDrawMap(): Layer 2 (Counties), 0.048s
[Tue Dec  3 08:53:24 2013].166022 msDrawMap(): Layer 3 (Daily Precip), 21.361s
[Tue Dec  3 08:53:24 2013].166057 msDrawMap(): Drawing Label Cache, 0.000s
[Tue Dec  3 08:53:24 2013].166062 msDrawMap() total time: 21.463s
[Tue Dec  3 08:53:24 2013].192358 msSaveImage(/Users/xxxxx/precip.png) total time: 0.026s
[Tue Dec  3 08:53:24 2013].192398 msFreeMap(): freeing map at 0x7fb1d9010200.

The following psql statement executes in 218.802 ms from within psql connection.

select (count(*)/((date '8-31-2013'- date '4-1-2013')+1)::numeric>=0.98) as list, round(sum(p.amount)::numeric,2) as label,s.site_id,s.the_geom,round(sum(p.amount)::numeric,2) as amount from precip.station s join precip.precip_data p on p.site_id=s.site_id where the_geom is not null and p.measDate >= date '4-1-2013' and p.measDate <= date '8-31-2013' group by s.site_id,s.the_geom;

Time: 218.802 ms

My question is why does it take mapserver so long to draw that layer, 21.463s when the select statement runs so much faster from psql?  Is there anything I can do about the issue.

Versions

MapServer version 6.4.0 OUTPUT=PNG OUTPUT=JPEG OUTPUT=KML SUPPORTS=PROJ SUPPORTS=AGG SUPPORTS=FREETYPE SUPPORTS=CAIRO SUPPORTS=ICONV SUPPORTS=WMS_SERVER SUPPORTS=WMS_CLIENT SUPPORTS=WFS_SERVER SUPPORTS=WFS_CLIENT SUPPORTS=WCS_SERVER SUPPORTS=GEOS INPUT=JPEG INPUT=POSTGIS INPUT=OGR INPUT=GDAL INPUT=SHAPEFILE

POSTGIS="2.0.3 r11128" GEOS="3.3.8-CAPI-1.7.8" PROJ="Rel. 4.8.0, 6 March 2012" GDAL="GDAL 1.10.0, released 2013/04/24" LIBXML="2.7.3" LIBJSON="UNKNOWN" TOPOLOGY RASTER

psql output sample

 list | label | site_id |                      the_geom                      | amount
------+-------+---------+----------------------------------------------------+--------
 t    | 20.14 |       2 | 0101000020DA0800000000000074C737410000000090B6FB40 |  20.14
 f    | 13.04 |       3 | 0101000020DA08000000000000337036410000000098CB0741 |  13.04
 t    | 17.29 |       4 | 0101000020DA08000000000000ED2036410000000028BB0B41 |  17.29
...
...
 f    | 14.27 |    4667 | 0101000020DA08000000000000831038410000000004571B41 |  14.27
 f    | 14.49 |    4708 | 0101000020DA080000000000009A743A4100000000D0C81C41 |  14.49
 f    |  0.75 |    4709 | 0101000020DA0800000000000017674041000000009CC81241 |   0.75
(512 rows)
Time: 218.802 ms

Query plan from psql

                                                                       QUERY PLAN

---------------------------------------------------------------------------------------------------------------------------------------------------------

 GroupAggregate  (cost=33077.14..33523.12 rows=3577 width=44) (actual time=130.122..191.921 rows=512 loops=1)

   ->  Sort  (cost=33077.14..33135.07 rows=23174 width=44) (actual time=129.933..167.485 rows=66303 loops=1)

         Sort Key: s.site_id, s.the_geom

         Sort Method: external merge  Disk: 3744kB

         ->  Hash Join  (cost=701.16..30683.00 rows=23174 width=44) (actual time=11.586..46.325 rows=66303 loops=1)

               Hash Cond: (p.site_id = s.site_id)

               ->  Bitmap Heap Scan on precip_data p  (cost=495.49..30100.03 rows=23291 width=12) (actual time=7.969..20.132 rows=67868 loops=1)

                     Recheck Cond: ((measdate >= '2013-04-01'::date) AND (measdate <= '2013-08-31'::date))

                     ->  Bitmap Index Scan on precip_data_measdate  (cost=0.00..489.67 rows=23291 width=0) (actual time=7.899..7.899 rows=67868 loops=1)

                           Index Cond: ((measdate >= '2013-04-01'::date) AND (measdate <= '2013-08-31'::date))

               ->  Hash  (cost=160.95..160.95 rows=3577 width=36) (actual time=3.592..3.592 rows=3444 loops=1)

                     Buckets: 1024  Batches: 1  Memory Usage: 219kB

                     ->  Seq Scan on station s  (cost=0.00..160.95 rows=3577 width=36) (actual time=0.013..2.632 rows=3444 loops=1)

                           Filter: (the_geom IS NOT NULL)

                           Rows Removed by Filter: 98

 Total runtime: 217.698 ms

(16 rows)

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.osgeo.org/pipermail/mapserver-users/attachments/20131203/d18c5021/attachment.htm>