The same query - much different runtimes

[Johann Spies <johann.spies@xxxxxxxxx>]

While waiting for a query to finish (activated through a web interface), I ran the same query using psql through a ssh-connection with much different runtimes.

I have configured the server to log queries taking more than five seconds and in the log the query for which I waited was logged as:

2014-04-07 12:01:38 SAST LOG:  duration: 466754.684 ms  plan:
        Query Text: SELECT  isi_alt_names.code FROM rresearch, isi_alt_names WHERE ((((UPPER(rresearch.ny) = 'GUANGZHOU') AND\
 (UPPER(rresearch.nu) = 'PEOPLES R CHINA')) AND (isi_alt_names.rsc_id = rresearch.id)) AND (isi_alt_names.code IS NOT NULL)) \
ORDER BY rresearch.id, isi_alt_names.id LIMIT 2 OFFSET 0;
        Limit  (cost=384216.93..384216.94 rows=2 width=15)
          ->  Sort  (cost=384216.93..384244.77 rows=11137 width=15)
                Sort Key: rresearch.id, isi_alt_names.id
                ->  Nested Loop  (cost=138757.99..384105.56 rows=11137 width=15)
                      ->  Bitmap Heap Scan on rresearch  (cost=138757.99..161224.50 rows=11337 width=4)
                            Recheck Cond: ((upper((ny)::text) = 'GUANGZHOU'::text) AND (upper((nu)::text) = 'PEOPLES R CHINA'\
::text))
                            ->  BitmapAnd  (cost=138757.99..138757.99 rows=11337 width=0)
                                  ->  Bitmap Index Scan on rresearch_ny_idx  (cost=0.00..4930.62 rows=215233 width=0)
                                        Index Cond: (upper((ny)::text) = 'GUANGZHOU'::text)
                                  ->  Bitmap Index Scan on rresearch_nu_idx  (cost=0.00..133821.46 rows=6229156 width=0)
                                        Index Cond: (upper((nu)::text) = 'PEOPLES R CHINA'::text)
                      ->  Index Scan using isi_alt_countrynames_rsc_id_idx on isi_alt_names  (cost=0.00..19.65 rows=1 width=1\
5)
                            Index Cond: (rsc_id = rresearch.id)
                            Filter: (code IS NOT NULL)

While this was going on, I only changed the query to include the schema (the web-based query used search_path) and ran it.  Query Analyze said:

"Limit  (cost=384288.35..384288.36 rows=2 width=15) (actual time=2945.338..2945.340 rows=2 loops=1)"
"  Output: isi_alt_names.code, rresearch.id, isi_alt_names.id"
"  Buffers: shared hit=1408146"
"  ->  Sort  (cost=384288.35..384316.20 rows=11137 width=15) (actual time=2945.338..2945.338 rows=2 loops=1)"
"        Output: isi_alt_names.code, rresearch.id, isi_alt_names.id"
"        Sort Key: rresearch.id, isi_alt_names.id"
"        Sort Method: top-N heapsort  Memory: 25kB"
"        Buffers: shared hit=1408146"
"        ->  Nested Loop  (cost=138757.99..384176.98 rows=11137 width=15) (actual time=1530.875..2876.376 rows=241920 loops=1)"
"              Output: isi_alt_names.code, rresearch.id, isi_alt_names.id"
"              Buffers: shared hit=1408146"
"              ->  Bitmap Heap Scan on isi.rresearch  (cost=138757.99..161224.50 rows=11337 width=4) (actual time=1530.848..1750.169 rows=241337 loops=1)"
"                    Output: rresearch.id, rresearch.cn, rresearch.nf, rresearch.nc, rresearch.nd, rresearch.nn, rresearch.ny, rresearch.np, rresearch.nu, rresearch.nz, rresearch.uuid, rresearch.tsv"
"                    Recheck Cond: ((upper((rresearch.ny)::text) = 'GUANGZHOU'::text) AND (upper((rresearch.nu)::text) = 'PEOPLES R CHINA'::text))"
"                    Buffers: shared hit=195242"
"                    ->  BitmapAnd  (cost=138757.99..138757.99 rows=11337 width=0) (actual time=1484.363..1484.363 rows=0 loops=1)"
"                          Buffers: shared hit=31173"
"                          ->  Bitmap Index Scan on rresearch_ny_idx  (cost=0.00..4930.62 rows=215233 width=0) (actual time=60.997..60.997 rows=241354 loops=1)"
"                                Index Cond: (upper((rresearch.ny)::text) = 'GUANGZHOU'::text)"
"                                Buffers: shared hit=1124"
"                          ->  Bitmap Index Scan on rresearch_nu_idx  (cost=0.00..133821.46 rows=6229156 width=0) (actual time=1350.819..1350.819 rows=6434248 loops=1)"
"                                Index Cond: (upper((rresearch.nu)::text) = 'PEOPLES R CHINA'::text)"
"                                Buffers: shared hit=30049"
"              ->  Index Scan using isi_alt_countrynames_rsc_id_idx on isi.isi_alt_names  (cost=0.00..19.65 rows=1 width=15) (actual time=0.003..0.004 rows=1 loops=241337)"
"                    Output: isi_alt_names.rsc_id, isi_alt_names.code, isi_alt_names.id, isi_alt_names.institution"
"                    Index Cond: (isi_alt_names.rsc_id = rresearch.id)"
"                    Filter: (isi_alt_names.code IS NOT NULL)"
"                    Buffers: shared hit=1212904"
"Total runtime: 2945.400 ms"

I then ran the query and the result was produced in about the same time as (2945 ms).

What can cause such a huge discrepancy?  I have checked and there was no other process blocking the query.

Regards
Johann

--
Because experiencing your loyal love is better than life itself,
my lips will praise you.  (Psalm 63:3)