Re: BUG #15455: Endless lseek

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.

> Dear all,
> 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)
>
> gettimeofday({1540302906, 733829}, NULL) = 0
> epoll_wait(40<anon_inode:[eventpoll]>, {}, 1, 1802) = 0
> close(40<anon_inode:[eventpoll]>) = 0
> gettimeofday({1540302908, 538020}, NULL) = 0
> gettimeofday({1540302908, 538120}, NULL) = 0
> write(2</var/log/postgresql/postgresql-9.6-main.log>, "[2018-10-23 13:55:08
> UTC]:127.0."..., 321) = 321
> gettimeofday({1540302908, 538310}, NULL) = 0
> sendto(10,
> "\2\0\0\0x\1\0\0\356\330\254\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
> 376, 0, NULL, 0) = 376
> gettimeofday({1540302908, 538477}, NULL) = 0
> sendto(11,
> "\27\3\3\0Y\326\231\n\324\212\351W\26\311\363\t\316&\214\223\237\301o\30\361\0347\242\365\264-'"...,
> 94, 0, NULL, 0) = 94
> recvfrom(11, 0x7fe363a94913, 5, 0, 0, 0) = -1 EAGAIN (Resource temporarily
> unavailable)
> epoll_wait(3<anon_inode:[eventpoll]>, {{EPOLLIN, {u32=1671705328,
> u64=140614606009072}}}, 1, -1) = 1
> recvfrom(11, "\27\3\3\0\210", 5, 0, NULL, NULL) = 5
> recvfrom(11,
> "\326\264\345\323\r\334\213\265\362_`\vC\347H\10P\375\33\255\37\317\317m\211\211T\17\221\361gg"...,
> 136, 0, NULL, NULL) = 136
> gettimeofday({1540302908, 539005}, NULL) = 0
> gettimeofday({1540302908, 539076}, NULL) = 0
> gettimeofday({1540302908, 539146}, NULL) = 0
> setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={21600, 0}}, NULL) =
> 0
> lseek(23</data2/postgresql/9.6/main/base/11327726/11357540>, 0, SEEK_END) =
> 193478656
> lseek(35</data2/postgresql/9.6/main/base/11327726/11357546>, 0, SEEK_END) =
> 197910528
> lseek(23</data2/postgresql/9.6/main/base/11327726/11357540>, 0, SEEK_END) =
> 193478656
> lseek(35</data2/postgresql/9.6/main/base/11327726/11357546>, 0, SEEK_END) =
> 197910528
> lseek(35</data2/postgresql/9.6/main/base/11327726/11357546>, 0, SEEK_END) =
> 197910528
> lseek(35</data2/postgresql/9.6/main/base/11327726/11357546>, 0, SEEK_END) =
> 197910528
> ......
> ......
> ......
>
> where 197910528 is the table A!.
>
> 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:
>
> gettimeofday({1540302790, 333762}, NULL) = 0
> epoll_wait(39<anon_inode:[eventpoll]>, {}, 1, 23861) = 0
> close(39<anon_inode:[eventpoll]>) = 0
> gettimeofday({1540302814, 219009}, NULL) = 0
> gettimeofday({1540302814, 219126}, NULL) = 0
> write(2</var/log/postgresql/postgresql-9.6-main.log>, "[2018-10-23 13:53:34
> UTC]:127.0."..., 323) = 323
> gettimeofday({1540302814, 219339}, NULL) = 0
> sendto(10,
> "\2\0\0\0\250\3\0\0\356\330\254\0\10\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
> 936, 0, NULL, 0) = 936
> sendto(10,
> "\2\0\0\0\230\0\0\0\356\330\254\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
> 152, 0, NULL, 0) = 152
> gettimeofday({1540302814, 219572}, NULL) = 0
> sendto(11,
> "\27\3\3\0Y\326\231\n\324\212\351W\3T\26F\366\3344\"[\375\0262w\2120\33\256QY\375"...,
> 94, 0, NULL, 0) = 94
> recvfrom(11, 0x7fe363a94913, 5, 0, 0, 0) = -1 EAGAIN (Resource temporarily
> unavailable)
> epoll_wait(3<anon_inode:[eventpoll]>, {{EPOLLIN, {u32=1671705328,
> u64=140614606009072}}}, 1, -1) = 1
> recvfrom(11, "\27\3\3\0\210", 5, 0, NULL, NULL) = 5
> recvfrom(11,
> "\326\264\345\323\r\334\213\243\207\216\321\30\225\33\"&\20\313\330\252\32g\r\217j\22i\244\373\321\0210"...,
> 136, 0, NULL, NULL) = 136
> gettimeofday({1540302814, 221199}, NULL) = 0
> gettimeofday({1540302814, 221267}, NULL) = 0
> close(23</data2/postgresql/9.6/main/base/11327726/11357519>) = 0
> gettimeofday({1540302814, 221434}, NULL) = 0
> setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={21600, 0}}, NULL) =
> 0
> open("base/11327726/11357519", O_RDWR) = 23
> lseek(23</data2/postgresql/9.6/main/base/11327726/11357519>, 0, SEEK_END) =
> 193478656
> lseek(34</data2/postgresql/9.6/main/base/11327726/11357525>, 0, SEEK_END) =
> 197910528
> lseek(23</data2/postgresql/9.6/main/base/11327726/11357519>, 0, SEEK_END) =
> 193478656
> lseek(34</data2/postgresql/9.6/main/base/11327726/11357525>, 0, SEEK_END) =
> 197910528
> gettimeofday({1540302814, 313434}, NULL) = 0
> write(2</var/log/postgresql/postgresql-9.6-main.log>, "[2018-10-23 13:53:34
> UTC]:127.0."..., 406) = 406
> gettimeofday({1540302814, 313683}, NULL) = 0
> gettimeofday({1540302814, 313757}, NULL) = 0
> sendto(11,
> "\27\3\3\0N\326\231\n\324\212\351W\4\253\271:\215\321\253\307S\224\344tS>\16\225\222UYc"...,
> 83, 0, NULL, 0) = 83
> recvfrom(11, 0x7fe363a94913, 5, 0, 0, 0) = -1 EAGAIN (Resource temporarily
> unavailable)
> epoll_wait(3<anon_inode:[eventpoll]>, <detached ...>
>
>
> What's the cause of this strange behaviour? What we can do?
>

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com