Re: [PERFORM] Query much slower when run from postgres function

Lists: pgsql-jdbcpgsql-performance
From: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>
To: pgsql-performance(at)postgresql(dot)org
Subject: Query much slower when run from postgres function
Date: 2009-03-09 13:36:32
Message-ID: 49B51B60.6030600@megafon.hr
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

I have a function, looking like this:

CREATE OR REPLACE FUNCTION get_memo_display_queue_size(a_service_id integer)
RETURNS integer AS
$BODY$
SELECT
COUNT(*)::integer
FROM
v_messages_memo
LEFT JOIN messages_memo_displayed
ON id = message_id
WHERE
service_id = $1
AND state = 1
AND admin_id IS NULL;
$BODY$
LANGUAGE 'sql' VOLATILE SECURITY DEFINER
COST 100;

Now, when I run that function from psql, it takes around 200ms to complete:

pulitzer2=# explain analyze select get_memo_display_queue_size(1829);
QUERY PLAN

----------------------------------------------------------------------------------------
Result (cost=0.00..0.26 rows=1 width=0) (actual time=219.728..219.730
rows=1 loops=1)
Total runtime: 219.758 ms
(2 rows)

pulitzer2=#

And it takes around 200ms each time I run the function!

When I rewrite the query so I can see queryplan, I get this:

create view _v1 as
SELECT
*
FROM
v_messages_memo
LEFT JOIN messages_memo_displayed
ON id = message_id
WHERE
state = 1
AND admin_id IS NULL;

pulitzer2=# EXPLAIN ANALYZE select count(*) from _v1 WHERE service_id =
1829;

QUERY PLAN

------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=23506.14..23506.15 rows=1 width=0) (actual
time=6.001..6.002 rows=1 loops=1)
-> Nested Loop (cost=150.69..23505.59 rows=216 width=0) (actual
time=5.744..5.971 rows=13 loops=1)
-> Hash Left Join (cost=150.69..11035.16 rows=2104 width=4)
(actual time=5.721..5.793 rows=13 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=97.03..10955.11
rows=4209 width=4) (actual time=0.042..0.075 rows=13 loops=1)
Recheck Cond: (service_id = 1829)
-> Bitmap Index Scan on
messages_uq__service_id__tan (cost=0.00..95.98 rows=4209 width=0)
(actual time=0.032..0.032 rows=13 loops=1)
Index Cond: (service_id = 1829)
-> Hash (cost=28.85..28.85 rows=1985 width=8) (actual
time=5.666..5.666 rows=1985 loops=1)
-> Seq Scan on messages_memo_displayed
(cost=0.00..28.85 rows=1985 width=8) (actual time=0.009..2.697 rows=1985
loops=1)
-> Index Scan using messages_memo_pk on messages_memo
(cost=0.00..5.91 rows=1 width=4) (actual time=0.006..0.008 rows=1 loops=13)
Index Cond: (messages_memo.message_id = messages.id)
Filter: ((messages_memo.state)::integer = 1)
Total runtime: 6.079 ms
(15 rows)

So I noticed that postgres is using seq_scan on messages_memo_displayed,
although there is a PK (and an index) on message_id in
messages_memo_displayed (I'll post DDL of the tables at the end of the
post).

So, I tried EXPLAIN ANALYZE after I forced planner not to use sequential
scans:

pulitzer2=# EXPLAIN ANALYZE select count(*) from _v1 WHERE service_id =
1829;

QUERY PLAN

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=25403.60..25403.61 rows=1 width=0) (actual
time=6.546..6.547 rows=1 loops=1)
-> Nested Loop (cost=2048.16..25403.06 rows=216 width=0) (actual
time=6.287..6.512 rows=13 loops=1)
-> Hash Left Join (cost=2048.16..12932.63 rows=2104 width=4)
(actual time=6.268..6.340 rows=13 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=97.03..10955.11
rows=4209 width=4) (actual time=0.043..0.078 rows=13 loops=1)
Recheck Cond: (service_id = 1829)
-> Bitmap Index Scan on
messages_uq__service_id__tan (cost=0.00..95.98 rows=4209 width=0)
(actual time=0.032..0.032 rows=13 loops=1)
Index Cond: (service_id = 1829)
-> Hash (cost=1926.31..1926.31 rows=1985 width=8)
(actual time=6.211..6.211 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.069..3.221 rows=1985 loops=1)
-> Index Scan using messages_memo_pk on messages_memo
(cost=0.00..5.91 rows=1 width=4) (actual time=0.006..0.008 rows=1 loops=13)
Index Cond: (messages_memo.message_id = messages.id)
Filter: ((messages_memo.state)::integer = 1)
Total runtime: 6.628 ms
(15 rows)

No sequential scan. So I 'changed' my function so that first row says
'SET enable_seqscan TO false'. After that, here are the times for the
function call:

mike(at)som:~$ psql -U postgres pulitzer2
Welcome to psql 8.3.5, the PostgreSQL interactive terminal.

Type: \copyright for distribution terms
\h for help with SQL commands
\? for help with psql commands
\g or terminate with semicolon to execute query
\q to quit
pulitzer2=# explain analyze select get_memo_display_queue_size(1829);
QUERY PLAN

----------------------------------------------------------------------------------------
Result (cost=0.00..0.26 rows=1 width=0) (actual time=300.448..300.450
rows=1 loops=1)
Total runtime: 300.491 ms
(2 rows)

pulitzer2=# explain analyze select get_memo_display_queue_size(1829);
QUERY PLAN

------------------------------------------------------------------------------------
Result (cost=0.00..0.26 rows=1 width=0) (actual time=1.940..1.941
rows=1 loops=1)
Total runtime: 1.961 ms
(2 rows)

pulitzer2=# explain analyze select get_memo_display_queue_size(1829);
QUERY PLAN

------------------------------------------------------------------------------------
Result (cost=0.00..0.26 rows=1 width=0) (actual time=1.946..1.947
rows=1 loops=1)
Total runtime: 1.973 ms
(2 rows)

pulitzer2=# explain analyze select get_memo_display_queue_size(1829);
QUERY PLAN

------------------------------------------------------------------------------------
Result (cost=0.00..0.26 rows=1 width=0) (actual time=1.936..1.937
rows=1 loops=1)
Total runtime: 1.964 ms
(2 rows)

pulitzer2=#

So, first query on the same connection takes 300ms, and any
subsequential query on the same connection takes less than 2 ms. If I
remove 'SET enable_seqscan TO false' from the top of the function, every
call to the function takes around 200-300ms.

Now, as I was explained on pg-jdbc mailinglist, that 'SET enable_seqscan
TO false' affects all queries on that persistent connection from tomcat,
and It's not good solution. So I wanted to post here to ask what other
options do I have.

While writing this I realized that, without forcing sequential scan out,
I get much quicker execution times when I do:

SELECT count(*) FROM _v1 WHERE service_id = 1829

then when I do

SELECT get_memo_display_queue_size(1829),

as seen here:

mike(at)som:~$ psql -U postgres pulitzer2
Welcome to psql 8.3.5, the PostgreSQL interactive terminal.

Type: \copyright for distribution terms
\h for help with SQL commands
\? for help with psql commands
\g or terminate with semicolon to execute query
\q to quit

pulitzer2=# explain analyze select get_memo_display_queue_size(1829);
QUERY PLAN

----------------------------------------------------------------------------------------
Result (cost=0.00..0.26 rows=1 width=0) (actual time=259.090..259.092
rows=1 loops=1)
Total runtime: 259.132 ms
(2 rows)

pulitzer2=# EXPLAIN ANALYZE select count(*) from _v1 WHERE service_id =
1829;

QUERY PLAN

------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=23517.98..23517.99 rows=1 width=0) (actual
time=5.942..5.943 rows=1 loops=1)
-> Nested Loop (cost=150.70..23517.44 rows=216 width=0) (actual
time=5.674..5.909 rows=13 loops=1)
-> Hash Left Join (cost=150.70..11037.87 rows=2105 width=4)
(actual time=5.633..5.706 rows=13 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=97.04..10957.81
rows=4210 width=4) (actual time=0.032..0.063 rows=13 loops=1)
Recheck Cond: (service_id = 1829)
-> Bitmap Index Scan on
messages_uq__service_id__tan (cost=0.00..95.98 rows=4210 width=0)
(actual time=0.022..0.022 rows=13 loops=1)
Index Cond: (service_id = 1829)
-> Hash (cost=28.85..28.85 rows=1985 width=8) (actual
time=5.588..5.588 rows=1985 loops=1)
-> Seq Scan on messages_memo_displayed
(cost=0.00..28.85 rows=1985 width=8) (actual time=0.009..2.690 rows=1985
loops=1)
-> Index Scan using messages_memo_pk on messages_memo
(cost=0.00..5.92 rows=1 width=4) (actual time=0.008..0.010 rows=1 loops=13)
Index Cond: (messages_memo.message_id = messages.id)
Filter: ((messages_memo.state)::integer = 1)
Total runtime: 6.026 ms
(15 rows)

pulitzer2=# explain analyze select get_memo_display_queue_size(1829);
QUERY PLAN

----------------------------------------------------------------------------------------
Result (cost=0.00..0.26 rows=1 width=0) (actual time=211.712..211.714
rows=1 loops=1)
Total runtime: 211.742 ms
(2 rows)

pulitzer2=# EXPLAIN ANALYZE select count(*) from _v1 WHERE service_id =
1829;

QUERY PLAN

------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=23517.98..23517.99 rows=1 width=0) (actual
time=5.918..5.920 rows=1 loops=1)
-> Nested Loop (cost=150.70..23517.44 rows=216 width=0) (actual
time=5.659..5.885 rows=13 loops=1)
-> Hash Left Join (cost=150.70..11037.87 rows=2105 width=4)
(actual time=5.638..5.711 rows=13 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=97.04..10957.81
rows=4210 width=4) (actual time=0.043..0.078 rows=13 loops=1)
Recheck Cond: (service_id = 1829)
-> Bitmap Index Scan on
messages_uq__service_id__tan (cost=0.00..95.98 rows=4210 width=0)
(actual time=0.033..0.033 rows=13 loops=1)
Index Cond: (service_id = 1829)
-> Hash (cost=28.85..28.85 rows=1985 width=8) (actual
time=5.581..5.581 rows=1985 loops=1)
-> Seq Scan on messages_memo_displayed
(cost=0.00..28.85 rows=1985 width=8) (actual time=0.009..2.678 rows=1985
loops=1)
-> Index Scan using messages_memo_pk on messages_memo
(cost=0.00..5.92 rows=1 width=4) (actual time=0.006..0.008 rows=1 loops=13)
Index Cond: (messages_memo.message_id = messages.id)
Filter: ((messages_memo.state)::integer = 1)
Total runtime: 5.994 ms
(15 rows)

pulitzer2=#

Now I'm confused, why is 'sql' function much slower than 'direct' SELECT?

Mike

P.S. Here are tables definition, from psql:

pulitzer2=# \d messages
Table "public.messages"
Column | Type |
Modifiers
--------------------+--------------------------+---------------------------------------------------------------------
id | integer | not null default
nextval(('public.message_id_seq'::text)::regclass)
from | character varying(15) | not null
to | character varying(10) | not null
receiving_time | timestamp with time zone | not null default now()
raw_text | character varying | not null
keyword | character varying |
destination_id | integer | not null
vpn_id | integer |
service_id | integer |
status | integer | not null default 2
gateway_message_id | character varying | not null
prize_id | integer |
tan | character varying |
Indexes:
"messages_pk" PRIMARY KEY, btree (id)
"messages_uq__gateway_message_id" UNIQUE, btree (gateway_message_id)
"messages_uq__service_id__tan" UNIQUE, btree (service_id, tan)
"messages_ix_from" btree ("from")
"messages_ix_receiving_time__service_id__status" btree
(receiving_time, service_id, status)
"messages_ix_vpn_id" btree (vpn_id)
Foreign-key constraints:
"messages_fk__destinations_id" FOREIGN KEY (destination_id)
REFERENCES destinations(id)
"messages_fk__service_prizes_prize_id" FOREIGN KEY (prize_id)
REFERENCES service_prizes(prize_id)
"messages_fk__services_id" FOREIGN KEY (service_id) REFERENCES
services(id)
"messages_fk__vpns_id" FOREIGN KEY (vpn_id) REFERENCES vpns(id)

pulitzer2=# \d messages_memo
Table "public.messages_memo"
Column | Type | Modifiers
------------------------+--------------------------+-----------
message_id | integer | not null
memo | character varying |
state | dom_messages_memo_state | not null
admin_id | integer |
admin_change_timestamp | timestamp with time zone |
Indexes:
"messages_memo_pk" PRIMARY KEY, btree (message_id)
Foreign-key constraints:
"messages_memo_fk__messages_id" FOREIGN KEY (message_id) REFERENCES
messages(id)

pulitzer2=# \d messages_memo_displayed
Table "public.messages_memo_displayed"
Column | Type | Modifiers
------------+---------+-----------
message_id | integer | not null
admin_id | integer | not null
Indexes:
"messages_memo_displayed_pk" PRIMARY KEY, btree (message_id, admin_id)
Foreign-key constraints:
"messages_memo_displayed_fk__admins_id" FOREIGN KEY (admin_id)
REFERENCES admins(id)
"messages_memo_displayed_fk__messages_id" FOREIGN KEY (message_id)
REFERENCES messages(id)

pulitzer2=# \d v_messages_memo
View "public.v_messages_memo"
Column | Type | Modifiers
--------------------+--------------------------+-----------
id | integer |
from | character varying(15) |
to | character varying(10) |
receiving_time | timestamp with time zone |
raw_text | character varying |
keyword | character varying |
destination_id | integer |
vpn_id | integer |
service_id | integer |
status | integer |
gateway_message_id | character varying |
prize_id | integer |
tan | character varying |
memo | character varying |
state | dom_messages_memo_state |
displayed | boolean |
View definition:
SELECT v_messages_full.id, v_messages_full."from",
v_messages_full."to", v_messages_full.receiving_time,
v_messages_full.raw_text, v_messages_full.keyword,
v_messages_full.destination_id, v_messages_full.vpn_id,
v_messages_full.service_id, v_messages_full.status,
v_messages_full.gateway_message_id, v_messages_full.prize_id,
v_messages_full.tan, messages_memo.memo, messages_memo.state,
NULL::boolean AS displayed
FROM messages v_messages_full
JOIN messages_memo ON v_messages_full.id = messages_memo.message_id;

pulitzer2=#


From: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
To: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>
Cc: pgsql-performance(at)postgresql(dot)org
Subject: Re: Query much slower when run from postgres function
Date: 2009-03-09 16:31:34
Message-ID: 27649.1236616294@sss.pgh.pa.us
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr> writes:
> Now I'm confused, why is 'sql' function much slower than 'direct' SELECT?

Usually the reason for this is that the planner chooses a different plan
when it has knowledge of the particular value you are searching for than
when it does not. I suppose 'service_id' has a very skewed distribution
and you are looking for an uncommon value?

regards, tom lane


From: Guillaume Cottenceau <gc(at)mnc(dot)ch>
To: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, pgsql-performance(at)postgresql(dot)org
Cc: pgsql-jdbc(at)postgresql(dot)org
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-09 16:51:24
Message-ID: 87fxhmmygj.fsf@meuh.mnc.lan
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

Tom Lane <tgl 'at' sss.pgh.pa.us> writes:

> Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr> writes:
>> Now I'm confused, why is 'sql' function much slower than 'direct' SELECT?
>
> Usually the reason for this is that the planner chooses a different plan
> when it has knowledge of the particular value you are searching for than
> when it does not.

Yes, and since Mario is coming from JDBC, I'll share my part on
this: I also noticed some very wrong plans in JDBC because of the
"optimization" in prepared statements consisting of planning once
for all runs, e.g. without any parameter values to help planning.

My understanding is that practically, it's difficult for the
planner to opt for an index (or not) because the selectivity of a
parameter value may be much different when the actual value
changes.

Normally, the planner "thinks" that planning is so costly that
it's better to plan once for all runs, but practically for our
use, this is very wrong (it may be very good for some uses,
though it would be interesting to know the actual uses share).

Until it's possible to specifically tell the JDBC driver (and/or
PG?) to not plan once for all runs (or is there something better
to think of?), or the whole thing would be more clever (off the
top of my head, PG could try to replan with the first actual
values - or first xx actual values - and if the plan is
different, then flag that prepared statement for replanning each
time if the overall time estimate is different enough), I've
opted to tell the JDBC driver to use the protocol version 2, as
prepared statements were not so much prepared back then (IIRC
parameter interpolation is performed in driver and the whole SQL
query is passed each time, parsed, and planned) using
protocolVersion=2 in the JDBC URL. So far it worked very well for
us.

--
Guillaume Cottenceau


From: Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com>
To: Guillaume Cottenceau <gc(at)mnc(dot)ch>
Cc: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, pgsql-performance(at)postgresql(dot)org, pgsql-jdbc(at)postgresql(dot)org
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-09 17:04:23
Message-ID: 1d4e0c10903091004m758d7ea2s91e33631be81215a@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

On Mon, Mar 9, 2009 at 5:51 PM, Guillaume Cottenceau <gc(at)mnc(dot)ch> wrote:
> Until it's possible to specifically tell the JDBC driver (and/or
> PG?) to not plan once for all runs (or is there something better
> to think of?), or the whole thing would be more clever (off the
> top of my head, PG could try to replan with the first actual
> values - or first xx actual values - and if the plan is
> different, then flag that prepared statement for replanning each
> time if the overall time estimate is different enough), I've
> opted to tell the JDBC driver to use the protocol version 2, as
> prepared statements were not so much prepared back then (IIRC
> parameter interpolation is performed in driver and the whole SQL
> query is passed each time, parsed, and planned) using
> protocolVersion=2 in the JDBC URL. So far it worked very well for
> us.

Unnamed prepared statements are planned after binding the values,
starting with 8.3, or more precisely starting with 8.3.2 as early 8.3
versions were partially broken on this behalf.

It's not always possible to use protocol version 2 as it's quite
limited (especially considering the exceptions returned).

--
Guillaume


From: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
To: Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com>
Cc: Guillaume Cottenceau <gc(at)mnc(dot)ch>, Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, pgsql-performance(at)postgresql(dot)org, pgsql-jdbc(at)postgresql(dot)org
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-09 17:16:34
Message-ID: 5165.1236618994@sss.pgh.pa.us
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com> writes:
> Unnamed prepared statements are planned after binding the values,
> starting with 8.3, or more precisely starting with 8.3.2 as early 8.3
> versions were partially broken on this behalf.

No, 8.2 did it too (otherwise we wouldn't have considered 8.3.0 to be
broken...). The thing I'm not too clear about is what "use of an
unnamed statement" translates to for a JDBC user.

regards, tom lane


From: Andreas Wenk <a(dot)wenk(at)netzmeister-st-pauli(dot)de>
To: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
Cc: Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com>, Guillaume Cottenceau <gc(at)mnc(dot)ch>, Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, pgsql-performance(at)postgresql(dot)org, pgsql-jdbc(at)postgresql(dot)org
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-09 17:42:16
Message-ID: 49B554F8.7090603@netzmeister-st-pauli.de
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance


Tom Lane schrieb:
> Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com> writes:
>> Unnamed prepared statements are planned after binding the values,
>> starting with 8.3, or more precisely starting with 8.3.2 as early 8.3
>> versions were partially broken on this behalf.
>
> No, 8.2 did it too (otherwise we wouldn't have considered 8.3.0 to be
> broken...). The thing I'm not too clear about is what "use of an
> unnamed statement" translates to for a JDBC user.
>
> regards, tom lane
>
I followed another post in the PHP List. Andrew McMillan was talking
about his experiences with udf's in Oracle and PG (--> look for subject:
Re: [PHP] pl/php for windows). He was writing that, by using udf's, the
planner sometimes uses strange and not performant plans. So generally I
understood that using udf's is a good idea - compared with the work I
have to do when I code that e.g in PHP and also compared to the better
resulting performance with udf's. So what is your experience with using
udf's (plpgsql)? Is there something like "use it in this case but not in
that case"?

Your answers are very welcome ...

Cheers

Andy


From: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>
To: pgsql-performance(at)postgresql(dot)org
Subject: Re: Query much slower when run from postgres function
Date: 2009-03-09 19:13:01
Message-ID: 49B56A3D.8000100@megafon.hr
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

Tom Lane wrote:
> Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr> writes:
>> Now I'm confused, why is 'sql' function much slower than 'direct' SELECT?
>
> Usually the reason for this is that the planner chooses a different plan
> when it has knowledge of the particular value you are searching for than
> when it does not. I suppose 'service_id' has a very skewed distribution
> and you are looking for an uncommon value?

I don't think so. Here is distribution for the messages_memo_displayed
table (joined with messages, just to show how many messages of each
service_id are there in messages_memo_displayed):

pulitzer2=# select service_id, count(*) from messages join
messages_memo_displayed on id = message_id group by service_id order by
service_id;
service_id | count
------------+-------
504 | 2
1790 | 1922
1814 | 1
1816 | 57
1818 | 3
(5 rows)

And the sizes of other tables involved:

pulitzer2=# select count(*) from messages_memo_displayed;
count
-------
1985
(1 row)

Time: 0.602 ms
pulitzer2=#

pulitzer2=# select count(*) from messages;
count
---------
1096388
(1 row)

Time: 345.267 ms
pulitzer2=# select count(*) from messages_memo;
count
--------
776238
(1 row)

Time: 133.942 ms
pulitzer2=#

As I've mentioned earlier, I have created an view, for the sake of this
posting:

CREATE OR REPLACE VIEW _v1 AS
SELECT messages.id, messages."from", messages."to",
messages.receiving_time, messages.raw_text, messages.keyword,
messages.destination_id, messages.vpn_id, messages.service_id,
messages.status, messages.gateway_message_id, messages.prize_id,
messages.tan, messages_memo.memo, messages_memo.state,
messages_memo.displayed, messages_memo_displayed.admin_id
FROM messages
JOIN messages_memo ON messages.id = messages_memo.message_id
LEFT JOIN messages_memo_displayed ON messages.id =
messages_memo_displayed.message_id
WHERE messages_memo.state::integer = 1 AND
messages_memo_displayed.admin_id IS NULL;

And then I created a function:

CREATE OR REPLACE FUNCTION
__new__get_memo_display_queue_size(a_service_id integer)
RETURNS integer AS
$BODY$
SELECT
COUNT(*)::int4
FROM
_v1
WHERE
service_id = $1
$BODY$
LANGUAGE 'sql' VOLATILE SECURITY DEFINER;

Now, here are the differences:
pulitzer2=# select count(*) from _v1 where service_id = 504;
count
-------
0
(1 row)

Time: 6.101 ms
pulitzer2=# select __new__get_memo_display_queue_size(504);
__new__get_memo_display_queue_size
------------------------------------
0
(1 row)

Time: 322.555 ms
pulitzer2=# select count(*) from _v1 where service_id = 1790;
count
-------
1
(1 row)

Time: 25.203 ms
pulitzer2=# select __new__get_memo_display_queue_size(1790);
__new__get_memo_display_queue_size
------------------------------------
1
(1 row)

Time: 225.763 ms
pulitzer2=# select count(*) from _v1 where service_id = 1814;
count
-------
2
(1 row)

Time: 13.662 ms
pulitzer2=# select __new__get_memo_display_queue_size(1814);
__new__get_memo_display_queue_size
------------------------------------
2
(1 row)

Time: 215.251 ms
pulitzer2=# select count(*) from _v1 where service_id = 1816;
count
-------
1
(1 row)

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

Time: 220.457 ms
pulitzer2=# select count(*) from _v1 where service_id = 1829;
count
-------
13
(1 row)

Time: 2.023 ms
pulitzer2=# select __new__get_memo_display_queue_size(1829);
__new__get_memo_display_queue_size
------------------------------------
13
(1 row)

Time: 221.956 ms
pulitzer2=#

Is this difference normal? I tend to have the interface between the
database and the application trough functions, and I'd like not to
include 'SELECT COUNT(*)...' in my Java code (at least, if I don't have
to! - esp. because I'm not Java developer on the project).

Then, this is also interesting, I think! I'm telling the planer never to
use sequential scan:

pulitzer2=# set enable_seqscan to false;
SET
Time: 0.150 ms
pulitzer2=# select __new__get_memo_display_queue_size(1829);
__new__get_memo_display_queue_size
------------------------------------
13
(1 row)

Time: 2.412 ms
pulitzer2=# select count(*) from _v1 where service_id = 1829;
count
-------
13
(1 row)

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

Time: 2.473 ms
pulitzer2=# select count(*) from _v1 where service_id = 1816;
count
-------
1
(1 row)

Time: 2.117 ms
pulitzer2=#

Now the the execution times are almost the same.

So, why this difference in the first place, and, what should I do to
have satisfying results when calling a postgres function?
I could rewrite the function from plain sql to plpgsql, and add 'SET
enable_seqscan TO false' before getting the count, and add 'SET
enable_seqscan TO true' after getting the count, but as I was explained
on pg-jdbc mailinglist that is not the way to go.

And I still don't understand why do I have excellent times when I force
planner not to use sequential scan inside the function, but when
'calling' the query from plain sql (SELECT COUNT(*) FROM _v1 WHERE),
execution time is always around 2-4ms, regardles of the value of
enable_seqscan parametar.

Mike


From: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>
To: pgsql-performance(at)postgresql(dot)org
Cc: pgsql-jdbc(at)postgresql(dot)org
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-09 19:26:05
Message-ID: 49B56D4D.9090605@megafon.hr
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

Guillaume Cottenceau wrote:
>>> Now I'm confused, why is 'sql' function much slower than 'direct' SELECT?
>> Usually the reason for this is that the planner chooses a different plan
>> when it has knowledge of the particular value you are searching for than
>> when it does not.
>
> Yes, and since Mario is coming from JDBC, I'll share my part on
> this: I also noticed some very wrong plans in JDBC because of the
> "optimization" in prepared statements consisting of planning once
> for all runs, e.g. without any parameter values to help planning.
>

For what is worth:

When I call postgres function via JDBC, I have almost the same execution
time as when calling function from psql.

When I call SELECT COUNT(*)... WHERE... query from JDBC, I again have
almost the same execution time as when executing query from psql.

Postgres function takes around 200ms, and SELECT query takes around 2-4ms.

Mike


From: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
To: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>
Cc: pgsql-performance(at)postgresql(dot)org
Subject: Re: Query much slower when run from postgres function
Date: 2009-03-09 19:51:58
Message-ID: 14317.1236628318@sss.pgh.pa.us
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

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

prepare foo(int) as
SELECT
COUNT(*)::int4
FROM
_v1
WHERE
service_id = $1
;

execute foo(504);

which should produce results similar to the function. You could
then use "explain analyze execute" to probe further into what's
happening.

regards, tom lane


From: Dave Cramer <pg(at)fastcrypt(dot)com>
To: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
Cc: Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com>, Guillaume Cottenceau <gc(at)mnc(dot)ch>, Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, pgsql-performance(at)postgresql(dot)org, pgsql-jdbc(at)postgresql(dot)org
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-09 19:56:53
Message-ID: 491f66a50903091256n7fe4a3f6i93267d0d53b983cb@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

On Mon, Mar 9, 2009 at 1:16 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com> writes:
> > Unnamed prepared statements are planned after binding the values,
> > starting with 8.3, or more precisely starting with 8.3.2 as early 8.3
> > versions were partially broken on this behalf.
>
> No, 8.2 did it too (otherwise we wouldn't have considered 8.3.0 to be
> broken...). The thing I'm not too clear about is what "use of an
> unnamed statement" translates to for a JDBC user.
>

Tom,

The driver will use unnamed statements for all statements until it sees the
same statement N times where N is 5 I believe, after that it uses a named
statement.

Dave


From: James Mansion <james(at)mansionfamily(dot)plus(dot)com>
To: Dave Cramer <pg(at)fastcrypt(dot)com>
Cc: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>, Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com>, Guillaume Cottenceau <gc(at)mnc(dot)ch>, Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, pgsql-performance(at)postgresql(dot)org, pgsql-jdbc(at)postgreSQL(dot)org
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-09 20:35:14
Message-ID: 49B57D82.4030706@mansionfamily.plus.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance


>
> The driver will use unnamed statements for all statements until it
> sees the same statement N times where N is 5 I believe, after that it
> uses a named statement.
>
>
Shame there's no syntax for it to pass the a table of the parameters to
the server when it creates the named statement as planner hints.

James


From: Scott Carey <scott(at)richrelevance(dot)com>
To: Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com>, Guillaume Cottenceau <gc(at)mnc(dot)ch>
Cc: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, "pgsql-performance(at)postgresql(dot)org" <pgsql-performance(at)postgresql(dot)org>, "pgsql-jdbc(at)postgresql(dot)org" <pgsql-jdbc(at)postgresql(dot)org>
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-09 20:56:01
Message-ID: C5DAD06F.31CB%scott@richrelevance.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance


1. And how do you do that from JDBC? There is no standard concept of 'unnamed' prepared statements in most database APIs, and if there were the behavior would be db specific. Telling PG to plan after binding should be more flexible than unnamed prepared statements - or at least more transparent to standard APIs. E.g. SET plan_prepared_postbind='true'.
2. How do you use those on a granularity other than global from jdbc? ( - I tried setting max_prepared_transactions to 0 but this didn't seem to work either, and it would be global if it did). Prepared statements are still great for things like selecting off a primary key, or especially inserts. Controls at the connection or user level would be significantly more valuable than global ones.
3. Is it possible to test them from psql? (documentation is weak, PREPARE requires a name, functions require names, etc .. C api has docs but that's not of use for most).

I'd love to know if there were answers to the above that were workable.

In the end, we had to write our own client side code to deal with sql injection safely and avoid jdbc prepared statements to get acceptable performance in many cases (all cases involving partitioned tables, a few others). At least dollar-quotes are powerful and useful for dealing with this. Since the most important benefit of prepared statements is code clarity and sql injection protection, its sad to see weakness in control/configuration over prepared statement behavior at the parse/plan level get in the way of using them for those benefits.

On 3/9/09 9:04 AM, "Guillaume Smet" <guillaume(dot)smet(at)gmail(dot)com> wrote:

On Mon, Mar 9, 2009 at 5:51 PM, Guillaume Cottenceau <gc(at)mnc(dot)ch> wrote:
> Until it's possible to specifically tell the JDBC driver (and/or
> PG?) to not plan once for all runs (or is there something better
> to think of?), or the whole thing would be more clever (off the
> top of my head, PG could try to replan with the first actual
> values - or first xx actual values - and if the plan is
> different, then flag that prepared statement for replanning each
> time if the overall time estimate is different enough), I've
> opted to tell the JDBC driver to use the protocol version 2, as
> prepared statements were not so much prepared back then (IIRC
> parameter interpolation is performed in driver and the whole SQL
> query is passed each time, parsed, and planned) using
> protocolVersion=2 in the JDBC URL. So far it worked very well for
> us.

Unnamed prepared statements are planned after binding the values,
starting with 8.3, or more precisely starting with 8.3.2 as early 8.3
versions were partially broken on this behalf.

It's not always possible to use protocol version 2 as it's quite
limited (especially considering the exceptions returned).

--
Guillaume

--
Sent via pgsql-performance mailing list (pgsql-performance(at)postgresql(dot)org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance


From: Oliver Jowett <oliver(at)opencloud(dot)com>
To: Dave Cramer <pg(at)fastcrypt(dot)com>
Cc: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>, Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com>, Guillaume Cottenceau <gc(at)mnc(dot)ch>, Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, pgsql-performance(at)postgresql(dot)org, pgsql-jdbc(at)postgresql(dot)org, scott(at)richrelevance(dot)com
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-09 21:31:42
Message-ID: 49B58ABE.7070105@opencloud.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

Dave Cramer wrote:
>
>
> On Mon, Mar 9, 2009 at 1:16 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us
> <mailto:tgl(at)sss(dot)pgh(dot)pa(dot)us>> wrote:
>
> Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com
> <mailto:guillaume(dot)smet(at)gmail(dot)com>> writes:
> > Unnamed prepared statements are planned after binding the values,
> > starting with 8.3, or more precisely starting with 8.3.2 as early 8.3
> > versions were partially broken on this behalf.
>
> No, 8.2 did it too (otherwise we wouldn't have considered 8.3.0 to be
> broken...). The thing I'm not too clear about is what "use of an
> unnamed statement" translates to for a JDBC user.
>
>
> Tom,
>
> The driver will use unnamed statements for all statements until it sees
> the same statement N times where N is 5 I believe, after that it uses a
> named statement.

Right, with the caveat that "the same statement" means "exactly the same
PreparedStatement object". If you happen to run the same (textual) query
via two different PreparedStatement objects, they're still considered
different queries for the purposes of this threshold.

You can also tune the threshold via the prepareThreshold parameter in
the driver URL, or use org.postgresql.PGStatement.setPrepareThreshold
(an extension interface implemented by the driver on its Statement
objects) on a per-statement basis.

prepareThreshold=0 is a special value that means "never use a named
statement".

The idea behind the threshold is that if a PreparedStatement object is
reused, that's a fairly good indication that the application wants to
run the same query many times with different parameters (since it's
going to the trouble of preserving the statement object for reuse). But
it's all tunable if needed.

Also see http://jdbc.postgresql.org/documentation/head/server-prepare.html

-O


From: Oliver Jowett <oliver(at)opencloud(dot)com>
To: Scott Carey <scott(at)richrelevance(dot)com>
Cc: Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com>, Guillaume Cottenceau <gc(at)mnc(dot)ch>, Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, "pgsql-performance(at)postgresql(dot)org" <pgsql-performance(at)postgresql(dot)org>, "pgsql-jdbc(at)postgresql(dot)org" <pgsql-jdbc(at)postgresql(dot)org>
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-09 21:40:26
Message-ID: 49B58CCA.8060308@opencloud.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

Scott Carey wrote:
>
> 1. And how do you do that from JDBC? There is no standard concept of
> ‘unnamed’ prepared statements in most database APIs, and if there
> were the behavior would be db specific. Telling PG to plan after
> binding should be more flexible than unnamed prepared statements —
> or at least more transparent to standard APIs. E.g. SET
> plan_prepared_postbind=’true’.

I've suggested that as a protocol-level addition in the past, but it
would mean a new protocol version. The named vs. unnamed statement
behaviour was an attempt to crowbar it into the protocol without
requiring a version change. If it's really a planner behaviour thing,
maybe it does belong at the SET level, but I believe that there's
usually an aversion to having to SET anything per query to get
reasonable plans.

> 2. How do you use those on a granularity other than global from jdbc?

prepareThreshold=N (as part of a connection URL),
org.postgresql.PGConnection.setPrepareThreshold() (connection-level
granularity), org.postgresql.PGStatement.setPrepareThreshold()
(statement-level granularity). See the driver docs.

> ( — I tried setting max_prepared_transactions to 0 but this
> didn’t seem to work either, and it would be global if it did).

max_prepared_transactions is to do with two-phase commit, not prepared
statements.

> In the end, we had to write our own client side code to deal with sql
> injection safely and avoid jdbc prepared statements to get acceptable
> performance in many cases (all cases involving partitioned tables, a few
> others). At least dollar-quotes are powerful and useful for dealing
> with this. Since the most important benefit of prepared statements is
> code clarity and sql injection protection, its sad to see weakness in
> control/configuration over prepared statement behavior at the parse/plan
> level get in the way of using them for those benefits.

It's unfortunate that ended up doing this, because it >is< all
configurable on the JDBC side. Did you ask on pgsql-jdbc?

-O


From: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>
To: pgsql-performance(at)postgresql(dot)org
Subject: Re: Query much slower when run from postgres function
Date: 2009-03-09 22:13:32
Message-ID: 49B5948C.3050800@megafon.hr
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

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


From: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
To: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>
Cc: pgsql-performance(at)postgresql(dot)org
Subject: Re: Query much slower when run from postgres function
Date: 2009-03-09 23:36:10
Message-ID: 17869.1236641770@sss.pgh.pa.us
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr> writes:
> So, it is the same. When I do EXPLAIN ANALYZE EXECUTE I get completely
> different execution plan:
> ...
> -> 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)

Well, there's the problem: without knowing what the specific service_id
is, the planner is estimating 12848 matching rows, which is evidently
off by a couple of orders of magnitude. And that's pushing it to adopt
a hash join instead of a nestloop. Are you sure the stats on this
table are up to date? Maybe you need to increase the stats target?

regards, tom lane


From: Scott Carey <scott(at)richrelevance(dot)com>
To: Oliver Jowett <oliver(at)opencloud(dot)com>
Cc: Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com>, Guillaume Cottenceau <gc(at)mnc(dot)ch>, Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, "pgsql-performance(at)postgresql(dot)org" <pgsql-performance(at)postgresql(dot)org>, "pgsql-jdbc(at)postgresql(dot)org" <pgsql-jdbc(at)postgresql(dot)org>
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-10 03:38:50
Message-ID: C5DB2ED8.31FD%scott@richrelevance.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

On 3/9/09 1:40 PM, "Oliver Jowett" <oliver(at)opencloud(dot)com> wrote:

Scott Carey wrote:
>
> 1. And how do you do that from JDBC? There is no standard concept of

I've suggested that as a protocol-level addition in the past, but it
would mean a new protocol version. The named vs. unnamed statement
behaviour was an attempt to crowbar it into the protocol without
requiring a version change. If it's really a planner behaviour thing,
maybe it does belong at the SET level, but I believe that there's
usually an aversion to having to SET anything per query to get
reasonable plans.

There's a strong aversion, but I find myself re-writing queries to get good plans, a de-facto hint really. Its mandatory in the land of partitioned tables and large aggregates, much more rare elsewhere. I have a higher aversion to rewriting queries then telling the planner to use more information or to provide it with more information.

> 2. How do you use those on a granularity other than global from jdbc?

prepareThreshold=N (as part of a connection URL),
org.postgresql.PGConnection.setPrepareThreshold() (connection-level
granularity), org.postgresql.PGStatement.setPrepareThreshold()
(statement-level granularity). See the driver docs.

I know I've tried the connection URL thing one time and that did not fix the performance problem. I did not know if it was user error. Without knowing how to trace what the query really was or if the setting was working properly, or having any other easy avenue to see if an unnamed prepared statement even fixed my problem, I had to resort to what would clearly fix it (there was only 1 day to fix it, and there was one proven way to fix it). I would love to be able to try out an unnamed prepared statement in psql, to prove that it even works to solve the query planning issue or not. In the end, it was simpler to change the code and probably less time consuming than all the options other than the connection URL setting.

> ( - I tried setting max_prepared_transactions to 0 but this
> didn't seem to work either, and it would be global if it did).

max_prepared_transactions is to do with two-phase commit, not prepared
statements.

Thanks! Good to know, the configuration documentation could be more clear... I got the two prepares confused.

> In the end, we had to write our own client side code to deal with sql
> injection safely and avoid jdbc prepared statements to get acceptable

It's unfortunate that ended up doing this, because it >is< all
configurable on the JDBC side. Did you ask on pgsql-jdbc?

-O

I searched the archives, and did find a reference to the connection URL setting and recall trying that but not seeing the expected result. Rather than debugging, a decision was made to go with the solution that worked and be done with it. This was also when we were in production on 8.3.1 or 8.3.2 or so, so the bugs there might have caused some confusion in the rush to solve the issue.

I'm still not sure that unnamed prepared statements will help my case. If the driver is using unnamed prepared statements for the first 5 uses of a query then naming it, I should see the first 5 uses significantly faster than those after. I'll keep an eye out for that in the places where we are still using prepared statements that can cause problems and in the old log files. Until another issue comes up, there isn't sufficient motivation to fix what is no longer broken for us.

Thanks for the good info on dealing with configuring unnamed prepared statements with the jdbc driver. That may come in very handy later.


From: Guillaume Cottenceau <gc(at)mnc(dot)ch>
To: Oliver Jowett <oliver(at)opencloud(dot)com>
Cc: pgsql-jdbc(at)postgresql(dot)org
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-10 08:05:52
Message-ID: 87bps9ls4f.fsf@meuh.mnc.lan
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

Oliver Jowett <oliver 'at' opencloud.com> writes:

> The idea behind the threshold is that if a PreparedStatement object is
> reused, that's a fairly good indication that the application wants to
> run the same query many times with different parameters (since it's
> going to the trouble of preserving the statement object for reuse). But

Or it may just need the safeness of driver/database parameter
"interpolation", to get a "free" efficient safeguard against SQL
injection. As for myself, I have found no other way to obtain
driver/database parameter interpolation. So sometimes I use
prepared statements even for running a query only once. I am
unsure it is a widely used pattern, but SQL injection being quite
important to fight against, I think I may not be the only one.

--
Guillaume Cottenceau


From: Oliver Jowett <oliver(at)opencloud(dot)com>
To: Guillaume Cottenceau <gc(at)mnc(dot)ch>
Cc: pgsql-jdbc(at)postgresql(dot)org
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-10 08:39:44
Message-ID: 49B62750.6090103@opencloud.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

Guillaume Cottenceau wrote:
> Oliver Jowett <oliver 'at' opencloud.com> writes:
>
>> The idea behind the threshold is that if a PreparedStatement object is
>> reused, that's a fairly good indication that the application wants to
>> run the same query many times with different parameters (since it's
>> going to the trouble of preserving the statement object for reuse). But
>
> Or it may just need the safeness of driver/database parameter
> "interpolation", to get a "free" efficient safeguard against SQL
> injection.

In which case, the application usually throws the PreparedStatement
object away after executing it once, and the threshold is never reached.
As I said, the application has to do extra work to preserve exactly the
same PreparedStatement object for reuse before the threshold applies, at
which point it's reasonable to assume that it could be a
performance-sensitive query that would benefit from preserving the query
plan and avoiding parse/plan costs on every execution.

It's just a heuristic because there *is* a tradeoff and many/most
applications are not going to be customized specifically to know about
that tradeoff. And it's configurable because the tradeoff is not the
same in every case.

Do you have a suggestion for a better way to decide when to use a named
statement?

-O


From: Guillaume Cottenceau <gc(at)mnc(dot)ch>
To: Oliver Jowett <oliver(at)opencloud(dot)com>
Cc: pgsql-jdbc(at)postgresql(dot)org
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-10 09:41:19
Message-ID: 87wsaxk94w.fsf@meuh.mnc.lan
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

Oliver Jowett <oliver 'at' opencloud.com> writes:

> Guillaume Cottenceau wrote:
>> Oliver Jowett <oliver 'at' opencloud.com> writes:
>>
>>> The idea behind the threshold is that if a PreparedStatement object is
>>> reused, that's a fairly good indication that the application wants to
>>> run the same query many times with different parameters (since it's
>>> going to the trouble of preserving the statement object for reuse). But
>>
>> Or it may just need the safeness of driver/database parameter
>> "interpolation", to get a "free" efficient safeguard against SQL
>> injection.
>
> In which case, the application usually throws the PreparedStatement
> object away after executing it once, and the threshold is never reached.
> As I said, the application has to do extra work to preserve exactly the
> same PreparedStatement object for reuse before the threshold applies, at
> which point it's reasonable to assume that it could be a
> performance-sensitive query that would benefit from preserving the query
> plan and avoiding parse/plan costs on every execution.

Thanks for the clarification!

That may just be me, but I see two issues here: first, parsing
and planning are tied together, but parsing should be always done
first time only as I see no point in reparsing in subsequent uses
of the PreparedStatement?; second, it's still questionable that a
"performance-sensitive" query should mean benefiting from
preserving the query plan: I have seen dramatic use cases where
the preserved query plan opted for a seqscan and then the query
was orders of magnitude slower than it should because the actual
then used values would have qualified for an indexscan.

> It's just a heuristic because there *is* a tradeoff and many/most
> applications are not going to be customized specifically to know about
> that tradeoff. And it's configurable because the tradeoff is not the
> same in every case.

Yes, and it's well documented, actually. I obviously didn't read
it carefully enough last time :/ I guess my approach of using the
protocol version 2 should be replaced by unsetting the prepared
threshold.. I think I came up with that workaround after that
post from Kris:

http://archives.postgresql.org/pgsql-jdbc/2008-03/msg00070.php

because strangely, you and I intervened in that thread, but the
prepared threshold issue was not raised, so I followed the
protocolVersion=2 path. Did I miss something - e.g. is the topic
today different from the topic back then, for some reason? Am I
wrong in assuming that your "please replan this statement every
time you get new parameters" suggestion is nearly-achievable with
unsetting the prepared threshold ("nearly" being the difference
between replanning always, and replanning only when parameters
are new)?

Anyway, documentation-wise, I've tried to think of how the
documentation could be a little more aggressive with the warning:

http://zarb.org/~gc/t/jdbc-more-cautious-preparedstatements.diff

That said, there's something more: when the documentation says:

There are a number of ways to enable server side prepared
statements depending on your application's needs. The general
method is to set a threshold for a PreparedStatement.

I assume that by default server side prepared statements are
*not* enabled, although it seems to be the case, with a threshold
of 5 as a simple test shows when using driver 8.3-604.jdbc3 (on
PG 8.3.6).

I think that either they should not be enabled by default
(really, it could be better with, but it could be so much worse
that is it really a good idea to make a "dropin" use of the
driver use it?), or the documentation should clearly state they
are, and add even more warnings about potential drawbacks. WDYT?

http://zarb.org/~gc/t/jdbc-more-cautious-preparedstatements2.diff

Btw, how can the doc be built? "ant doc" failed on missing
docbook.stylesheet but I was unable to find how to set that
value.

> Do you have a suggestion for a better way to decide when to use a named
> statement?

Oh, I feel I don't have the qualifications to answer that
question, sorry! The only thing I could think of, was what I
talked about in a previous mail, e.g. save all plans of the first
xx queries before reaching the threshold, and then when the
threshold is reached, compare the global cost estimates of the
saved plans, and do not activate server side prepare if they are
too different, as caching the plan for that query would probably
yield too slow results sometimes. Ideally, I guess a new
PG-specific method should be added to activate that feature (and
set the value for "are the plans too different?"). But bear in
mind that it may be a stupid idea :)

--
Guillaume Cottenceau


From: fche(at)redhat(dot)com (Frank Ch(dot) Eigler)
To: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
Cc: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, pgsql-performance(at)postgresql(dot)org
Subject: Re: Query much slower when run from postgres function
Date: 2009-03-10 14:40:51
Message-ID: y0mr615785o.fsf@ton.toronto.redhat.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> writes:

> Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr> writes:
>> Now I'm confused, why is 'sql' function much slower than 'direct' SELECT?
>
> Usually the reason for this is that the planner chooses a different plan
> when it has knowledge of the particular value you are searching for than
> when it does not. I suppose 'service_id' has a very skewed distribution
> and you are looking for an uncommon value?

For a prepared statement, could the planner produce *several* plans,
if it guesses great sensitivity to the parameter values? Then it
could choose amongst them at run time.

- FChE


From: Kris Jurka <books(at)ejurka(dot)com>
To: Guillaume Cottenceau <gc(at)mnc(dot)ch>
Cc: Oliver Jowett <oliver(at)opencloud(dot)com>, pgsql-jdbc(at)postgresql(dot)org
Subject: Re: [PERFORM] Query much slower when run from postgres function
Date: 2009-03-10 16:55:24
Message-ID: Pine.BSO.4.64.0903101253030.15435@leary.csoft.net
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

On Tue, 10 Mar 2009, Guillaume Cottenceau wrote:

> Btw, how can the doc be built? "ant doc" failed on missing
> docbook.stylesheet but I was unable to find how to set that
> value.
>

Create a file named build.local.properties and put something like the
following in it:

docbook.stylesheet=/usr/share/sgml/docbook/stylesheet/xsl/nwalsh/xhtml/chunk.xsl
docbook.dtd=/usr/share/sgml/docbook/dtd/xml/4.2

Kris Jurka


From: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
To: fche(at)redhat(dot)com (Frank Ch(dot) Eigler)
Cc: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, pgsql-performance(at)postgresql(dot)org
Subject: Re: Query much slower when run from postgres function
Date: 2009-03-10 17:20:47
Message-ID: 355.1236705647@sss.pgh.pa.us
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

fche(at)redhat(dot)com (Frank Ch. Eigler) writes:
> For a prepared statement, could the planner produce *several* plans,
> if it guesses great sensitivity to the parameter values? Then it
> could choose amongst them at run time.

We've discussed that in the past. "Choose at runtime" is a bit more
easily said than done though --- you can't readily flip between plan
choices part way through, if you've already emitted some result rows.

regards, tom lane


From: decibel <decibel(at)decibel(dot)org>
To: Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>
Cc: pgsql-performance(at)postgresql(dot)org
Subject: Re: Query much slower when run from postgres function
Date: 2009-03-14 14:31:31
Message-ID: 5005AE34-7085-499B-8B4A-B4F5AD69B183@decibel.org
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

On Mar 9, 2009, at 8:36 AM, Mario Splivalo wrote:
> Now, as I was explained on pg-jdbc mailinglist, that 'SET
> enable_seqscan TO false' affects all queries on that persistent
> connection from tomcat, and It's not good solution. So I wanted to
> post here to ask what other options do I have.

FWIW, you can avoid that with SET LOCAL (though it would still affect
the rest of the transaction).

You could also store whatever enable_seqscan was set to in a variable
before setting it to false and then set it back when you're done.
--
Decibel!, aka Jim C. Nasby, Database Architect decibel(at)decibel(dot)org
Give your computer some brain candy! www.distributed.net Team #1828


From: decibel <decibel(at)decibel(dot)org>
To: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
Cc: fche(at)redhat(dot)com (Frank Ch(dot) Eigler), Mario Splivalo <mario(dot)splivalo(at)megafon(dot)hr>, pgsql-performance(at)postgresql(dot)org
Subject: Re: Query much slower when run from postgres function
Date: 2009-03-14 14:42:22
Message-ID: E6757F02-1F73-4DDE-A5D4-0606CC517B1C@decibel.org
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

On Mar 10, 2009, at 12:20 PM, Tom Lane wrote:
> fche(at)redhat(dot)com (Frank Ch. Eigler) writes:
>> For a prepared statement, could the planner produce *several* plans,
>> if it guesses great sensitivity to the parameter values? Then it
>> could choose amongst them at run time.
>
> We've discussed that in the past. "Choose at runtime" is a bit more
> easily said than done though --- you can't readily flip between plan
> choices part way through, if you've already emitted some result rows.

True, but what if we planned for both high and low cardinality cases,
assuming that pg_stats indicated both were a possibility? We would
have to store multiple plans for one prepared statement, which
wouldn't work well for more complex queries (if you did high and low
cardinality estimates for each table you'd end up with 2^r plans,
where r is the number of relations), so we'd need a way to cap it
somehow. Of course, whether that's easier than having the ability to
throw out a current result set and start over with a different plan
is up for debate...

On a related note, I wish there was a way to tell plpgsql not to pre-
plan a query. Sure, you can use EXECUTE, but building the query plan
is a serious pain in the rear.
--
Decibel!, aka Jim C. Nasby, Database Architect decibel(at)decibel(dot)org
Give your computer some brain candy! www.distributed.net Team #1828


From: Віталій Тимчишин <tivv00(at)gmail(dot)com>
To:
Cc: pgsql-performance(at)postgresql(dot)org
Subject: Re: Query much slower when run from postgres function
Date: 2009-03-16 13:04:18
Message-ID: 331e40660903160604v3a47fabfqef2bdd75289edb4e@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-jdbc pgsql-performance

2009/3/14 decibel <decibel(at)decibel(dot)org>

> On Mar 10, 2009, at 12:20 PM, Tom Lane wrote:
>
>> fche(at)redhat(dot)com (Frank Ch. Eigler) writes:
>>
>>> For a prepared statement, could the planner produce *several* plans,
>>> if it guesses great sensitivity to the parameter values? Then it
>>> could choose amongst them at run time.
>>>
>>
>> We've discussed that in the past. "Choose at runtime" is a bit more
>> easily said than done though --- you can't readily flip between plan
>> choices part way through, if you've already emitted some result rows.
>>
>
> True, but what if we planned for both high and low cardinality cases,
> assuming that pg_stats indicated both were a possibility? We would have to
> store multiple plans for one prepared statement, which wouldn't work well
> for more complex queries (if you did high and low cardinality estimates for
> each table you'd end up with 2^r plans, where r is the number of relations),
> so we'd need a way to cap it somehow. Of course, whether that's easier than
> having the ability to throw out a current result set and start over with a
> different plan is up for debate...
>
> On a related note, I wish there was a way to tell plpgsql not to pre-plan a
> query. Sure, you can use EXECUTE, but building the query plan is a serious
> pain in the rear.
>

I'd say it would be great for PostgreSQL to replan each execution of query
automatically if execution plan tells it would take some factor (say, x100,
configurable) more time to execute query then to plan. In this case it would
not spend many time planning for small queries, but will use the most
efficient plan possible for long queries. And even if a query can't be run
better, it would spend only 1/factor time more (1% more time for factor of
100).