Re: Slow set-returning functions - Mailing list pgsql-performance

>> Is there any way that I can see what execution plan is being used
>> internally by the functions?
>>
>
> Not directly, but you can do this:
>
>
> postgres=# PREPARE p (int4) AS SELECT id FROM foo WHERE lower(name) LIKE
> 'foo' ORDER BY id OFFSET 0 LIMIT $1;
> PREPARE
>
> postgres=# EXPLAIN EXECUTE p(100); QUERY PLAN
> -----------------------------------------------------------------------------
>  Limit  (cost=0.00..49.18 rows=2 width=4)
>
> -> Index Scan using foo_pkey on foo (cost=0.00..614.77 rows=25 width=4)
>          Filter: (lower(name) ~~ 'foo'::text)
> (3 rows)


I think that having the ability to see the execution plans being used
by queries inside functions would be quite useful.

More generally, I would like to be able to log the execution plans of
all queries issued by an application (in my case I am working on a web
application, where some of the queries are auto-generated by
Hibernate). I've tried setting debug_print_plan, but the results are a
little hard to interpret.

As an experiment, I have tried hacking around a little with the code.
This is my first foray into the source code, so I might well be
missing something, but basically I added a new configuration parameter
debug_explain_plan which causes all queries to be instrumented and
ExecutorRun() to call explain_outNode() at the end, logging the
results at level DEBUG1.

It seems to work quite well as a development aid for my web
application. It is also useful from a psql session (similar to
AUTOTRACE in Oracle):

test=# create table foo(a int primary key);
NOTICE:  CREATE TABLE / PRIMARY KEY will create implicit index "foo_pkey" for table "foo"
CREATE TABLE
test=# insert into foo values (1), (2), (3), (4), (5);
INSERT 0 5
test=# set debug_explain_plan=true;
SET
test=# set client_min_messages=debug1;
SET
test=# select count(*) from foo where a>3;
DEBUG:  ------------------- query plan -------------------
DETAIL:  Aggregate  (cost=32.45..32.46 rows=1 width=0) (actual time=0.066..0.068 rows=1 loops=1)
  ->  Bitmap Heap Scan on foo  (cost=10.45..30.45 rows=800 width=0) (actual time=0.039..0.043 rows=2 loops=1)
        Recheck Cond: (a> 3)
        ->  Bitmap Index Scan on foo_pkey  (cost=0.00..10.25 rows=800 width=0) (actual time=0.025..0.025 rows=2
loops=1)
              Index Cond: (a> 3)
Query runtime: 0.089 ms
 count
-------
     2
(1 row)

test=# create function foo() returns int as 'select max(a) from foo;' language sql stable;
CREATE FUNCTION
test=# select * from foo where a=foo();
DEBUG:  ------------------- query plan -------------------
DETAIL:  Result  (cost=0.04..0.05 rows=1 width=0) (actual time=0.044..0.044 rows=1 loops=1)
  InitPlan
    ->  Limit  (cost=0.00..0.04 rows=1 width=4) (actual time=0.032..0.034 rows=1 loops=1)
          ->  Index Scan Backward using foo_pkey on foo  (cost=0.00..84.25 rows=2400 width=4) (actual time=0.025..0.025
rows=1loops=1) 
                Filter: (a IS NOT NULL)
Query runtime: 0.050 ms
CONTEXT:  SQL function "foo" statement 1
DEBUG:  ------------------- query plan -------------------
DETAIL:  Result  (cost=0.04..0.05 rows=1 width=0) (actual time=0.037..0.037 rows=1 loops=1)
  InitPlan
    ->  Limit  (cost=0.00..0.04 rows=1 width=4) (actual time=0.027..0.029 rows=1 loops=1)
          ->  Index Scan Backward using foo_pkey on foo  (cost=0.00..84.25 rows=2400 width=4) (actual time=0.021..0.021
rows=1loops=1) 
                Filter: (a IS NOT NULL)
Query runtime: 0.044 ms
CONTEXT:  SQL function "foo" statement 1
DEBUG:  ------------------- query plan -------------------
DETAIL:  Index Scan using foo_pkey on foo  (cost=0.25..8.52 rows=1 width=4) (actual time=1.638..1.642 rows=1 loops=1)
  Index Cond: (a = foo())
Query runtime: 1.686 ms
 a
---
 5
(1 row)


(Curious that foo() is being executed twice in this case).

The CONTEXT is very useful, particularly when functions call other
functions, since it gives the call stack (presumably only for SQL and
PL/pgSQL functions). For top-level queries I would ideally like the
CONTEXT to log the SQL being executed, but I couldn't figure out how
to access that information.

Anyway, I'd be interested to know if anyone has thought about doing
anything like this before and if anyone else might find this useful.

Dean

_________________________________________________________________
Free games, great prizes - get gaming at Gamesbox.
http://www.searchgamesbox.com