Re: Slow statement when using 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(at)truviso(dot)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
>