[pgrouting-users] Re: [OT] stored procedure performance [SOLVED]

Stephen_Woodbridge1 · October 24, 2011, 8:14pm

OK, googling about seems like this is normal but bad behavior. I did fine a way to work around this bad behavior.

This is BAD (function called 6 times):
select a.*, (b).* from (select x, y, imt_rgeo_countyzip(x,y) as b from (select -79.2723 as x, 41.2393 as y) as c) as a;

This is GOOD (function called 1 time):
select a.*, (b).* from (select x, y, imt_rgeo_countyzip(x,y) as b from (select -79.2723 as x, 41.2393 as y) as c offset 0) as a;

It is amazing what you can find in Google

-Steve

On 10/24/2011 12:04 PM, Stephen Woodbridge wrote:

Hi All,

This is a little off topic, but I did find this issue developing a
postgis related stored procedure.

This is a simple reverse geocoder and it works fine, but here is the
issue and this potentially impacts all procedures that return a record.

So here is the basic query. I added some raise notice to show whats
happening.

select * from imt_rgeo_countyzip(-79.2723,41.2393);
"Clarion";"PA";"42031";"16225";0;0

NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
Total query runtime: 81 ms.
1 row retrieved.

So here is the problem! If you call the function this way, it appears to
get called once for each field in the returned record. So if you have 6
fields it actually executes the function 6 times!!!! and the cost goes
up by 6X to 415 ms from 81 ms.

select (imt_rgeo_countyzip(-79.2723,41.2393)).*;
"Clarion";"PA";"42031";"16225";0;0

NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment

Total query runtime: 415 ms.
1 row retrieved.

Thoughts,
-Steve

Stephen_Woodbridge1 · October 24, 2011, 8:27pm

Sorry for this noise, this was supposed to go to the postgis list. And I will post it to that, so you may get yet another copy of it.

On 10/24/2011 4:14 PM, Stephen Woodbridge wrote:

OK, googling about seems like this is normal but bad behavior. I did
fine a way to work around this bad behavior.

This is BAD (function called 6 times):
select a.*, (b).* from (select x, y, imt_rgeo_countyzip(x,y) as b from
(select -79.2723 as x, 41.2393 as y) as c) as a;

This is GOOD (function called 1 time):
select a.*, (b).* from (select x, y, imt_rgeo_countyzip(x,y) as b from
(select -79.2723 as x, 41.2393 as y) as c offset 0) as a;

It is amazing what you can find in Google

-Steve

On 10/24/2011 12:04 PM, Stephen Woodbridge wrote:

Hi All,

This is a little off topic, but I did find this issue developing a
postgis related stored procedure.

This is a simple reverse geocoder and it works fine, but here is the
issue and this potentially impacts all procedures that return a record.

So here is the basic query. I added some raise notice to show whats
happening.

select * from imt_rgeo_countyzip(-79.2723,41.2393);
"Clarion";"PA";"42031";"16225";0;0

NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
Total query runtime: 81 ms.
1 row retrieved.

So here is the problem! If you call the function this way, it appears to
get called once for each field in the returned record. So if you have 6
fields it actually executes the function 6 times!!!! and the cost goes
up by 6X to 415 ms from 81 ms.

select (imt_rgeo_countyzip(-79.2723,41.2393)).*;
"Clarion";"PA";"42031";"16225";0;0

NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: calling imt_rgeo_countyzip
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: rr: (Clarion,PA,42031,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment
NOTICE: zip: (16225,0), radius: 0.0013
CONTEXT: PL/pgSQL function "imt_rgeo_countyzip" line 8 at assignment

Total query runtime: 415 ms.
1 row retrieved.

Thoughts,
-Steve

_______________________________________________
Pgrouting-users mailing list
Pgrouting-users@lists.osgeo.org
http://lists.osgeo.org/mailman/listinfo/pgrouting-users