BUG #8163: simultaneous nearly identical update queries execute extremely slowly - Mailing list pgsql-bugs

The following bug has been logged on the website:

Bug reference:      8163
Logged by:          Todd Cook
Email address:      tcook@blackducksoftware.com
PostgreSQL version: 8.4.16
Operating system:   Fedora 14
Description:        =


When nearly identical update queries arrive simultaneously, the first one to
execute runs normally, but subsequent executions run _extremely_ slowly. =

We've seen this behaviour in production, and the contrived test case below
reproduces the issue.

test=3D> select version() ;
                                                      version               =

                                       =

---------------------------------------------------------------------------=
-----------------------------------------
 PostgreSQL 8.4.16 on x86_64-unknown-linux-gnu, compiled by GCC gcc (GCC)
4.4.4 20100726 (Red Hat 4.4.4-13), 64-bit


To set up:

create table prof as select i as id, i::text col1, (i*2)::text col2 ,
(i*3)::text col3, i*2 col4, md5((i % 5999)::text) as hash, (i % 6000)::text
as hint, (i*4)::text col6, i*5 col7, i*6 col8 from
generate_series(1,36000000) i ;
create table tree as select 'fixed16charstrng'::text as changeme, md5((i %
200000)::text) as hash from generate_series(1,400000) i ;
create index tree_hash_idx on tree(hash) ;

The problematic query run in isolation:

explain analyze update tree set changeme =3D 'changed' where hash in (select
hash from prof where hint =3D '2500') ;
                                                          QUERY PLAN        =

                                                 =

---------------------------------------------------------------------------=
---------------------------------------------------
 Nested Loop  (cost=3D1000098.75..1000104.44 rows=3D11583 width=3D39) (actu=
al
time=3D6765.316..6871.167 rows=3D11998 loops=3D1)
   ->  HashAggregate  (cost=3D1000098.75..1000098.76 rows=3D1 width=3D33) (=
actual
time=3D6765.264..6768.259 rows=3D5999 loops=3D1)
         ->  Seq Scan on prof  (cost=3D0.00..1000084.15 rows=3D5840 width=
=3D33)
(actual time=3D1.351..6755.691 rows=3D6000 loops=3D1)
               Filter: (hint =3D '2500'::text)
   ->  Index Scan using tree_hash_idx on tree  (cost=3D0.00..5.65 rows=3D2
width=3D39) (actual time=3D0.014..0.016 rows=3D2 loops=3D5999)
         Index Cond: (tree.hash =3D prof.hash)
 Total runtime: 7132.700 ms
(7 rows)

To exercise the problem (assuming a database named "test"):
psql -c "update tree set changeme =3D 'changed' where hash in (select hash
from prof where hint =3D '2500')" test &
psql -c "update tree set changeme =3D 'changed' where hash in (select hash
from prof where hint =3D '2501')" test &
psql -c "update tree set changeme =3D 'changed' where hash in (select hash
from prof where hint =3D '2502')" test &
psql -c "update tree set changeme =3D 'changed' where hash in (select hash
from prof where hint =3D '2503')" test &
psql -c "update tree set changeme =3D 'changed' where hash in (select hash
from prof where hint =3D '2504')" test &
psql -c "update tree set changeme =3D 'changed' where hash in (select hash
from prof where hint =3D '2505')" test &
psql -c "update tree set changeme =3D 'changed' where hash in (select hash
from prof where hint =3D '2506')" test &

One of the update begins executing immediately, while the others block
waiting on the first (which is expected). The first update finished in under
10 seconds, and another one started executing; however, this second one has
now been executing for 2 hours.

strace output from that backend is almost exclusively reads, with only a few
calls to lseek.  Attaching with gdb and interrupting a few times mostly gave
this backtrace:

#0  0x0000003b812d3490 in __read_nocancel () from /lib64/libc.so.6
#1  0x00000000005cd0cd in FileRead ()
#2  0x00000000005dc55d in mdread ()
#3  0x00000000005ca315 in ReadBuffer_common ()
#4  0x00000000005cac7f in ReadBufferExtended ()
#5  0x0000000000460c8b in heapgetpage ()
#6  0x000000000046110a in heapgettup_pagemode ()
#7  0x0000000000461b56 in heap_getnext ()
#8  0x000000000054ef18 in SeqNext ()
#9  0x00000000005429ba in ExecScan ()
#10 0x000000000053b8a8 in ExecProcNode ()
#11 0x0000000000547ac8 in ExecAgg ()
#12 0x000000000053b7b8 in ExecProcNode ()
#13 0x000000000054e031 in ExecNestLoop ()
#14 0x000000000053b818 in ExecProcNode ()
#15 0x000000000053827e in EvalPlanQualNext ()
#16 0x000000000053867b in EvalPlanQual ()
#17 0x0000000000539afd in standard_ExecutorRun ()
#18 0x00007f796347881b in pgss_ExecutorRun (queryDesc=3D0x1af53b0,
direction=3DForwardScanDirection, count=3D0) at pg_stat_statements.c:516
#19 0x00000000005e3ad1 in ProcessQuery ()
#20 0x00000000005e3cd4 in PortalRunMulti ()
#21 0x00000000005e4452 in PortalRun ()
#22 0x00000000005dfac9 in exec_simple_query ()
#23 0x00000000005e10f3 in PostgresMain ()
#24 0x00000000005b4e73 in ServerLoop ()
#25 0x00000000005b729e in PostmasterMain ()
#26 0x0000000000562578 in main ()