Re: Query much slower when run from postgres function

Tom Lane wrote:
> Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr> writes:
>> Is this difference normal?
>
> It's hard to tell, because you aren't comparing apples to apples.
> Try a prepared statement, like
[...cut...]
> which should produce results similar to the function. You could
> then use "explain analyze execute" to probe further into what's
> happening.

Huh, thnx! :) This got me even more confused:

pulitzer2=# prepare foo(int) as select count(*) from _v1 where
service_id = $1;
PREPARE
Time: 4.425 ms
pulitzer2=# execute foo(1816);
count
-------
1
(1 row)

Time: 248.301 ms
pulitzer2=# select __new__get_memo_display_queue_size(1816);
__new__get_memo_display_queue_size
------------------------------------
1
(1 row)

Time: 218.914 ms
pulitzer2=#

So, it is the same. When I do EXPLAIN ANALYZE EXECUTE I get completely
different execution plan:

pulitzer2=# explain analyze execute foo(1816);

QUERY PLAN

--------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=40713.22..40713.23 rows=1 width=0) (actual
time=475.649..475.650 rows=1 loops=1)
-> Hash Join (cost=21406.91..40711.65 rows=626 width=0) (actual
time=183.004..475.629 rows=1 loops=1)
Hash Cond: (messages_memo.message_id = messages.id)
-> Seq Scan on messages_memo (cost=0.00..18630.83 rows=106825
width=4) (actual time=0.083..324.607 rows=107608 loops=1)
Filter: ((state)::integer = 1)
-> Hash (cost=21326.61..21326.61 rows=6424 width=4) (actual
time=5.868..5.868 rows=5 loops=1)
-> Hash Left Join (cost=341.64..21326.61 rows=6424
width=4) (actual time=5.650..5.855 rows=5 loops=1)
Hash Cond: (messages.id =
messages_memo_displayed.message_id)
Filter: (messages_memo_displayed.admin_id IS NULL)
-> Bitmap Heap Scan on messages
(cost=287.98..21192.42 rows=12848 width=4) (actual time=0.049..0.169
rows=62 loops=1)
Recheck Cond: (service_id = $1)
-> Bitmap Index Scan on
messages_uq__service_id__tan (cost=0.00..284.77 rows=12848 width=0)
(actual time=0.038..0.038 rows=62 loops=1)
Index Cond: (service_id = $1)
-> Hash (cost=28.85..28.85 rows=1985 width=8)
(actual time=5.564..5.564 rows=1985 loops=1)
-> Seq Scan on messages_memo_displayed
(cost=0.00..28.85 rows=1985 width=8) (actual time=0.008..2.674 rows=1985
loops=1)
Total runtime: 475.761 ms
(16 rows)

Time: 476.280 ms
pulitzer2=#

There is a sequential scan on messages_memo, a scan that doesn't show up
when I just do 'SELECT COUNT(*)...'.

When I do 'set enable_seqscan to false' before i do PREPARE, here is the
execution plan:

pulitzer2=# explain analyze execute foo(1816);

QUERY PLAN

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=55624.91..55624.92 rows=1 width=0) (actual
time=7.122..7.123 rows=1 loops=1)
-> Nested Loop (cost=2239.11..55623.34 rows=626 width=0) (actual
time=7.098..7.108 rows=1 loops=1)
-> Hash Left Join (cost=2239.11..23224.07 rows=6424 width=4)
(actual time=6.663..6.962 rows=5 loops=1)
Hash Cond: (messages.id = messages_memo_displayed.message_id)
Filter: (messages_memo_displayed.admin_id IS NULL)
-> Bitmap Heap Scan on messages (cost=287.98..21192.42
rows=12848 width=4) (actual time=0.138..0.373 rows=62 loops=1)
Recheck Cond: (service_id = $1)
-> Bitmap Index Scan on
messages_uq__service_id__tan (cost=0.00..284.77 rows=12848 width=0)
(actual time=0.121..0.121 rows=62 loops=1)
Index Cond: (service_id = $1)
-> Hash (cost=1926.31..1926.31 rows=1985 width=8)
(actual time=6.430..6.430 rows=1985 loops=1)
-> Index Scan using messages_memo_displayed_pk on
messages_memo_displayed (cost=0.00..1926.31 rows=1985 width=8) (actual
time=0.063..3.320 rows=1985 loops=1)
-> Index Scan using messages_memo_pk on messages_memo
(cost=0.00..5.03 rows=1 width=4) (actual time=0.025..0.025 rows=0 loops=5)
Index Cond: (messages_memo.message_id = messages.id)
Filter: ((messages_memo.state)::integer = 1)
Total runtime: 7.260 ms
(15 rows)

Time: 7.786 ms

I have no idea why postgres chooses sequential scan over messages_memo
when I PREPARE the select. For now I'll go with plpgsql function
(instead of sql function) because I can do 'set enable_seqscan to true'
just before RETURNing the value. That way, when I call the function via
JDBC I have short execution times.

Mike