Re: Slow statement when using JDBC - Mailing list pgsql-jdbc

From yazan suleiman
Subject Re: Slow statement when using JDBC
Date
Msg-id AANLkTimk7b1zNOsmyeT66pnPJUvmAeN2bHa4vH5asBNV@mail.gmail.com
Whole thread Raw
In response to Re: Slow statement when using JDBC  (Maciek Sakrejda <msakrejda@truviso.com>)
Responses Re: Slow statement when using JDBC
List pgsql-jdbc
I've done more research.  This problem appears at the database level.  I excluded JDBC by running explain anaylze on 2 different statement, the first is a prepared one  The prepared showed the same behavior.  Please see below:

prepare t2 (real) AS
select
EVENT.ID, ORIGIN.ID AS ORIGINID,EVENT.PREFERRED_ORIGIN_ID AS PREFERRED_ORIGIN,
EVENT.CONTRIBUTOR, ORIGIN.TIME, ORIGIN.LATITUDE, ORIGIN.LONGITUDE, ORIGIN.DEPTH,ORIGIN.EVTYPE, ORIGIN.CATALOG, ORIGIN.AUTHOR OAUTHOR,
ORIGIN.CONTRIBUTOR OCONTRIBUTOR,MAGNITUDE.ID AS MAGID,MAGNITUDE.MAGNITUDE,MAGNITUDE.TYPE AS MAGTYPE

from event.event join event.origin on event.id=origin.eventid left join event.magnitude on origin.id=event.magnitude.origin_id

WHERE magnitude.magnitude>=$1 group by EVENT.ID, ORIGIN.ID,EVENT.PREFERRED_ORIGIN_ID, EVENT.CONTRIBUTOR,ORIGIN.TIME, ORIGIN.LATITUDE,
ORIGIN.LONGITUDE, ORIGIN.DEPTH,ORIGIN.EVTYPE, ORIGIN.CATALOG,ORIGIN.AUTHOR, ORIGIN.CONTRIBUTOR,MAGNITUDE.ID,MAGNITUDE.MAGNITUDE,MAGNITUDE.TYPE
order by MAGNITUDE.MAGNITUDE DESC;

explain analyze execute t2 (7.2);

"Group  (cost=1178550.31..1264062.63 rows=2137808 width=80) (actual time=32708.691..32713.863 rows=3198 loops=1)"
"  ->  Sort  (cost=1178550.31..1183894.83 rows=2137808 width=80) (actual time=32708.688..32709.081 rows=3198 loops=1)"
"        Sort Key: magnitude.magnitude, event.id, origin.id, event.preferred_origin_id, event.contributor, origin."time", origin.latitude, origin.longitude, origin.depth, origin.evtype, origin.catalog, origin.author, origin.contributor, magnitude.id, magnitude.type"
"        Sort Method:  quicksort  Memory: 546kB"
"        ->  Hash Join  (cost=463838.18..858790.88 rows=2137808 width=80) (actual time=21930.470..32688.144 rows=3198 loops=1)"
"              Hash Cond: (origin.eventid = event.id)"
"              ->  Hash Join  (cost=349974.86..636067.40 rows=2137808 width=72) (actual time=18213.223..28346.664 rows=3198 loops=1)"
"                    Hash Cond: (magnitude.origin_id = origin.id)"
"                    ->  Seq Scan on magnitude  (cost=0.00..158388.38 rows=2137808 width=22) (actual time=8.078..6009.938 rows=3198 loops=1)"
"                          Filter: ((magnitude)::double precision >= $1)"
"                    ->  Hash  (cost=213417.05..213417.05 rows=6133105 width=54) (actual time=18204.688..18204.688 rows=6133105 loops=1)"
"                          Buckets: 131072  Batches: 8  Memory Usage: 72865kB"
"                          ->  Seq Scan on origin  (cost=0.00..213417.05 rows=6133105 width=54) (actual time=0.015..7370.984 rows=6133105 loops=1)"
"              ->  Hash  (cost=56912.92..56912.92 rows=3276192 width=12) (actual time=3716.931..3716.931 rows=3276192 loops=1)"
"                    Buckets: 262144  Batches: 2  Memory Usage: 70620kB"
"                    ->  Seq Scan on event  (cost=0.00..56912.92 rows=3276192 width=12) (actual time=0.011..1567.850 rows=3276192 loops=1)"
"Total runtime: 32783.141 ms"



explain analyze
select
EVENT.ID, ORIGIN.ID AS ORIGINID,EVENT.PREFERRED_ORIGIN_ID AS PREFERRED_ORIGIN,
EVENT.CONTRIBUTOR, ORIGIN.TIME, ORIGIN.LATITUDE, ORIGIN.LONGITUDE, ORIGIN.DEPTH,ORIGIN.EVTYPE, ORIGIN.CATALOG, ORIGIN.AUTHOR OAUTHOR,
ORIGIN.CONTRIBUTOR OCONTRIBUTOR,MAGNITUDE.ID AS MAGID,MAGNITUDE.MAGNITUDE,MAGNITUDE.TYPE AS MAGTYPE

from event.event join event.origin on event.id=origin.eventid left join event.magnitude on origin.id=event.magnitude.origin_id

WHERE magnitude.magnitude>=7.2 group by EVENT.ID, ORIGIN.ID,EVENT.PREFERRED_ORIGIN_ID, EVENT.CONTRIBUTOR,ORIGIN.TIME, ORIGIN.LATITUDE,
ORIGIN.LONGITUDE, ORIGIN.DEPTH,ORIGIN.EVTYPE, ORIGIN.CATALOG,ORIGIN.AUTHOR, ORIGIN.CONTRIBUTOR,MAGNITUDE.ID,MAGNITUDE.MAGNITUDE,MAGNITUDE.TYPE
order by MAGNITUDE.MAGNITUDE DESC;




"Group  (cost=136246.03..136743.55 rows=12438 width=80) (actual time=124.478..129.753 rows=3198 loops=1)"
"  ->  Sort  (cost=136246.03..136277.12 rows=12438 width=80) (actual time=124.474..124.897 rows=3198 loops=1)"
"        Sort Key: magnitude.magnitude, event.id, origin.id, event.preferred_origin_id, event.contributor, origin."time", origin.latitude, origin.longitude, origin.depth, origin.evtype, origin.catalog, origin.author, origin.contributor, magnitude.id, magnitude.type"
"        Sort Method:  quicksort  Memory: 546kB"
"        ->  Nested Loop  (cost=281.58..135400.09 rows=12438 width=80) (actual time=2.250..103.318 rows=3198 loops=1)"
"              ->  Nested Loop  (cost=281.58..127177.93 rows=12438 width=72) (actual time=2.234..67.745 rows=3198 loops=1)"
"                    ->  Bitmap Heap Scan on magnitude  (cost=281.58..31203.00 rows=12438 width=22) (actual time=2.155..5.464 rows=3198 loops=1)"
"                          Recheck Cond: (magnitude >= 7.2)"
"                          ->  Bitmap Index Scan on mag_index  (cost=0.00..278.47 rows=12438 width=0) (actual time=1.763..1.763 rows=3198 loops=1)"
"                                Index Cond: (magnitude >= 7.2)"
"                    ->  Index Scan using origin_id_key on origin  (cost=0.00..7.70 rows=1 width=54) (actual time=0.017..0.017 rows=1 loops=3198)"
"                          Index Cond: (origin.id = magnitude.origin_id)"
"              ->  Index Scan using event_key_index on event  (cost=0.00..0.65 rows=1 width=12) (actual time=0.009..0.010 rows=1 loops=3198)"
"                    Index Cond: (event.id = origin.eventid)"
"Total runtime: 130.206 ms"

Can I force it to follow a certain plan?

Thanks

On Wed, Feb 2, 2011 at 1:59 PM, Maciek Sakrejda <msakrejda@truviso.com> wrote:
> For queries like this, you want to be sure that the query is planned
> each time based on the actual value.

Which I think *is* the case until you hit prepareThreshold in JDBC,
no? This has come up on the list before, and as long as you're using
an unnamed server-side prepared statement, the planner will wait to
plan it until it has the actual parameters available. That's why the
planning savings of having the JDBC driver "upgrade" you to named
statements after a few executions can come back to bite you: a
parameter-agnostic plan will often be *much* costlier than re-planning
every single time.

However, since Yazan is seeing this right off the bat (and not after a
certain number of executions), I'm suspicious. It'd be nice to see
what's happening here at the protocol level. Yazan, can you configure
driver-level logging through the loglevel connection param and
DriverManager.setLogWriter()?

---
Maciek Sakrejda | System Architect | Truviso

1065 E. Hillsdale Blvd., Suite 215
Foster City, CA 94404
www.truviso.com

pgsql-jdbc by date:

Previous
From: Maciek Sakrejda
Date:
Subject: Re: Slow statement when using JDBC
Next
From: Tom Lane
Date:
Subject: Re: Slow statement when using JDBC