Problems with queries using the earthdistance extension

[terrorobe]

It seems as if queries using the earthdistance extension can't be explained by pg_stat_plans.

Test data set: https://gist.github.com/4665854

Tested on PostgreSQL 9.1.7 with pg_stat_plans REL1_0_STABLE

test=# SELECT * FROM test  WHERE (earth_box(ll_to_earth(46.5845336914063, 14.7958154678345), 300) @> ll_to_earth(coordinate[0], coordinate[1]));
 id |      coordinate       
----+-----------------------
  3 | (46.5854,14.7956)
  4 | (46.586926,14.796106)
(2 rows)

test=# \x
Expanded display is on.
test=# select * from pg_stat_plans where query like 'SELECT % FROM test%';
-[ RECORD 1 ]-------+------------------------------------------------------------------------------------------------------------------------------------------
planid              | 2039753839
userid              | 16384
dbid                | 17743
query               | SELECT * FROM test  WHERE (earth_box(ll_to_earth(46.5845336914063, 14.7958154678345), 300) @> ll_to_earth(coordinate[0], coordinate[1]));
had_our_search_path | t
from_our_database   | t
query_explainable   | t
calls               | 7
total_time          | 4.798
rows                | 10
shared_blks_hit     | 45
shared_blks_read    | 0
shared_blks_written | 0
local_blks_hit      | 0
local_blks_read     | 0
local_blks_written  | 0
temp_blks_read      | 0
temp_blks_written   | 0
blk_read_time       | 
blk_write_time      | 
last_startup_cost   | 0
last_total_cost     | 437.875

test=# select * from pg_stat_plans_explain(2039753839,  16384, 17743);
WARNING:  Existing pg_stat_plans entry planid (2039753839) differs from new plan for query (3608718488).
-[ RECORD 1 ]---------+-
pg_stat_plans_explain | 

test=# \x
Expanded display is off.
test=# SELECT * FROM test  WHERE (earth_box(ll_to_earth(46.5845336914063, 14.7958154678345), 300) @> ll_to_earth(coordinate[0], coordinate[1]));
NOTICE:  updated pg_stat_plans query string of entry 2039753839
 id |      coordinate       
----+-----------------------
  3 | (46.5854,14.7956)
  4 | (46.586926,14.796106)
(2 rows)

test=#  

[petergeoghegan]

Are you sure that the plans produced aren't different for some reason that you have yet to consider?

There is a function exposed at the SQL level, pg_stat_plans_pprint(), which takes an SQL text, explains it and pretty-prints the plan tree. This is used by the integration tests - if you write a failing test-case, the tests produce a diff of the two plan trees that plan fingerprinting considers to be substantively different.

Now, if we had two pieces of SQL that we though ought to produce the same plan (or ought to not produce something fingerprinting sees as the same plan), we could just write a test case and see where fingerprinting went wrong, or where we went wrong in our belief that the two queries ought to be considered equivalent (or not equivalent).

We can't do that here though, because the differing plans are not reproducible by SQL. Ideally, you'd be able to "call pprint(plantree)" from gdb for each plan tree. That will pretty print out the tree in human readable form. We can then compare the two, and should be able to resolve the problem in that way.

[petergeoghegan]

Take a look at this commit in my personal fork of pg_stat_plans:

https://github.com/petergeoghegan/pg_stat_plans/commit/4c93b988df98a4650cb168b8fca9c32b51c2ba5f

If you can build with this commit, it should allow you to get to the bottom of this problem (and other similar problems) without too much effort.

[terrorobe]

Thanks for the patch - I'll test it during our next hack session and see what it comes up with!

[petergeoghegan]

@terrorobe Did you ever try this? Did you conclude that this wasn't a real problem?

[petergeoghegan]

I tracked down the problem, but I'm about out of steam for the night, so am not about to speculate on the exact cause just yet.

When I set a breakpoint here:

(gdb) bt
#0 pgsp_ExecutorEnd (queryDesc=0x24043e8) at pg_stat_plans.c:802
#1 0x00000000006320d0 in ExecutorEnd (queryDesc=0x24043e8) at execMain.c:405
#2 0x0000000000646103 in postquel_end (es=0x2403c08) at functions.c:868
#3 0x00000000006466e1 in fmgr_sql (fcinfo=0x2400690) at functions.c:1
*** SNIP ***

This happens:

(gdb) p *queryDesc
$5 = {operation = CMD_SELECT, plannedstmt = 0x2403b70, utilitystmt = 0x0, sourceText = 0x2402648 "SELECT '6378168'::float8", snapshot = 0x2318df8, crosscheck_snapshot = 0x0, dest = 0x2404480, params = 0x0, instrument_options = 1, tupDesc = 0x2426998, estate = 0x24264a8, planstate = 0x24265c0, totaltime = 0x2426e48}

Essentially, the explain infrastructure ends up explaining the query "SELECT '6378168'::float8" - this is obviously from this SQL from with the earthdistance extension:

CREATE FUNCTION earth() RETURNS float8
LANGUAGE SQL IMMUTABLE
AS 'SELECT ''6378168''::float8';

I'll try and take another look at this over the week ahead.

[terrorobe]

Peter - many thanks!

We lost access to that specific database and haven't had other issues with pg_stat_plans so far.

I might get access to a GIS-using database in the next few weeks, will keep you posted how it goes.

[petergeoghegan]

@terrorobe So the root issue is the one I reported to pgsql-bugs, here: http://www.postgresql.org/message-id/CAM3SWZTNZBmOYvM8BOPjpts=LCWvS2j_PevEt35wOxDgayzBvA@mail.gmail.com

There seems to be some confusion about just what pg_stat_statements (or, really, the core system) ought to do with SQL-function calls.

I have this provisional fix, that you may wish to try out:

https://github.com/petergeoghegan/pg_stat_plans/tree/fix_explain

I've run the regression tests on Postgres 9.2. I've also done some minimal smoke testing by running the Postgres regression tests (make installcheck) on a cluster with pg_stat_plans installed.

It would be useful if you could test this in a similar way on versions 9.0, 9.1 and 9.3. I didn't get the chance to do that today.

[terrorobe]

@petergeoghegan I'm going to be on vacation in iceland for the next three weeks - will only find time afterwards.

The best thing would be to formulate this as a regression test - do you know if there's already pgxs functionality to do testing for extensions?