clickhousedb_fdw icon indicating copy to clipboard operation
clickhousedb_fdw copied to clipboard

Published 20 hours ago • verified publisher icon Percona-Lab

postgres crashes on every third query with fdw

Open tomvantilburg opened this issue 6 years ago • 8 comments

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?

tomvantilburg avatar Apr 10 '19 15:04 tomvantilburg

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 [email protected] 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

ibrarahmad avatar Apr 10 '19 15:04 ibrarahmad

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.

tomvantilburg avatar Apr 10 '19 16:04 tomvantilburg

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

On Wed, Apr 10, 2019 at 9:02 PM Tom van Tilburg [email protected] 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

ibrarahmad avatar Apr 10 '19 16:04 ibrarahmad

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 ()

tomvantilburg avatar Apr 10 '19 19:04 tomvantilburg

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 [email protected] 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=, 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

ibrarahmad avatar Apr 11 '19 08:04 ibrarahmad

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.

tomvantilburg avatar Apr 11 '19 18:04 tomvantilburg

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 [email protected] 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

ibrarahmad avatar Apr 11 '19 18:04 ibrarahmad

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

tomvantilburg avatar Apr 14 '19 08:04 tomvantilburg