I have a benchmark test which runs a query very slowly under certain
circumstances. I used Ethereal to capture the packet traffic, and
also enabled debug5 logging out of curiousity. While the slow query
is in progress, there is no log or packet activity, but the cpu is
busy. These packets are below; look for SLOW PACKETS HERE to skip all
this explanatory drudge.
This WHERE clause is fast under all conditions:
... AND (val.data = $2) AND ...
This WHERE clause is fast as a simple query, but is excruciatingly
slow as prepare / execute / fetch:
... AND (val.data $2 AND val.data $3) AND ...
My test program is in Perl and uses DBI/DBD::Pg. Postgresql version
is 8.0.3 on a dual core dual opteron with 2G of RAM. DBI is version
1.48. DBD::Pg is version 1.42. The OS is rPath Linux 2.6.15.
The test runs each SQL statement three times, first as a simple query
to preload caches, then as prepare / execute / fetch, and lastly as a
simple query again.
$sth = $dbh-prepare(sql_with_placeholders);
$dbh-selectall_arrayref(sql_with_values_substituted);
$sth-execute(@values);
$sth-fetchall_arrayref();
$dbh-selectall_arrayref(sql_with_values_substituted);
I captured packet traffic and tailed the log while these were running.
Everything is fine except one query, which took 75 seconds to run,
when the others took 3 milliseconds. During this 75 seconds, the
postmaster log showed no activity, but top showed the postmaster quite
busy.
75 seconds! That's an eternity. I can't imagine any circumstances
where it makes sense. EXPLAIN ANALYZE doesn't show the slow timing
because it requires values, not $n placeholders, and it is the prepare
/ execute operation which is so slow. I will be glad to send the log,
the packet capture file, the test program itself, and anything else
which helps. Here are the EXPLAIN statements in case it helps.
EXPLAIN for the equality WHERE clause:
felix= explain analyze SELECT sid.data, glue.key, glue.val, glue.sid FROM
key, val, sid, glue WHERE (key.data =
'x6ATArB_k1cgLp1mD5x2nzVVf2DQw4Lw1-Ow5NCzzs5Pupg6K' AND key.id = glue.key) AND
(val.data = 357354306) AND val.id = glue.val AND glue.sid = sid.id;
QUERY
PLAN
Nested Loop (cost=5.82..1119.29 rows=1 width=60) (actual
time=2.271..36.184 rows=1 loops=1)
- Hash Join (cost=5.82..1116.27 rows=1 width=16) (actual
time=2.079..35.976 rows=1 loops=1)
Hash Cond: (outer.key = inner.id)
- Nested Loop (cost=0.00..1105.43 rows=1001 width=16) (actual
time=0.315..31.820 rows=1000 loops=1)
- Index Scan using val_data_key on val (cost=0.00..6.01
rows=1 width=4) (actual time=0.119..0.123 rows=1 loops=1)
Index Cond: (data = 357354306)
- Index Scan using glue_val_idx on glue
(cost=0.00..702.58 rows=31747 width=16) (actual time=0.181..24.438 rows=1000
loops=1)
Index Cond: (outer.id = glue.val)
- Hash (cost=5.82..5.82 rows=1 width=4) (actual
time=0.292..0.292 rows=0 loops=1)
- Index Scan using key_data_key on key (cost=0.00..5.82
rows=1 width=4) (actual time=0.266..0.271 rows=1 loops=1)
Index Cond: (data =
'x6ATArB_k1cgLp1mD5x2nzVVf2DQw4Lw1-Ow5NCzzs5Pupg6K'::text)
- Index Scan using sid_pkey on sid (cost=0.00..3.01 rows=1 width=52)
(actual time=0.179..0.183 rows=1 loops=1)
Index Cond: (outer.sid = sid.id)
Total runtime: 37.880 ms
(14 rows)
EXPLAIN for the range WHERE clause:
felix= explain analyze SELECT sid.data, glue.key, glue.val, glue.sid FROM
key, val, sid, glue WHERE (key.data = 'kOSkZ5iN6sz-KqGo51aTwqZnvCKQRUH2SZ8k'
AND key.id = glue.key) AND (val.data 183722006 AND val.data 183722206) AND
val.id = glue.val AND glue.sid = sid.id;
QUERY
PLAN
---
Nested Loop (cost=5.82..1119.30 rows=1 width=60) (actual
time=15.016..15.525 rows=1 loops=1)
- Hash Join (cost=5.82..1116.27 rows=1 width=16) (actual
time=14.879..15.374 rows=1 loops=1)
Hash Cond: (outer.key = inner.id)
- Nested Loop (cost=0.00..1105.43 rows=1001 width=16) (actual
time=0.211..11.666 rows=1000 loops=1)
- Index Scan using val_data_key on val (cost=0.00..6.01
rows=1 width=4) (actual time=0.071..0.076 rows=1 loops=1)
Index Cond: ((data 183722006) AND (data
