Re: BUG #15455: Endless lseek

AET_AW_001_000014_000007 is table A
JOIN WITHOUT INDEX su AET_AW_001_000014_000007

3000 rows : Execution time 1,5s

--------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Anti Join (cost=0.00..204.02 rows=1 width=4) (actual time=1535.056..1535.056 rows=0 loops=1)
Join Filter: ((d.oid)::text = (s.oid)::text)
Rows Removed by Join Filter: 4498500
-> Seq Scan on aw_001_000014_000007 s (cost=0.00..100.00 rows=1 width=90) (actual time=0.003..0.774 rows=3000 loops=1)
-> Materialize (cost=0.00..104.00 rows=1 width=90) (actual time=0.000..0.208 rows=1500 loops=3000)
-> Seq Scan on aet_aw_001_000014_000007 d (cost=0.00..104.00 rows=1 width=90) (actual time=0.003..0.786 rows=3000 loops=1)
Planning time: 0.166 ms
Execution time: 1535.096 ms

30.000 rows : Execution time214s

----------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Anti Join (cost=0.00..2064.02 rows=1 width=4) (actual time=214598.223..214598.223 rows=0 loops=1)
Join Filter: ((d.oid)::text = (s.oid)::text)
Rows Removed by Join Filter: 449985000
-> Seq Scan on aw_001_000014_000007 s (cost=0.00..1020.00 rows=1 width=90) (actual time=0.004..12.034 rows=30000 loops=1)
-> Materialize (cost=0.00..1044.01 rows=1 width=90) (actual time=0.000..3.114 rows=15000 loops=30000)
-> Seq Scan on aet_aw_001_000014_000007 d (cost=0.00..1044.00 rows=1 width=90) (actual time=0.004..9.235 rows=30000 loops=1)
Planning time: 0.246 ms
Execution time: 214598.430 ms

600.000 rows Execution time: Undefined (exponential)
----------------
not recorded

JOIN WITH INDEX on AET_AW_001_000014_000007

600.000 rows : Execution time 1,8s

-------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Anti Join (cost=0.42..23620.53 rows=1 width=4) (actual time=1850.355..1850.355 rows=0 loops=1)
-> Seq Scan on aw_001_000014_000007 s (cost=0.00..23618.00 rows=1 width=90) (actual time=0.005..164.216 rows=695521 loops=1)
-> Index Only Scan using aet_index on aet_aw_001_000014_000007 d (cost=0.42..3659.39 rows=3478 width=90) (actual time=0.002..0.002 rows=1 loops=695521)
Index Cond: (oid = (s.oid)::text)
Heap Fetches: 695521
Planning time: 0.195 ms
Execution time: 1850.392 ms

JOIN WITHOUT INDEX but WITH SLEEP(30) SINCE THE CREATION of AET_AW_001_000014_000007

600.000 rows : Execution time 0,8s

-------------------------------------------------------------------------------------------------------------------------------------------------
Hash Anti Join (cost=39808.22..72989.64 rows=1 width=4) (actual time=863.544..863.544 rows=0 loops=1)
Hash Cond: ((s.oid)::text = (d.oid)::text)
-> Seq Scan on aw_001_000014_000007 s (cost=0.00..30573.21 rows=695521 width=37) (actual time=0.004..151.082 rows=695521 loops=1)
-> Hash (cost=31114.21..31114.21 rows=695521 width=37) (actual time=419.699..419.700 rows=695521 loops=1)
Buckets: 1048576 Batches: 1 Memory Usage: 55059kB
-> Seq Scan on aet_aw_001_000014_000007 d (cost=0.00..31114.21 rows=695521 width=37) (actual time=0.006..180.611 rows=695521 loops=1)
Planning time: 0.576 ms
Execution time: 863.772 ms

________________________________
Da: Andres Freund <andres(at)anarazel(dot)de>
Inviato: mercoledì 24 ottobre 2018 10:31:36
A: Dilip Kumar
Cc: Ferranti, Andrea; PostgreSQL mailing lists
Oggetto: Re: BUG #15455: Endless lseek

On 2018-10-24 11:14:29 +0530, Dilip Kumar wrote:
> On Tue, Oct 23, 2018 at 9:35 PM PG Bug reporting form
> <noreply(at)postgresql(dot)org> wrote:
> >
> > The following bug has been logged on the website:
> >
> > Bug reference: 15455
> > Logged by: Andrea Ferranti
> > Email address: andrea(dot)ferranti(at)wolterskluwer(dot)com
> > PostgreSQL version: 9.6.10
> > Operating system: Ubuntu 16
> > Description:
> >
> I think you have already raised the same bug "BUG #15454: Endless
> lseek", Seems this is duplicate.

I think the other bug is incomplete / truncated...

> > We have experienced a strange behaviour on PostgreSQL 9.6.10.
> > (for privacy reason I cannot copy the exact query and data on which query
> > are performed).
> >
> > We have a series of query that move data from a table to another by using
> > the following logic.
> >
> > create table A;
> > insert data into A from B;
> > <insert remaining data into A from B>;
> > drop B;
> > rename A to B;
> >
> > the <insert remaining data into A from B> step has the following logic:
> >
> > INSERT INTO A SELECT X
> > FROM B DEST_TABLE JOIN (
> > SELECT ---
> > FROM B SOURCE_TABLE)
> > SOURCE_TABLE
> > ON SOURCE_TABLE.S0 = DEST_TABLE.
> > AND SOURCE_TABLE.S1 = DEST_TABLE.
> >
> > the last query doesn't terminate.
> > In particular, we have found that the inner select (...FROM A JOIN B...)
> > generate a series of lseek as following.
> >
> > (we have execute a strace of posgtreSQL process)

> > by adding a "sleep" of 30 seconds before the <insert remaining data into A
> > from B>; everything works and following is the strace of the correct
> > process:

I assume this might "just" be a chance for autovacuum to analyze the
table. If you do an EXPLAIN of the query both with the 30s wait and
without, does the plan change? Does adding an explicit ANALYZE of both
a and b before inserting fix the issue?

Greetings,

Andres Freund