Message-ID: <49B5948C.3050800@megafon.hr>
Date: Mon, 09 Mar 2009 23:13:32 +0100
From: Mario Splivalo <mario.splivalo@megafon.hr>
User-Agent: Thunderbird 2.0.0.19 (X11/20090105)
MIME-Version: 1.0
To: pgsql-performance@postgresql.org
Subject: Re: Query much slower when run from postgres function
References: <49B51B60.6030600@megafon.hr> <27649.1236616294@sss.pgh.pa.us>
	<49B56A3D.8000100@megafon.hr> <14317.1236628318@sss.pgh.pa.us>
In-Reply-To: <14317.1236628318@sss.pgh.pa.us>
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit

Tom Lane wrote:
> Mario Splivalo <mario.splivalo@megafon.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