Re: Slow query after upgrades

On Dec 13, 2007, at 3:58 PM, Guillaume Smet wrote:

> On Dec 13, 2007 10:28 PM, Tom Duffey <tduffey(at)techbydesign(dot)com> wrote:
>> The odd thing is that the same query is used in other components of
>> the application and we have not noticed any issues. This led me to
>> believe that something about this particular piece is causing the
>> problem, possibly external to the query or the JDBC driver. Running
>> the query in psql, for example, doesn't seem slow at all. So maybe
>> it's not a PostgreSQL problem at all but I thought someone might have
>> seen this and have some insight into where I should look.
>
> Usual questions: did you analyze your database after loading the dump?

Yes.

> One of the problem you can meet is that the new driver uses protocol
> v3 by default, which means that your query are prepared and planned
> without the value of the parameters as it was the case using v2 of the
> protocol. This can lead in bad plans in specific cases.
> You may consider using protocol v2 again if it's your problem by
> adding protocolVersion=2 to your JDBC connection URL.
>
>> Is there some logging I can use to compare what is happening on the
>> server side when this query is run by the app with the problem vs.
>> something else (psql or another of our applications)?
>
> Use log_min_duration_statement in your postgresql.conf (0 if you want
> to log every queries).

This seems to be exactly what is happening. The old driver executes
the query in 2.6ms while the new driver takes 63516.5ms. It's worth
pointing out that this is a large table containing 310646676 rows and
growing.

Here is the log output when executing the query in psql:

LOG: duration: 15.771 ms statement: SELECT point_history.point_id,
point_history.timestamp, point_history.value, point_history.status
FROM point_history WHERE point_history.point_id = 21001 AND poi
nt_history.timestamp >= '2007-12-11 22:22:45' ORDER BY
point_history.timestamp DESC;

Then the pg74.216.jdbc3 driver:

LOG: duration: 2.682 ms statement: SELECT
point_history.point_id, point_history.timestamp, point_history.value,
point_history.status FROM point_history WHERE point_history.point_id =
21001 AND point_history.timestamp >= '2007-12-11
22:27:41'

And the 8.2 JDBC4 driver:

LOG: duration: 1.047 ms parse <unnamed>: SELECT
point_history.point_id, point_history.timestamp, point_history.value,
point_history.status FROM point_history WHERE point_history.point_id =
$1 AND point_history.timestamp >= $2 ORDER BY point_history.timestamp
DESC
LOG: duration: 0.335 ms bind <unnamed>: SELECT
point_history.point_id, point_history.timestamp, point_history.value,
point_history.status FROM point_history WHERE point_history.point_id =
$1 AND point_history.timestamp >=
$2 ORDER BY point_history.timestamp DESC
DETAIL: parameters: $1 = '21001', $2 = '2007-12-11 22:22:45'
LOG: duration: 63516.530 ms execute <unnamed>: SELECT
point_history.point_id, point_history.timestamp, point_history.value,
point_history.status FROM point_history WHERE point_history.point_id =
$1 AND point_history.timestamp >=
$2 ORDER BY point_history.timestamp DESC
DETAIL: parameters: $1 = '21001', $2 = '2007-12-11 22:22:45'

Here's what explain has to say about this query:

foo=> EXPLAIN SELECT point_history.point_id, point_history.timestamp,
point_history.value, point_history.status FROM point_history WHERE
point_history.point_id = 21001 AND point_history.timestamp >=
'2007-12-11 22:22:45' ORDER BY point_history.timestamp DESC;
QUERY PLAN
------------------------------------------------------------------------------------------------------------
Index Scan Backward using point_history_pkey on point_history
(cost=0.00..264.60 rows=58 width=20)
Index Cond: ((point_id = 21001) AND ("timestamp" >= '2007-12-11
22:22:45'::timestamp without time zone))
(2 rows)

Any suggestions?

Tom