Cursor-based results: bafflingly slow

Dear list,

I'm using setFetchSize(100) to stream results from the server, and I'm
really puzzled by how slow some queries are to execute. I don't think
I'm doing anything obviously stupid: I've setAutoCommit(false) and so
forth.

For example, here's part of the output from loglevel=2:

13:03:08.871 (2)  FE=> Parse(stmt=S_9,query="select polypeptide.feature_id
  , featureprop_type_cv.name as type_cv
  , featureprop_type.name as type
  , featureprop.value
from feature polypeptide
join featureprop on featureprop.feature_id = polypeptide.feature_id
join cvterm featureprop_type on featureprop.type_id = featureprop_type.cvterm_id
join cv featureprop_type_cv on featureprop_type.cv_id = featureprop_type.cv_id
where polypeptide.type_id in (
191
)
and polypeptide.organism_id = (
   select organism_id from organism
   where common_name = $1
)
order by polypeptide.feature_id",oids={1043})
13:03:08.877 (2)  FE=> Bind(stmt=S_9,portal=C_10,$1=<Etenella>)
13:03:08.878 (2)  FE=> Describe(portal=C_10)
13:03:08.878 (2)  FE=> Execute(portal=C_10,limit=100)
13:03:08.878 (2)  FE=> Sync


(The database schema is Chado – http://gmod.org/wiki/Schema)

It has been running for more than half an hour with no apparent
response yet. If I try to do something equivalent in psql, I can't
find any way to make it take more than a few seconds.

For example, if I use "limit 100" to simulate the effect of fetching
the first 100 results:

prepare query as
select polypeptide.feature_id
  , featureprop_type_cv.name as type_cv
  , featureprop_type.name as type
  , featureprop.value
from feature polypeptide
join featureprop on featureprop.feature_id = polypeptide.feature_id
join cvterm featureprop_type on featureprop.type_id = featureprop_type.cvterm_id
join cv featureprop_type_cv on featureprop_type.cv_id = featureprop_type.cv_id
where polypeptide.type_id in (
191
)
and polypeptide.organism_id = (
   select organism_id from organism
   where common_name = $1
)
order by polypeptide.feature_id
limit 100
;

explain analyze execute query('Etenella');

then I get:

 Limit  (cost=1.95..42662.18 rows=100 width=612) (actual
time=219.367..253.029 rows=100 loops=1)
  InitPlan
    ->  Seq Scan on organism  (cost=0.00..1.95 rows=1 width=4)
(actual time=8.175..8.196 rows=1 loops=1)
          Filter: ((common_name)::text = $1)
  ->  Nested Loop  (cost=0.00..2245634.37 rows=5264 width=612)
(actual time=219.358..252.312 rows=100 loops=1)
        ->  Nested Loop  (cost=0.00..2245341.09 rows=188 width=96)
(actual time=186.960..218.784 rows=4 loops=1)
              ->  Nested Loop  (cost=0.00..1948637.05 rows=37696
width=56) (actual time=166.944..175.615 rows=4 loops=1)
                    ->  Index Scan using feature_genedb_idx1 on
feature polypeptide  (cost=0.00..108669.87 rows=32192 width=4) (actual
time=66.732..66.732 rows=1 loops=1)
                          Index Cond: ((organism_id = $0) AND (type_id = 191))
                    ->  Index Scan using featureprop_idx1 on
featureprop  (cost=0.00..55.64 rows=121 width=56) (actual
time=100.187..108.833 rows=4 loops=1)
                          Index Cond: (featureprop.feature_id =
polypeptide.feature_id)
              ->  Index Scan using cvterm_pkey on cvterm
featureprop_type  (cost=0.00..7.86 rows=1 width=52) (actual
time=10.766..10.771 rows=1 loops=4)
                    Index Cond: (featureprop_type.cvterm_id =
featureprop.type_id)
                    Filter: (featureprop_type.cv_id = featureprop_type.cv_id)
        ->  Seq Scan on cv featureprop_type_cv  (cost=0.00..1.28
rows=28 width=516) (actual time=8.101..8.193 rows=25 loops=4)
 Total runtime: 270.637 ms


Any suggestions?

Thanks,
Robin