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

On 05/15/13 13:27, tcook@blackducksoftware.com wrote:
> 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.

I've repeated the test below on a 9.1.9 installation, and it works fine there.
Each update finished in about 7 seconds.

-- todd

>
> test=> 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 = 'changed' where hash in (select
> hash from prof where hint = '2500') ;
>                                                            QUERY PLAN
>
>
------------------------------------------------------------------------------------------------------------------------------
>   Nested Loop  (cost=1000098.75..1000104.44 rows=11583 width=39) (actual
> time=6765.316..6871.167 rows=11998 loops=1)
>     ->  HashAggregate  (cost=1000098.75..1000098.76 rows=1 width=33) (actual
> time=6765.264..6768.259 rows=5999 loops=1)
>           ->  Seq Scan on prof  (cost=0.00..1000084.15 rows=5840 width=33)
> (actual time=1.351..6755.691 rows=6000 loops=1)
>                 Filter: (hint = '2500'::text)
>     ->  Index Scan using tree_hash_idx on tree  (cost=0.00..5.65 rows=2
> width=39) (actual time=0.014..0.016 rows=2 loops=5999)
>           Index Cond: (tree.hash = prof.hash)
>   Total runtime: 7132.700 ms
> (7 rows)
>
> To exercise the problem (assuming a database named "test"):
> psql -c "update tree set changeme = 'changed' where hash in (select hash
> from prof where hint = '2500')" test &
> psql -c "update tree set changeme = 'changed' where hash in (select hash
> from prof where hint = '2501')" test &
> psql -c "update tree set changeme = 'changed' where hash in (select hash
> from prof where hint = '2502')" test &
> psql -c "update tree set changeme = 'changed' where hash in (select hash
> from prof where hint = '2503')" test &
> psql -c "update tree set changeme = 'changed' where hash in (select hash
> from prof where hint = '2504')" test &
> psql -c "update tree set changeme = 'changed' where hash in (select hash
> from prof where hint = '2505')" test &
> psql -c "update tree set changeme = 'changed' where hash in (select hash
> from prof where hint = '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=0x1af53b0,
> direction=ForwardScanDirection, count=0) 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 ()
>
>
>