Hi

I have been having some serious performance issues when using prepared
statements which I can not re-produce when using a direct statement. Let
me try to explain

The query does an order by in descending order on several columns for
which an index exists.

The explain output as follows

rascal=# explain SELECT oid, * FROM calllog
WHERE calllog_mainteng = '124 '
AND calllog_phase = 8
AND calllog_self < 366942
OR calllog_mainteng = '124 '
AND calllog_phase < 8
ORDER BY calllog_mainteng DESC,
calllog_phase DESC,
calllog_self DESC limit 25;
QUERY PLAN
---------------------------------------------------------------------------------------------------------
Limit (cost=0.00..111.62 rows=25 width=2164)
-> Index Scan Backward using calllog_rmc_idx on calllog
(cost=0.00..53475.22 rows=11977 width=2164)
Index Cond: (calllog_mainteng = '124 '::bpchar)
Filter: (((calllog_phase = 8) AND (calllog_self < 366942)) OR
(calllog_phase < 8))

When running the query directly from psql it returns the required rows
in less than 100 milli-seconds.

However, when using a prepared statement from my C application on the
above query and executing it the query duration is as follows

SELECT oid, * FROM calllog
WHERE calllog_mainteng = '124 '
AND calllog_phase = 8
AND calllog_self < 366942
OR calllog_mainteng = '124 '
AND calllog_phase < 8
ORDER BY calllog_mainteng DESC,
calllog_phase DESC,
calllog_self DESC limit 25
Row[s] = 25, Duration = 435409.474 ms

The index as per the explain is defined as follows

"calllog_rmc_idx" UNIQUE, btree (calllog_mainteng, calllog_phase,
calllog_self)

VACUUM and all those good things done

Version of PostgreSQL 8.1 and 8.2

enable_seqscan = off
enable_sort = off

Any advice/suggestions/thoughts much appreciated

--
Regards
Theo


---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

Theo Kramer a écrit :
> Hi
>
> I have been having some serious performance issues when using prepared
> statements which I can not re-produce when using a direct statement. Let
> me try to explain
>
> The query does an order by in descending order on several columns for
> which an index exists.
>
> The explain output as follows
>
> rascal=# explain SELECT oid, * FROM calllog
> WHERE calllog_mainteng = '124 '
> AND calllog_phase = 8
> AND calllog_self < 366942
> OR calllog_mainteng = '124 '
> AND calllog_phase < 8
> ORDER BY calllog_mainteng DESC,
> calllog_phase DESC,
> calllog_self DESC limit 25;
> QUERY PLAN
> ---------------------------------------------------------------------------------------------------------
> Limit (cost=0.00..111.62 rows=25 width=2164)
> -> Index Scan Backward using calllog_rmc_idx on calllog
> (cost=0.00..53475.22 rows=11977 width=2164)
> Index Cond: (calllog_mainteng = '124 '::bpchar)
> Filter: (((calllog_phase = 8) AND (calllog_self < 366942)) OR
> (calllog_phase < 8))
>
> When running the query directly from psql it returns the required rows
> in less than 100 milli-seconds.
>
> However, when using a prepared statement from my C application on the
> above query and executing it the query duration is as follows
>
> SELECT oid, * FROM calllog
> WHERE calllog_mainteng = '124 '
> AND calllog_phase = 8
> AND calllog_self < 366942
> OR calllog_mainteng = '124 '
> AND calllog_phase < 8
> ORDER BY calllog_mainteng DESC,
> calllog_phase DESC,
> calllog_self DESC limit 25
> Row[s] = 25, Duration = 435409.474 ms
>
> The index as per the explain is defined as follows
>
> "calllog_rmc_idx" UNIQUE, btree (calllog_mainteng, calllog_phase,
> calllog_self)
>
> VACUUM and all those good things done
>
> Version of PostgreSQL 8.1 and 8.2
>
> enable_seqscan = off
> enable_sort = off
>
> Any advice/suggestions/thoughts much appreciated
>
Reading the manual, you can learn that prepared statement can (not)
follow the same plan as direct query:
the plan is make before pg know the value of the variable.

See 'Notes' http://www.postgresql.org/docs/8.2/i...l-prepare.html


---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

On Wed, 2007-10-10 at 17:00 +0200, Cédric Villemain wrote:
> <snip>
> Reading the manual, you can learn that prepared statement can (not)
> follow the same plan as direct query:
> the plan is make before pg know the value of the variable.
>
> See 'Notes' http://www.postgresql.org/docs/8.2/i...l-prepare.html

Thanks, had missed that, however, I am afraid that I fail to see how
preparing a query using PQprepare() and then executing it using
PQexecPrepared(), is 8 thousand times slower than directly executing
it.,, ( 403386.583ms/50.0ms = 8067 ).

When doing a 'manual' prepare and explain analyze I get the following

rascal=# prepare cq (char(12), smallint, integer) as SELECT oid,
calllog_mainteng, calllog_phase, calllog_self FROM calllog
WHERE calllog_mainteng = $1
AND calllog_phase = $2
AND calllog_self < $3
OR calllog_mainteng = $1
AND calllog_phase < $2
ORDER BY calllog_mainteng DESC,
calllog_phase DESC,
calllog_self DESC limit 25;
PREPARE
rascal=# explain analyze execute cq ('124 ', 8, 366942);
QUERY
PLAN
---------------------------------------------------------------------------
Limit (cost=0.00..232.73 rows=25 width=26) (actual time=2.992..3.178
rows=25 loops=1)
-> Index Scan Backward using calllog_rmc_idx on calllog
(cost=0.00..38651.38 rows=4152 width=26) (actual time=2.986..3.116
rows=25 loops=1)
Index Cond: (calllog_mainteng = $1)
Filter: (((calllog_phase = $2) AND (calllog_self < $3)) OR
(calllog_phase < $2))
Total runtime: 3.272 ms


So I suspect that there is something more fundamental here...

--
Regards
Theo


---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

On 10/10/07, Theo Kramer <theo@flame.co.za> wrote:
> When running the query directly from psql it returns the required rows
> in less than 100 milli-seconds.
>
> However, when using a prepared statement from my C application on the
> above query and executing it the query duration is as follows
> ...
> Row[s] = 25, Duration = 435409.474 ms
>

How are you timing it? Does it really take 435 seconds to complete?
Try the following in psql:

postgres# PREPARE yourplan (VARCHAR, INT, INT) AS
SELECT oid, * FROM calllog
WHERE calllog_mainteng = $1
AND calllog_phase = $2
AND calllog_self < $3
OR calllog_mainteng = $1
AND calllog_phase < 8
ORDER BY calllog_mainteng DESC,
calllog_phase DESC,
calllog_self DESC limit 25;

postgres# EXECUTE yourplan('124 ', 8, 366942);

--
Jonah H. Harris, Sr. Software Architect | phone: 732.331.1324
EnterpriseDB Corporation | fax: 732.331.1301
499 Thornall Street, 2nd Floor | jonah.harris@enterprisedb.com
Edison, NJ 08837 | http://www.enterprisedb.com/

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

On Wed, 2007-10-10 at 15:55 -0400, Jonah H. Harris wrote:
> On 10/10/07, Theo Kramer <theo@flame.co.za> wrote:
> > When running the query directly from psql it returns the required rows
> > in less than 100 milli-seconds.
> >
> > However, when using a prepared statement from my C application on the
> > above query and executing it the query duration is as follows
> > ...
> > Row[s] = 25, Duration = 435409.474 ms
> >
>
> How are you timing it? Does it really take 435 seconds to complete?

Fraid so - and I am running postgresql on a separate machine from the
client machine - with the load going way up on the postgresql machine
and the client machine remains idle until the query returns.

Also the postgresql has only the one prepared statement executing during
my tests.

> Try the following in psql:

Did that - see my previous email.
--
Regards
Theo


---------------------------(end of broadcast)---------------------------
TIP 7: You can help support the PostgreSQL project by donating at

http://www.postgresql.org/about/donate

Theo Kramer a écrit :
> On Wed, 2007-10-10 at 17:00 +0200, Cédric Villemain wrote:
>
>> <snip>
>> Reading the manual, you can learn that prepared statement can (not)
>> follow the same plan as direct query:
>> the plan is make before pg know the value of the variable.
>>
>> See 'Notes' http://www.postgresql.org/docs/8.2/i...l-prepare.html
>>
>
> Thanks, had missed that, however, I am afraid that I fail to see how
> preparing a query using PQprepare() and then executing it using
> PQexecPrepared(), is 8 thousand times slower than directly executing
> it.,, ( 403386.583ms/50.0ms = 8067 ).
>
> When doing a 'manual' prepare and explain analyze I get the following
>
> rascal=# prepare cq (char(12), smallint, integer) as SELECT oid,
> calllog_mainteng, calllog_phase, calllog_self FROM calllog
> WHERE calllog_mainteng = $1
> AND calllog_phase = $2
> AND calllog_self < $3
> OR calllog_mainteng = $1
> AND calllog_phase < $2
> ORDER BY calllog_mainteng DESC,
> calllog_phase DESC,
> calllog_self DESC limit 25;
> PREPARE
> rascal=# explain analyze execute cq ('124 ', 8, 366942);
> QUERY
> PLAN
> ---------------------------------------------------------------------------
> Limit (cost=0.00..232.73 rows=25 width=26) (actual time=2.992..3.178
> rows=25 loops=1)
> -> Index Scan Backward using calllog_rmc_idx on calllog
> (cost=0.00..38651.38 rows=4152 width=26) (actual time=2.986..3.116
> rows=25 loops=1)
> Index Cond: (calllog_mainteng = $1)
> Filter: (((calllog_phase = $2) AND (calllog_self < $3)) OR
> (calllog_phase < $2))
> Total runtime: 3.272 ms
>
>
> So I suspect that there is something more fundamental here...
>
my two cents:
perhaps ... please check that with your C code
And be sure you are not providing time from application. If you have a
lot of data and/or a lag on your lan, it can be the cause of your so
big difference between psql and C




---------------------------(end of broadcast)---------------------------
TIP 7: You can help support the PostgreSQL project by donating at

http://www.postgresql.org/about/donate

Theo Kramer wrote:
> Thanks, had missed that, however, I am afraid that I fail to see how
> preparing a query using PQprepare() and then executing it using
> PQexecPrepared(), is 8 thousand times slower than directly executing
> it.,, ( 403386.583ms/50.0ms = 8067 ).
>
> When doing a 'manual' prepare and explain analyze I get the following

> rascal=# explain analyze execute cq ('124 ', 8, 366942);
> Total runtime: 3.272 ms
>
> So I suspect that there is something more fundamental here...

OK, so there must be something different between the two scenarios. It
can only be one of:
1. Query
2. DB Environment (user, locale, settings)
3. Network environment (server/client/network activity etc)

Are you sure you have the parameter types correct in your long-running
query?
Try setting log_min_duration_statement=9000 or so to capture
long-running queries.

Make sure the user and any custom settings are the same. Compare SHOW
ALL for both ways.

You've said elsewhere you've ruled out the network environment, so
there's not point worrying about that further.

--
Richard Huxton
Archonet Ltd

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

On Thu, 2007-10-11 at 10:12 +0100, Richard Huxton wrote:
> Theo Kramer wrote:
> >
> > So I suspect that there is something more fundamental here...
>
> OK, so there must be something different between the two scenarios. It
> can only be one of:
> 1. Query
> 2. DB Environment (user, locale, settings)
> 3. Network environment (server/client/network activity etc)

I suspect that it could also be in the way the libpq PQprepare(), and
PQexecPrepared() are handled... as opposed to the way PREPARE and
EXECUTE are handled.

>
> Are you sure you have the parameter types correct in your long-running
> query?

Yes - the problem surfaced during a going live session on an 80 user
system... and we had to roll back to the previous system in a hurry.
This was a part of the application that had missed testing, but I have
had other reports from some of my other systems where this appears to be
a problem but not of the magnitude that this one is.

In any case I have managed to reproduce it in my test environment with
configuration settings the same.

> Try setting log_min_duration_statement=9000 or so to capture
> long-running queries.

Thanks - will give that a try.

>
> Make sure the user and any custom settings are the same. Compare SHOW
> ALL for both ways.

> You've said elsewhere you've ruled out the network environment, so
> there's not point worrying about that further.

It is definitely not a network problem - ie. the postgresql server load
goes way up when this query is run.

--
Regards
Theo


---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

On 10/11/07, Theo Kramer <theo@flame.co.za> wrote:
> On Thu, 2007-10-11 at 10:12 +0100, Richard Huxton wrote:
> > Theo Kramer wrote:
> > >
> > > So I suspect that there is something more fundamental here...
> >
> > OK, so there must be something different between the two scenarios. It
> > can only be one of:
> > 1. Query
> > 2. DB Environment (user, locale, settings)
> > 3. Network environment (server/client/network activity etc)
>
> I suspect that it could also be in the way the libpq PQprepare(), and
> PQexecPrepared() are handled... as opposed to the way PREPARE and
> EXECUTE are handled.

PQexecPrepared is generally the fastest way to run queries from a C
app as long as you get the right plan. Some suggestions

* you can explain/explain analyze executing prepared statements from
psql shell...try that and see if you can reproduce results
* at worst case you can drop to execParams which is faster (and
better) than PQexec, at least
* if problem is plan related, you can always disable certain plan
types (seqscan), prepare, and re-enable those plan types
* do as Jonah suggested, first step is to try and reproduce problem from psql

merlin

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

On 10/11/07, Andrew - Supernews <andrew+nonews@supernews.com> wrote:
> On 2007-10-10, Theo Kramer <theo@flame.co.za> wrote:
> > When doing a 'manual' prepare and explain analyze I get the following
> >
> > rascal=# prepare cq (char(12), smallint, integer) as SELECT oid,
> > calllog_mainteng, calllog_phase, calllog_self FROM calllog
> > WHERE calllog_mainteng = $1
> > AND calllog_phase = $2
> > AND calllog_self < $3
> > OR calllog_mainteng = $1
> > AND calllog_phase < $2
> > ORDER BY calllog_mainteng DESC,
> > calllog_phase DESC,
> > calllog_self DESC limit 25;
> > PREPARE
>
> When you do this from the application, are you passing it 3 parameters,
> or 5? The plan is clearly taking advantage of the fact that the two
> occurrences of $1 and $2 are known to be the same value; if your app is
> using some interface that uses ? placeholders rather than numbered
> parameters, then the planner will not be able to make this assumption.
>
> Also, from the application, is the LIMIT 25 passed as a constant or is that
> also a parameter?

also, this looks a bit like a drilldown query, which is ordering the
table on 2+ fields. if that's the case, row wise comparison is a
better and faster approach. is this a converted cobol app?

merlin

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings