search

Percona-Lab / clickhousedb_fdw

PostgreSQL's Foreign Data Wrapper For ClickHouse
Other
201 stars 24 forks source link

postgres crashes on every third query with fdw #6

Open tomvantilburg opened 5 years ago

tomvantilburg commented 5 years ago

I'm currently checking out the fdw and struggling with seemingly random but frequent postgres crashes when querying a clickhouse table via the FDW. Can't figure out yet what library is causing this, and postgres log is not helpful: server process (PID 2809) was terminated by signal 6: Aborted

Any idea where I can start looking for error/debug messages?

ibrarahmad commented 5 years ago

Sol - 1: Can you please share your clickhouse and Postgres table? I will check it for you.

Sol - 2: 1 - ulimit -c unlimited 2 - run your query 3 - send me core file.

Sol - 3: If this is not the query issue then it's definitely your setup issue.

1 - psql > SELECT pg_backend_pid(); This will return you the pid

5 - psql> run your query...

in another terminal

2 - sudo gdb 3 - gdb > attach [pid] 4 - gdb > c

6 - gdb > bt

On Wed, Apr 10, 2019 at 8:29 PM Tom van Tilburg notifications@github.com wrote:

I'm currently checking out the fdw and struggling with seemingly random but frequent postgres crashes when querying a clickhouse table via the FDW. Can't figure out yet what library is causing this, and postgres log is not helpful: server process (PID 2809) was terminated by signal 6: Aborted

Any idea where I can start looking for error/debug messages?

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/Percona-Lab/clickhousedb_fdw/issues/6, or mute the thread https://github.com/notifications/unsubscribe-auth/ADbS8skwpLmvxdPeaWGpBPhFdHPHtOvtks5vfgNTgaJpZM4cnhbl .

-- Ibrar Ahmed

tomvantilburg commented 5 years ago

Will do. In the meantime: the crash is not random but always on the third transaction in the same session. When I open a new session for every transaction it runs fine.

ibrarahmad commented 5 years ago

Ok, you mean same query crash on every third run?

On Wed, Apr 10, 2019 at 9:02 PM Tom van Tilburg notifications@github.com wrote:

Will do. In the meantime: the crash is not random but always on the third transaction in the same session. When I open a new session for every transaction it runs fine.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

-- Ibrar Ahmed

tomvantilburg commented 5 years ago

Correct, same query on every third run, regardless of kind of query it seems.

Here is the gdb output for the following query: select * FROM data where segmentid = 10 limit 10;

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007f96fa04e801 in __GI_abort () at abort.c:79
#2  0x00007f92d8bfaaae in _Unwind_SetGR ()
   from /usr/local/lib/odbc/libclickhouseodbc.so
#3  0x00007f92d8b56111 in __gxx_personality_v0 ()
   from /usr/local/lib/odbc/libclickhouseodbc.so
#4  0x00007f96f7f10553 in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#5  0x00007f96f7f10dd5 in _Unwind_Resume () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#6  0x00007f92d862a7fc in Poco::Net::HTTPClientSession::receiveResponse(Poco::Net::HTTPResponse&) () from /usr/lib/libPocoNet.so.50
#7  0x00007f92d8b4d803 in Statement::sendRequest (this=this@entry=0x55eb1a1508b0, 
    mutator=std::unique_ptr<IResultMutator> = {...})
    at /home/tom/src/clickhouse-odbc-1.0.0.20190409/driver/statement.cpp:87
#8  0x00007f92d8b3d7d8 in <lambda(Statement&)>::operator() (
    __closure=<optimized out>, statement=...)
    at /home/tom/src/clickhouse-odbc-1.0.0.20190409/driver/odbc.cpp:97
#9  doWith<Statement, SQLExecute(HSTMT)::<lambda(Statement&)> > (f=..., 
    handle_opaque=0x55eb1a1508b0)
    at /home/tom/src/clickhouse-odbc-1.0.0.20190409/driver/utils.h:21
#10 SQLExecute (statement_handle=0x55eb1a1508b0)
 at /home/tom/src/clickhouse-odbc-1.0.0.20190409/driver/odbc.cpp:99
#11 0x00007f92d9060701 in SQLExecute (statement_handle=0x55eb1a2a5720)
    at SQLExecute.c:290
#12 0x00007f92d92bd474 in odbc_execute (conn=0x55eb1a23cc60)
    at lib/clickhouse-client.cpp:165
#13 0x00007f92d94c3e41 in clickhouseIterateForeignScan (node=0x55eb1a1d8240)
    at clickhousedb_fdw.c:1115
#14 0x000055eb1846dfd3 in ?? ()
#15 0x000055eb1844a20d in ExecScan ()
#16 0x000055eb18461074 in ?? ()
#17 0x000055eb1844190d in standard_ExecutorRun ()
#18 0x000055eb18590f06 in ?? ()
#19 0x000055eb18592558 in PortalRun ()
#20 0x000055eb1858e05f in ?? ()
#21 0x000055eb1859005e in PostgresMain ()
#22 0x000055eb1851aa7d in ?? ()
#23 0x000055eb1851babf in PostmasterMain ()
#24 0x000055eb182a84c2 in main ()
ibrarahmad commented 5 years ago

If you have a simple query, please share with me. By looking at the stack-trace everything ok till the clickhousedb_fdw and it crash in ODBC driver.

On Thu, Apr 11, 2019 at 12:12 AM Tom van Tilburg notifications@github.com wrote:

Correct, same query on every third run.

Here is the gdb output:

0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51

1 0x00007f96fa04e801 in __GI_abort () at abort.c:79

2 0x00007f92d8bfaaae in _Unwind_SetGR ()

from /usr/local/lib/odbc/libclickhouseodbc.so

3 0x00007f92d8b56111 in __gxx_personality_v0 ()

from /usr/local/lib/odbc/libclickhouseodbc.so

4 0x00007f96f7f10553 in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1

5 0x00007f96f7f10dd5 in _Unwind_Resume () from /lib/x86_64-linux-gnu/libgcc_s.so.1

6 0x00007f92d862a7fc in Poco::Net::HTTPClientSession::receiveResponse(Poco::Net::HTTPResponse&) () from /usr/lib/libPocoNet.so.50

7 0x00007f92d8b4d803 in Statement::sendRequest (this=this@entry=0x55eb1a1508b0,

mutator=std::unique_ptr<IResultMutator> = {...})
at /home/tom/src/clickhouse-odbc-1.0.0.20190409/driver/statement.cpp:87

8 0x00007f92d8b3d7d8 in <lambda(Statement&)>::operator() (

__closure=<optimized out>, statement=...)
at /home/tom/src/clickhouse-odbc-1.0.0.20190409/driver/odbc.cpp:97

9 doWith<Statement, SQLExecute(HSTMT)::<lambda(Statement&)> > (f=...,

handle_opaque=0x55eb1a1508b0)
at /home/tom/src/clickhouse-odbc-1.0.0.20190409/driver/utils.h:21

10 SQLExecute (statement_handle=0x55eb1a1508b0)

at /home/tom/src/clickhouse-odbc-1.0.0.20190409/driver/odbc.cpp:99

11 0x00007f92d9060701 in SQLExecute (statement_handle=0x55eb1a2a5720)

at SQLExecute.c:290

12 0x00007f92d92bd474 in odbc_execute (conn=0x55eb1a23cc60)

at lib/clickhouse-client.cpp:165

13 0x00007f92d94c3e41 in clickhouseIterateForeignScan (node=0x55eb1a1d8240)

at clickhousedb_fdw.c:1115

14 0x000055eb1846dfd3 in ?? ()

15 0x000055eb1844a20d in ExecScan ()

16 0x000055eb18461074 in ?? ()

17 0x000055eb1844190d in standard_ExecutorRun ()

18 0x000055eb18590f06 in ?? ()

19 0x000055eb18592558 in PortalRun ()

20 0x000055eb1858e05f in ?? ()

21 0x000055eb1859005e in PostgresMain ()

22 0x000055eb1851aa7d in ?? ()

23 0x000055eb1851babf in PostmasterMain ()

24 0x000055eb182a84c2 in main ()

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/Percona-Lab/clickhousedb_fdw/issues/6#issuecomment-481824578, or mute the thread https://github.com/notifications/unsubscribe-auth/ADbS8vpVZwrz45q8ChhvrSkSiaNSj0drks5vfjeYgaJpZM4cnhbl .

-- Ibrar Ahmed

tomvantilburg commented 5 years ago

I've been trying to reproduce with a smaller dataset but that seems to work fine. Unfortunately I'm not able to share the larger set. If there is anything else I can do to test/debug, please let me know.

ibrarahmad commented 5 years ago

Run the server with debug level 2 and send me the server log.

On Thu, Apr 11, 2019 at 11:18 PM Tom van Tilburg notifications@github.com wrote:

I've been trying to reproduce with a smaller dataset but that seems to work fine. Unfortunately I'm not able to share the larger set. If there is anything else I can do to test/debug, please let me know.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/Percona-Lab/clickhousedb_fdw/issues/6#issuecomment-482239718, or mute the thread https://github.com/notifications/unsubscribe-auth/ADbS8hxMKPByShi5GC6XdAZhiLhJD8rAks5vf3ySgaJpZM4cnhbl .

-- Ibrar Ahmed

tomvantilburg commented 5 years ago

I ran 3 times the same query and the third time it crashed as expected. From the log I took the second and the third query and pasted below. imo there is not much to see in the log, I hope you can make somehting of it.

2019-04-14 08:34:03.338 UTC [1507] tom@mydb DEBUG:  > clickhouseGetForeignRelSize:411
2019-04-14 08:34:03.338 UTC [1507] tom@mydb DEBUG:  < clickhouseGetForeignRelSize:506
2019-04-14 08:34:03.338 UTC [1507] tom@mydb DEBUG:  > clickhouseGetForeignPaths:760
2019-04-14 08:34:03.338 UTC [1507] tom@mydb DEBUG:  > get_useful_pathkeys_for_relation:644
2019-04-14 08:34:03.338 UTC [1507] tom@mydb DEBUG:  < clickhouseGetForeignPaths:782
2019-04-14 08:34:03.338 UTC [1507] tom@mydb DEBUG:  > clickhouseGetForeignPlan:810
2019-04-14 08:34:03.338 UTC [1507] tom@mydb DEBUG:  > deparseSelectStmtForRel:1038
2019-04-14 08:34:03.338 UTC [1507] tom@mydb DEBUG:  > deparseSelectSql:1121
2019-04-14 08:34:03.338 UTC [1507] tom@mydb DEBUG:  < deparseSelectSql:1162
2019-04-14 08:34:03.338 UTC [1507] tom@mydb DEBUG:  > deparseSelectStmtForRel:1096
2019-04-14 08:34:03.338 UTC [1507] tom@mydb DEBUG:  > clickhouseBeginForeignScan:1005
2019-04-14 08:34:03.339 UTC [1507] tom@mydb DEBUG:  > GetConnection:104
2019-04-14 08:34:03.340 UTC [1507] tom@mydb DEBUG:  < GetConnection:210
2019-04-14 08:34:03.340 UTC [1507] tom@mydb DEBUG:  < clickhouseBeginForeignScan:1093
2019-04-14 08:34:03.340 UTC [1507] tom@mydb DEBUG:  > clickhouseIterateForeignScan:1107
2019-04-14 08:34:03.379 UTC [1507] tom@mydb DEBUG:  > fetch_more_data:1610
2019-04-14 08:34:03.379 UTC [1507] tom@mydb DEBUG:  > make_tuple_from_result_row:3066
2019-04-14 08:34:03.379 UTC [1507] tom@mydb DEBUG:  < make_tuple_from_result_row:3222
2019-04-14 08:34:03.379 UTC [1507] tom@mydb DEBUG:  < fetch_more_data:1618:SELECT timest, segmentid, speedkph FROM mydb.fcd_data WHERE ((segmentid = 10))
2019-04-14 08:34:03.379 UTC [1507] tom@mydb DEBUG:  < clickhouseIterateForeignScan:1135
2019-04-14 08:34:03.379 UTC [1507] tom@mydb DEBUG:  > clickhouseIterateForeignScan:1107
2019-04-14 08:34:03.379 UTC [1507] tom@mydb DEBUG:  > fetch_more_data:1610
2019-04-14 08:34:03.379 UTC [1507] tom@mydb DEBUG:  > make_tuple_from_result_row:3066
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < make_tuple_from_result_row:3222
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < fetch_more_data:1618:SELECT timest, segmentid, speedkph FROM mydb.fcd_data WHERE ((segmentid = 10))
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < clickhouseIterateForeignScan:1135
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > clickhouseIterateForeignScan:1107
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > fetch_more_data:1610
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > make_tuple_from_result_row:3066
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < make_tuple_from_result_row:3222
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < fetch_more_data:1618:SELECT timest, segmentid, speedkph FROM mydb.fcd_data WHERE ((segmentid = 10))
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < clickhouseIterateForeignScan:1135
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > clickhouseIterateForeignScan:1107
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > fetch_more_data:1610
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > make_tuple_from_result_row:3066
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < make_tuple_from_result_row:3222
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < fetch_more_data:1618:SELECT timest, segmentid, speedkph FROM mydb.fcd_data WHERE ((segmentid = 10))
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < clickhouseIterateForeignScan:1135
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > clickhouseIterateForeignScan:1107
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > fetch_more_data:1610
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > make_tuple_from_result_row:3066
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < make_tuple_from_result_row:3222
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < fetch_more_data:1618:SELECT timest, segmentid, speedkph FROM mydb.fcd_data WHERE ((segmentid = 10))
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < clickhouseIterateForeignScan:1135
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > clickhouseIterateForeignScan:1107
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > fetch_more_data:1610
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > make_tuple_from_result_row:3066
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < make_tuple_from_result_row:3222
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < fetch_more_data:1618:SELECT timest, segmentid, speedkph FROM mydb.fcd_data WHERE ((segmentid = 10))
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < clickhouseIterateForeignScan:1135
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > clickhouseIterateForeignScan:1107
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > fetch_more_data:1610
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > make_tuple_from_result_row:3066
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < make_tuple_from_result_row:3222
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < fetch_more_data:1618:SELECT timest, segmentid, speedkph FROM mydb.fcd_data WHERE ((segmentid = 10))
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < clickhouseIterateForeignScan:1135
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > clickhouseIterateForeignScan:1107
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > fetch_more_data:1610
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > make_tuple_from_result_row:3066
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < make_tuple_from_result_row:3222
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < fetch_more_data:1618:SELECT timest, segmentid, speedkph FROM mydb.fcd_data WHERE ((segmentid = 10))
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < clickhouseIterateForeignScan:1135
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > clickhouseIterateForeignScan:1107
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > fetch_more_data:1610
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > make_tuple_from_result_row:3066
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < make_tuple_from_result_row:3222
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < fetch_more_data:1618:SELECT timest, segmentid, speedkph FROM mydb.fcd_data WHERE ((segmentid = 10))
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < clickhouseIterateForeignScan:1135
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > clickhouseIterateForeignScan:1107
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > fetch_more_data:1610
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > make_tuple_from_result_row:3066
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < make_tuple_from_result_row:3222
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < fetch_more_data:1618:SELECT timest, segmentid, speedkph FROM mydb.fcd_data WHERE ((segmentid = 10))
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < clickhouseIterateForeignScan:1135
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  > clickhouseEndForeignScan:1161
2019-04-14 08:34:03.380 UTC [1507] tom@mydb DEBUG:  < clickhouseEndForeignScan:1173
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  > clickhouseGetForeignRelSize:411
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  < clickhouseGetForeignRelSize:506
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  > clickhouseGetForeignPaths:760
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  > get_useful_pathkeys_for_relation:644
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  < clickhouseGetForeignPaths:782
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  > clickhouseGetForeignPlan:810
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  > deparseSelectStmtForRel:1038
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  > deparseSelectSql:1121
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  < deparseSelectSql:1162
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  > deparseSelectStmtForRel:1096
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  > clickhouseBeginForeignScan:1005
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  > GetConnection:104
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  < GetConnection:210
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  < clickhouseBeginForeignScan:1093
2019-04-14 08:34:04.395 UTC [1507] tom@mydb DEBUG:  > clickhouseIterateForeignScan:1107
2019-04-14 08:34:04.646 UTC [2258] DEBUG:  forked new backend, pid=1541 socket=11
2019-04-14 08:34:04.647 UTC [2258] DEBUG:  server process (PID 1507) was terminated by signal 6: Aborted
2019-04-14 08:34:04.647 UTC [2258] DETAIL:  Failed process was running: select * FROM fcd.data where segmentid = 10 limit 10;
2019-04-14 08:34:04.647 UTC [2258] LOG:  server process (PID 1507) was terminated by signal 6: Aborted
2019-04-14 08:34:04.647 UTC [2258] DETAIL:  Failed process was running: select * FROM fcd.data where segmentid = 10 limit 10;
2019-04-14 08:34:04.647 UTC [2258] LOG:  terminating any other active server processes
2019-04-14 08:34:04.647 UTC [2258] DEBUG:  sending SIGQUIT to process 31175
2019-04-14 08:34:04.647 UTC [2258] DEBUG:  sending SIGQUIT to process 1541
2019-04-14 08:34:04.647 UTC [2258] DEBUG:  sending SIGQUIT to process 31171
2019-04-14 08:34:04.647 UTC [2258] DEBUG:  sending SIGQUIT to process 31170
2019-04-14 08:34:04.647 UTC [2258] DEBUG:  sending SIGQUIT to process 31172
2019-04-14 08:34:04.647 UTC [2258] DEBUG:  sending SIGQUIT to process 31173
2019-04-14 08:34:04.647 UTC [2258] DEBUG:  sending SIGQUIT to process 31174
2019-04-14 08:34:04.647 UTC [31174] DEBUG:  writing stats file "pg_stat/global.stat"
2019-04-14 08:34:04.647 UTC [31173] WARNING:  terminating connection because of crash of another server process
2019-04-14 08:34:04.647 UTC [31173] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2019-04-14 08:34:04.647 UTC [31173] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2019-04-14 08:34:04.647 UTC [31174] DEBUG:  writing stats file "pg_stat/db_1.stat"
2019-04-14 08:34:04.647 UTC [31174] DEBUG:  removing temporary stats file "/var/run/postgresql/11-main.pg_stat_tmp/db_1.stat"
2019-04-14 08:34:04.647 UTC [31174] DEBUG:  writing stats file "pg_stat/db_16385.stat"
2019-04-14 08:34:04.648 UTC [31174] DEBUG:  removing temporary stats file "/var/run/postgresql/11-main.pg_stat_tmp/db_16385.stat"
2019-04-14 08:34:04.648 UTC [31174] DEBUG:  writing stats file "pg_stat/db_0.stat"
2019-04-14 08:34:04.648 UTC [31174] DEBUG:  removing temporary stats file "/var/run/postgresql/11-main.pg_stat_tmp/db_0.stat"
2019-04-14 08:34:04.650 UTC [2258] DEBUG:  server process (PID 1541) exited with exit code 1
2019-04-14 08:34:05.119 UTC [2258] LOG:  all server processes terminated; reinitializing
2019-04-14 08:34:05.119 UTC [2258] DEBUG:  cleaning up dynamic shared memory control segment with ID 908121309
2019-04-14 08:34:06.839 UTC [2258] DEBUG:  mmap(17605591040) with MAP_HUGETLB failed, huge pages disabled: Cannot allocate memory
2019-04-14 08:34:07.198 UTC [2258] DEBUG:  SlruScanDirectory invoking callback on pg_notify/0000
2019-04-14 08:34:07.198 UTC [2258] DEBUG:  removing file "pg_notify/0000"
2019-04-14 08:34:07.198 UTC [2258] DEBUG:  dynamic shared memory system will support 180 segments
2019-04-14 08:34:07.198 UTC [2258] DEBUG:  created dynamic shared memory control segment 1479302018 (4336 bytes)
2019-04-14 08:34:07.199 UTC [1542] LOG:  database system was interrupted; last known up at 2019-04-12 15:30:26 UTC
2019-04-14 08:34:07.260 UTC [1542] DEBUG:  checkpoint record is at 6/CCD70438
2019-04-14 08:34:07.260 UTC [1542] DEBUG:  redo record is at 6/CCD6F970; shutdown false
2019-04-14 08:34:07.260 UTC [1542] DEBUG:  next transaction ID: 0:179474; next OID: 376838
2019-04-14 08:34:07.260 UTC [1542] DEBUG:  next MultiXactId: 1; next MultiXactOffset: 0
2019-04-14 08:34:07.260 UTC [1542] DEBUG:  oldest unfrozen transaction ID: 561, in database 1
2019-04-14 08:34:07.260 UTC [1542] DEBUG:  oldest MultiXactId: 1, in database 1
2019-04-14 08:34:07.260 UTC [1542] DEBUG:  commit timestamp Xid oldest/newest: 0/0
2019-04-14 08:34:07.260 UTC [1542] DEBUG:  transaction ID wrap limit is 2147484208, limited by database with OID 1
2019-04-14 08:34:07.260 UTC [1542] DEBUG:  MultiXactId wrap limit is 2147483648, limited by database with OID 1
2019-04-14 08:34:07.260 UTC [1542] DEBUG:  starting up replication slots
2019-04-14 08:34:07.260 UTC [1542] DEBUG:  starting up replication origin progress state
2019-04-14 08:34:07.260 UTC [1542] LOG:  database system was not properly shut down; automatic recovery in progress
2019-04-14 08:34:07.270 UTC [1542] DEBUG:  resetting unlogged relations: cleanup 1 init 0
2019-04-14 08:34:07.271 UTC [1542] LOG:  redo starts at 6/CCD6F970
2019-04-14 08:34:07.271 UTC [1542] LOG:  invalid record length at 6/CCD704A8: wanted 24, got 0
2019-04-14 08:34:07.271 UTC [1542] LOG:  redo done at 6/CCD70438
2019-04-14 08:34:07.271 UTC [1542] DEBUG:  resetting unlogged relations: cleanup 0 init 1
2019-04-14 08:34:07.289 UTC [1542] DEBUG:  performing replication slot checkpoint
2019-04-14 08:34:07.385 UTC [1542] DEBUG:  attempting to remove WAL segments older than log file 0000000000000006000000CB
2019-04-14 08:34:07.395 UTC [1542] DEBUG:  MultiXactId wrap limit is 2147483648, limited by database with OID 1
2019-04-14 08:34:07.395 UTC [1542] DEBUG:  MultiXact member stop limit is now 4294914944 based on MultiXact 1
2019-04-14 08:34:07.415 UTC [1543] DEBUG:  checkpointer updated shared memory configuration values
2019-04-14 08:34:07.416 UTC [1546] DEBUG:  autovacuum launcher started
2019-04-14 08:34:07.417 UTC [2258] DEBUG:  starting background worker process "logical replication launcher"
2019-04-14 08:34:07.417 UTC [2258] LOG:  database system is ready to accept connections