Thread: BUG #17791: Assert on procarray.c
The following bug has been logged on the website: Bug reference: 17791 Logged by: Robins Tharakan Email address: tharakan@gmail.com PostgreSQL version: 12.14 Operating system: Ubuntu 20.04 Description: This assert() is: - Not easily reproducible + rare (~twice a month) - Always surfaces only on REL_12_STABLE (never on v13+) - The line numbers changed (in Nov 22) but IIUC its the same signature - SQLs seem irrelevant. Can dig up full SQLs, if required. - I provide 4 backtraces, 2 SELECTs, 1 UPDATE, 1 DELETE. Posting here because I noticed the above pattern today, and thought someone could identify what's so specifically wrong with v12. Note that the bug could pre-date Oct 22, since I wasn't aggressively testing older versions before then. 2022-10-10 :TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 419) 2022-11-19 :TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 419) 2022-11-22 :TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 419) 2022-11-30 :TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 430) 2022-12-09 :TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 430) 2022-12-11 :TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 430) 2023-02-13 :TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 430) 2023-02-13 :TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 430) === Backtrace - PID 3911829 - a5f3f2fce1@REL_12_STABLE === Core was generated by `postgres: a5f3f2fce1@REL_12_STABLE@sqith: u87 postgres 127.0.0.1(35270) SELECT'. Program terminated with signal SIGABRT, Aborted. #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00007f64ef7cd859 in __GI_abort () at abort.c:79 #2 0x0000562a05a92bb9 in ExceptionalCondition ( conditionName=0x562a05cb9a78 "!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", errorType=0x562a05cb9a68 "FailedAssertion", fileName=0x562a05cb9a39 "procarray.c", lineNumber=430) at assert.c:54 #3 0x0000562a058c511d in ProcArrayEndTransaction (proc=0x7f64e7084e90, latestXid=128185) at procarray.c:430 #4 0x0000562a0551f641 in AbortTransaction () at xact.c:2709 #5 0x0000562a0551ffa0 in AbortCurrentTransaction () at xact.c:3242 #6 0x0000562a058fb4bb in PostgresMain (argc=1, argv=0x562a06ec38b8, dbname=0x562a06e8b0a8 "postgres", username=0x562a06ec3898 "u87") at postgres.c:4067 #7 0x0000562a05840a7c in BackendRun (port=0x562a06ec12f0) at postmaster.c:4517 #8 0x0000562a0584013c in BackendStartup (port=0x562a06ec12f0) at postmaster.c:4200 #9 0x0000562a0583c016 in ServerLoop () at postmaster.c:1725 #10 0x0000562a0583b7a3 in PostmasterMain (argc=3, argv=0x562a06e89010) at postmaster.c:1398 #11 0x0000562a0574ee81 in main (argc=3, argv=0x562a06e89010) at main.c:228 === Backtrace FULL - PID 3911829 - a5f3f2fce1@REL_12_STABLE === #2 0x0000562a05a92bb9 in ExceptionalCondition ( conditionName=0x562a05cb9a78 "!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", errorType=0x562a05cb9a68 "FailedAssertion", fileName=0x562a05cb9a39 "procarray.c", lineNumber=430) at assert.c:54 No locals. #3 0x0000562a058c511d in ProcArrayEndTransaction (proc=0x7f64e7084e90, latestXid=128185) at procarray.c:430 pgxact = 0x7f64e70af79c #4 0x0000562a0551f641 in AbortTransaction () at xact.c:2709 s = 0x562a05e11cc0 <TopTransactionStateData> latestXid = 128185 is_parallel_worker = false __func__ = "AbortTransaction" #5 0x0000562a0551ffa0 in AbortCurrentTransaction () at xact.c:3242 s = 0x562a05e11cc0 <TopTransactionStateData> #6 0x0000562a058fb4bb in PostgresMain (argc=1, argv=0x562a06ec38b8, dbname=0x562a06e8b0a8 "postgres", username=0x562a06ec3898 "u87") at postgres.c:4067 firstchar = 81 input_message = { data = 0x562a06e8f4b8 "select \n cast(nullif(sample_0.a,\n (select line_number from pg_catalog.pg_hba_file_rules limit 1 offset 3)\n ) as int4) as c0, \n pg_catalog.pg_is_in_recovery() as c1\nfrom \n public.fprt2 as s"..., len = 312, maxlen = 1024, cursor = 312} local_sigjmp_buf = {{__jmpbuf = {94738484097264, -2389127319967802128, 94738476870288, 140722819967216, 0, 0, -2389127319737115408, -8253623502494016272}, __mask_was_saved = 1, __saved_mask = {__val = {0, 0, 0, 0, 51539607567, 140722819966272, 94738483588553, 0, 94738485738760, 94738485732538, 51539612060, 4869, 94738504519872, 94738504768168, 4398046511104, 0}}}} send_ready_for_query = false disable_idle_in_transaction_timeout = false __func__ = "PostgresMain" #################################### === Backtrace - PID 4149811 - a5f3f2fce1@REL_12_STABLE === Core was generated by `postgres: a5f3f2fce1@REL_12_STABLE@sqith: u63 postgres 127.0.0.1(53584) DELETE'. Program terminated with signal SIGABRT, Aborted. #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00007f64ef7cd859 in __GI_abort () at abort.c:79 #2 0x0000562a05a92bb9 in ExceptionalCondition ( conditionName=0x562a05cb9a78 "!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", errorType=0x562a05cb9a68 "FailedAssertion", fileName=0x562a05cb9a39 "procarray.c", lineNumber=430) at assert.c:54 #3 0x0000562a058c511d in ProcArrayEndTransaction (proc=0x7f64e6d5ba00, latestXid=340911) at procarray.c:430 #4 0x0000562a0551f641 in AbortTransaction () at xact.c:2709 #5 0x0000562a0551ffa0 in AbortCurrentTransaction () at xact.c:3242 #6 0x0000562a058fb4bb in PostgresMain (argc=1, argv=0x562a06ede610, dbname=0x562a06ede5e8 "postgres", username=0x562a06e8b0b8 "u63") at postgres.c:4067 #7 0x0000562a05840a7c in BackendRun (port=0x562a06ef8260) at postmaster.c:4517 #8 0x0000562a0584013c in BackendStartup (port=0x562a06ef8260) at postmaster.c:4200 #9 0x0000562a0583c016 in ServerLoop () at postmaster.c:1725 #10 0x0000562a0583b7a3 in PostmasterMain (argc=3, argv=0x562a06e89010) at postmaster.c:1398 #11 0x0000562a0574ee81 in main (argc=3, argv=0x562a06e89010) at main.c:228 === Backtrace FULL - PID 4149811 - a5f3f2fce1@REL_12_STABLE === Core was generated by `postgres: a5f3f2fce1@REL_12_STABLE@sqith: u63 postgres 127.0.0.1(53584) DELETE'. Program terminated with signal SIGABRT, Aborted. #2 0x0000562a05a92bb9 in ExceptionalCondition ( conditionName=0x562a05cb9a78 "!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", errorType=0x562a05cb9a68 "FailedAssertion", fileName=0x562a05cb9a39 "procarray.c", lineNumber=430) at assert.c:54 No locals. #3 0x0000562a058c511d in ProcArrayEndTransaction (proc=0x7f64e6d5ba00, latestXid=340911) at procarray.c:430 pgxact = 0x7f64e70a4060 #4 0x0000562a0551f641 in AbortTransaction () at xact.c:2709 s = 0x562a05e11cc0 <TopTransactionStateData> latestXid = 340911 is_parallel_worker = false __func__ = "AbortTransaction" #5 0x0000562a0551ffa0 in AbortCurrentTransaction () at xact.c:3242 s = 0x562a05e11cc0 <TopTransactionStateData> #6 0x0000562a058fb4bb in PostgresMain (argc=1, argv=0x562a06ede610, dbname=0x562a06ede5e8 "postgres", username=0x562a06e8b0b8 "u63") at postgres.c:4067 firstchar = 81 input_message = { data = 0x562a06e8f4b8 "delete from sqithsch24.dt\nwhere \n(pg_catalog.getdatabaseencoding() is not NULL) \n or (cast(coalesce((select c2 from import_dest2.t3 limit 1 offset 4)\n ,\n cast(coalesce((select c2 from imp"..., len = 695, maxlen = 1024, cursor = 695} local_sigjmp_buf = {{__jmpbuf = {94738484097264, -2389127319967802128, 94738476870288, 140722819967216, 0, 0, -2389127319737115408, -8253623502494016272}, __mask_was_saved = 1, __saved_mask = {__val = {0, 0, 0, 0, 51539607567, 140722819966272, 94738483588553, 0, 94738485738760, 94738485732538, 51539612060, 4869, 94738504519872, 94738504911848, 4398046511104, 0}}}} send_ready_for_query = false disable_idle_in_transaction_timeout = false __func__ = "PostgresMain" ########################################################## === Backtrace - PID 1447940 - e21856fd65@REL_12_STABLE === Core was generated by `postgres: e21856fd65@REL_12_STABLE@sqith: ubuntu postgres 127.0.0.1(46898) SELE'. Program terminated with signal SIGABRT, Aborted. #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00007ffb7c54c859 in __GI_abort () at abort.c:79 #2 0x000055cebc3064e4 in ExceptionalCondition ( conditionName=0x55cebc52bed8 "!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", errorType=0x55cebc52bec8 "FailedAssertion", fileName=0x55cebc52be99 "procarray.c", lineNumber=419) at assert.c:54 #3 0x000055cebc13dbf1 in ProcArrayEndTransaction (proc=0x7ffb76841e80, latestXid=33358) at procarray.c:419 #4 0x000055cebbd9c956 in AbortTransaction () at xact.c:2709 #5 0x000055cebbd9d2b5 in AbortCurrentTransaction () at xact.c:3242 #6 0x000055cebc173d49 in PostgresMain (argc=1, argv=0x55cebd21e6c8, dbname=0x55cebd1aeb88 "postgres", username=0x55cebd21e6a8 "ubuntu") at postgres.c:4055 #7 0x000055cebc0b969f in BackendRun (port=0x55cebd2156b0) at postmaster.c:4510 #8 0x000055cebc0b8d73 in BackendStartup (port=0x55cebd2156b0) at postmaster.c:4193 #9 0x000055cebc0b4db1 in ServerLoop () at postmaster.c:1725 #10 0x000055cebc0b453e in PostmasterMain (argc=3, argv=0x55cebd1acad0) at postmaster.c:1398 #11 0x000055cebbfc8077 in main (argc=3, argv=0x55cebd1acad0) at main.c:228 === Backtrace FULL - PID 1447940 - e21856fd65@REL_12_STABLE === Core was generated by `postgres: e21856fd65@REL_12_STABLE@sqith: ubuntu postgres 127.0.0.1(46898) SELE'. Program terminated with signal SIGABRT, Aborted. #2 0x000055cebc3064e4 in ExceptionalCondition ( conditionName=0x55cebc52bed8 "!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", errorType=0x55cebc52bec8 "FailedAssertion", fileName=0x55cebc52be99 "procarray.c", lineNumber=419) at assert.c:54 No locals. #3 0x000055cebc13dbf1 in ProcArrayEndTransaction (proc=0x7ffb76841e80, latestXid=33358) at procarray.c:419 pgxact = 0x7ffb76a14640 #4 0x000055cebbd9c956 in AbortTransaction () at xact.c:2709 s = 0x55cebc681c80 <TopTransactionStateData> latestXid = 33358 is_parallel_worker = false __func__ = "AbortTransaction" #5 0x000055cebbd9d2b5 in AbortCurrentTransaction () at xact.c:3242 s = 0x55cebc681c80 <TopTransactionStateData> #6 0x000055cebc173d49 in PostgresMain (argc=1, argv=0x55cebd21e6c8, dbname=0x55cebd1aeb88 "postgres", username=0x55cebd21e6a8 "ubuntu") at postgres.c:4055 firstchar = 81 input_message = { data = 0x55cebd1b3848 "select \n pg_catalog.getdatabaseencoding() as c0, \n case when pg_catalog.statement_timestamp() is not NULL then pg_catalog.pg_get_function_arguments(\n cast(cast(null as oid) as oid)) else pg_ca"..., len = 1063, maxlen = 2048, cursor = 1063} local_sigjmp_buf = {{__jmpbuf = {94346409419472, 5411436918575294414, 94346402234016, 140728059150544, 0, 0, 5411436918529157070, 2269720658606647246}, __mask_was_saved = 1, __saved_mask = { __val = {0, 0, 0, 0, 51539607567, 140728059149600, 94346408912601, 0, 94346411057624, 94346411051418, 51539612053, 4869, 94346424273824, 94346424748216, 4398046511104, 0}}}} send_ready_for_query = false disable_idle_in_transaction_timeout = false __func__ = "PostgresMain" ############################################# === Backtrace - PID 271497 - 7b96f525cd@REL_12_STABLE === Core was generated by `postgres: 7b96f525cd@REL_12_STABLE@sqith: ubuntu postgres 127.0.0.1(39634) UPDA'. Program terminated with signal SIGABRT, Aborted. #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x00007fb220668859 in __GI_abort () at abort.c:79 #2 0x00005651346645e1 in ExceptionalCondition ( conditionName=0x565134889f18 "!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", errorType=0x565134889f08 "FailedAssertion", fileName=0x565134889ed9 "procarray.c", lineNumber=430) at assert.c:54 #3 0x000056513449bbad in ProcArrayEndTransaction (proc=0x7fb21a919cb0, latestXid=30504) at procarray.c:430 #4 0x00005651340fa96c in AbortTransaction () at xact.c:2709 #5 0x00005651340fb2cb in AbortCurrentTransaction () at xact.c:3242 #6 0x00005651344d1ddb in PostgresMain (argc=1, argv=0x565135fee5d8, dbname=0x565135f7eb88 "postgres", username=0x565135fee5b8 "ubuntu") at postgres.c:4055 #7 0x0000565134417611 in BackendRun (port=0x565135fd9590) at postmaster.c:4510 #8 0x0000565134416ce5 in BackendStartup (port=0x565135fd9590) at postmaster.c:4193 #9 0x0000565134412d23 in ServerLoop () at postmaster.c:1725 #10 0x00005651344124b0 in PostmasterMain (argc=3, argv=0x565135f7cad0) at postmaster.c:1398 #11 0x0000565134326097 in main (argc=3, argv=0x565135f7cad0) at main.c:228 === Backtrace FULL - PID 271497 - 7b96f525cd@REL_12_STABLE === Core was generated by `postgres: 7b96f525cd@REL_12_STABLE@sqith: ubuntu postgres 127.0.0.1(39634) UPDA'. #2 0x00005651346645e1 in ExceptionalCondition ( conditionName=0x565134889f18 "!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", errorType=0x565134889f08 "FailedAssertion", fileName=0x565134889ed9 "procarray.c", lineNumber=430) at assert.c:54 No locals. #3 0x000056513449bbad in ProcArrayEndTransaction (proc=0x7fb21a919cb0, latestXid=30504) at procarray.c:430 pgxact = 0x7fb21ab2f6d4 #4 0x00005651340fa96c in AbortTransaction () at xact.c:2709 s = 0x5651349dfc80 <TopTransactionStateData> latestXid = 30504 is_parallel_worker = false __func__ = "AbortTransaction" #5 0x00005651340fb2cb in AbortCurrentTransaction () at xact.c:3242 s = 0x5651349dfc80 <TopTransactionStateData> #6 0x00005651344d1ddb in PostgresMain (argc=1, argv=0x565135fee5d8, dbname=0x565135f7eb88 "postgres", username=0x565135fee5b8 "ubuntu") at postgres.c:4055 firstchar = 81 input_message = { data = 0x565135f83848 "update sch18.dt set \n d = cast(nullif(sch18.dt.d,\n sch18.dt.d) as date)\nreturning \n pg_catalog.pg_client_encoding() as c0, \n cast(coalesce(pg_catalog.pg_conf_load_time(),\n case when pg_catalo"..., len = 2357, maxlen = 4096, cursor = 2357} local_sigjmp_buf = {{__jmpbuf = {94906771964864, 3111189373843782306, 94906764779168, 140737476492032, 0, 0, 3111189373915085474, 8678643532193970850}, __mask_was_saved = 1, __saved_mask = { __val = {0, 0, 0, 0, 51539607567, 140737476491088, 94906771458006, 0, 94906773602744, 94906773596538, 51539612053, 4869, 94906797771680, 94906798245832, 4398046511104, 0}}}} send_ready_for_query = false disable_idle_in_transaction_timeout = false __func__ = "PostgresMain" Thanks to SQLSmith for the find. - Robins Tharakan Amazon Web Services
Hi, On 2023-02-14 03:25:04 +0000, PG Bug reporting form wrote: > The following bug has been logged on the website: > > Bug reference: 17791 > Logged by: Robins Tharakan > Email address: tharakan@gmail.com > PostgreSQL version: 12.14 > Operating system: Ubuntu 20.04 > Description: > > This assert() is: > - Not easily reproducible + rare (~twice a month) > - Always surfaces only on REL_12_STABLE (never on v13+) > - The line numbers changed (in Nov 22) but IIUC its the same signature > - SQLs seem irrelevant. Can dig up full SQLs, if required. > - I provide 4 backtraces, 2 SELECTs, 1 UPDATE, 1 DELETE. > > > Posting here because I noticed the above pattern today, and thought > someone could identify what's so specifically wrong with v12. Note that > the bug could pre-date Oct 22, since I wasn't aggressively testing older > versions before then. Are there any log messages around the crashes? I'm wondering whether we're erroring out while aborting, to then abort again, or such. Which will often elicit warning/error messages. Unfortunately, without further information, I doubt this is sufficient for anybody to debug the issue. The stack traces all seem to be during error handling, after catching an error in PostgresMain(). So there's really not much to go on. Greetings, Andres Freund
Hi Andreas, > Are there any log messages around the crashes? I'm wondering whether we're > erroring out while aborting, to then abort again, or such. Which will often > elicit warning/error messages. Thanks for taking a look and possibly you're correct with your assumption. I mean I see a ton of FATALs but let me know if I am mistaken in assuming them to be harmless (since they just convey that the client's gone away)? Nonetheless, I have provided error logs going back till Oct 22 just in case the engine can recover from some of those scenarios. Two things about the test scenario that may be relevant: 1. Since performance was the least of my worries, the postgres server and the client workload are on the same box. Add dblink / FDW to this mix, and it is easy to end up with a ton of loopback connections (think SELECT dblink_conect() FROM pg_catalog.pg_class) - IMO noteworthy, since there are a ton of "Broken pipe"s and one instance of 'too many file descriptors'. 2. All versions are subjected to similar workload and it is possible that v13+ has generally improved in this area, and thus this possibly crashes less? Unsure. Hope it helps. ################################################ 2023-02-13 10:10:08.474 UTC [3918683] LOG: could not send data to client: Broken pipe 2023-02-13 10:10:08.474 UTC [3918683] FATAL: connection to client lost 2023-02-13 10:10:15.001 UTC [3918764] LOG: could not send data to client: Broken pipe 2023-02-13 10:10:15.001 UTC [3918764] FATAL: connection to client lost 2023-02-13 10:10:25.268 UTC [3918886] LOG: could not send data to client: Broken pipe 2023-02-13 10:10:25.269 UTC [3918886] FATAL: connection to client lost 2023-02-13 10:10:26.261 UTC [3918897] LOG: could not send data to client: Broken pipe 2023-02-13 10:10:26.261 UTC [3918897] FATAL: connection to client lost 2023-02-13 10:10:29.503 UTC [3918930] LOG: could not send data to client: Broken pipe 2023-02-13 10:10:29.503 UTC [3918930] FATAL: connection to client lost TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 430) 2023-02-13 10:10:41.629 UTC [3918961] LOG: could not receive data from client: Connection reset by peer 2023-02-13 10:10:43.008 UTC [3777407] LOG: server process (PID 3911829) was terminated by signal 6: Aborted 2023-02-13 10:10:43.008 UTC [3777407] DETAIL: Failed process was running: select cast(nullif(sample_0.a, (select line_number from pg_catalog.pg_hba_file_rules limit 1 offset 3) ) as int4) as c0, pg_catalog.pg_is_in_recovery() as c1 from public.fprt2 as sample_0 tablesample bernoulli (1.2) where public.test_found() > pg_catalog.pg_is_wal_replay_paused() limit 111 2023-02-13 10:10:43.008 UTC [3777407] LOG: terminating any other active server processes 2023-02-13 10:10:43.340 UTC [3777407] LOG: all server processes terminated; reinitializing 2023-02-13 10:10:43.472 UTC [3919088] LOG: database system was interrupted; last known up at 2023-02-13 10:09:22 UTC 2023-02-13 10:10:43.534 UTC [3919088] LOG: database system was not properly shut down; automatic recovery in progress 2023-02-13 10:10:43.540 UTC [3919088] LOG: redo starts at 2C/473107C8 2023-02-13 10:10:44.043 UTC [3919094] FATAL: the database system is in recovery mode ################################################ 2023-02-13 13:48:00.083 UTC [4073] LOG: could not send data to client: Broken pipe 2023-02-13 13:48:00.083 UTC [4073] FATAL: connection to client lost 2023-02-13 13:48:07.916 UTC [4174] LOG: could not send data to client: Broken pipe 2023-02-13 13:48:07.916 UTC [4174] FATAL: connection to client lost 2023-02-13 13:48:16.689 UTC [4193172] LOG: duration: 247511.694 ms statement: REINDEX INDEX sqithsch4.chr_c_idx4; 2023-02-13 13:48:17.247 UTC [4192307] LOG: duration: 250514.066 ms statement: REINDEX INDEX sqithsch7.chr_c_idx4; 2023-02-13 13:48:19.108 UTC [4193744] LOG: duration: 248244.637 ms statement: REINDEX INDEX sqithsch8.chr_c_idx4; 2023-02-13 13:48:19.660 UTC [4191898] LOG: duration: 253850.202 ms statement: REINDEX INDEX sqithsch25.chr_c_idx4; 2023-02-13 13:48:20.607 UTC [4193307] LOG: duration: 250962.064 ms statement: REINDEX INDEX sqithsch1.chr_c_idx4; 2023-02-13 13:48:20.857 UTC [4321] LOG: could not send data to client: Broken pipe 2023-02-13 13:48:20.857 UTC [4321] FATAL: connection to client lost 2023-02-13 13:48:24.460 UTC [4377] LOG: could not send data to client: Broken pipe 2023-02-13 13:48:24.460 UTC [4377] FATAL: connection to client lost 2023-02-13 13:48:25.059 UTC [4194142] LOG: duration: 251910.592 ms statement: REINDEX INDEX sqithsch17.chr_c_idx4_ccnew; 2023-02-13 13:48:33.644 UTC [460] LOG: duration: 248070.798 ms statement: REINDEX INDEX sqithsch29.chr_c_idx4; 2023-02-13 13:48:33.739 UTC [632] LOG: duration: 240490.057 ms statement: REINDEX INDEX sqithsch14.chr_c_idx4; 2023-02-13 13:48:50.101 UTC [4664] LOG: could not send data to client: Broken pipe 2023-02-13 13:48:50.101 UTC [4664] FATAL: connection to client lost 2023-02-13 13:48:55.741 UTC [4725] LOG: could not send data to client: Broken pipe 2023-02-13 13:48:55.741 UTC [4725] FATAL: connection to client lost 2023-02-13 13:48:55.991 UTC [2434] LOG: duration: 192161.947 ms statement: REINDEX INDEX sqithsch12.chr_c_idx4; 2023-02-13 13:48:56.021 UTC [4737] LOG: could not send data to client: Broken pipe 2023-02-13 13:48:56.021 UTC [4737] FATAL: connection to client lost TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 430) 2023-02-13 13:48:56.479 UTC [2349] LOG: duration: 193350.243 ms statement: REINDEX INDEX sqithsch27.chr_c_idx4; 2023-02-13 13:48:56.679 UTC [2438] LOG: duration: 192801.918 ms statement: REINDEX INDEX sqithsch13.chr_c_idx4_ccnew_ccnew; 2023-02-13 13:48:58.428 UTC [4748] LOG: could not receive data from client: Connection reset by peer 2023-02-13 13:48:58.677 UTC [4773] LOG: could not send data to client: Broken pipe 2023-02-13 13:48:58.677 UTC [4773] FATAL: connection to client lost 2023-02-13 13:49:01.002 UTC [1487] LOG: duration: 232718.744 ms statement: REINDEX INDEX sqithsch28.chr_c_idx4; 2023-02-13 13:49:02.393 UTC [4806] FATAL: terminating connection due to administrator command 2023-02-13 13:49:02.393 UTC [4806] STATEMENT: ALTER TABLE ONLY sqithsch18.chr ALTER COLUMN c SET DATA TYPE TEXT USING sqithsch18.chr.c 2023-02-13 13:49:02.470 UTC [3777407] LOG: background worker "parallel worker" (PID 4806) exited with exit code 1 2023-02-13 13:49:02.787 UTC [832] LOG: duration: 255613.229 ms statement: REINDEX INDEX sqithsch13.chr_c_idx4; 2023-02-13 13:49:02.961 UTC [3777407] LOG: server process (PID 4149811) was terminated by signal 6: Aborted 2023-02-13 13:49:02.961 UTC [3777407] DETAIL: Failed process was running: delete from sqithsch24.dt where (pg_catalog.getdatabaseencoding() is not NULL) or (cast(coalesce((select c2 from import_dest2.t3 limit 1 offset 4) , cast(coalesce((select c2 from import_dest1.t3 limit 1 offset 4) , cast(nullif((select c2 from import_dest2.t3 limit 1 offset 37) , cast(null as public.typ1)) as public.typ1)) as public.typ1)) as public.typ1) *>= cast(nullif(cast(null as public.typ1), cast(null as public.typ1)) as public.typ1)) returning sqithsch24.dt.d as c0, public.namedparmcursor_test8() as c1, pg_catalog.pg_current_wal_flush_lsn() as c2, pg_catalog.now() as c3, pg_catalog.session_user() as c4 2023-02-13 13:49:02.961 UTC [3777407] LOG: terminating any other active server processes 2023-02-13 13:49:03.264 UTC [3777407] LOG: all server processes terminated; reinitializing 2023-02-13 13:49:03.399 UTC [4848] LOG: database system was interrupted; last known up at 2023-02-13 13:47:57 UTC 2023-02-13 13:49:04.043 UTC [4849] FATAL: the database system is in recovery mode 2023-02-13 13:49:04.046 UTC [4850] FATAL: the database system is in recovery mode ################################################ 2022-12-09 15:41:07.667 UTC [515871] LOG: could not send data to client: Broken pipe 2022-12-09 15:41:07.686 UTC [515871] FATAL: connection to client lost 2022-12-09 15:41:14.794 UTC [516872] LOG: could not send data to client: Broken pipe 2022-12-09 15:41:14.794 UTC [516872] FATAL: connection to client lost 2022-12-09 15:41:54.815 UTC [517815] LOG: could not send data to client: Broken pipe 2022-12-09 15:41:54.815 UTC [517815] FATAL: connection to client lost 2022-12-09 15:42:09.856 UTC [519130] LOG: could not send data to client: Broken pipe 2022-12-09 15:42:09.856 UTC [519130] FATAL: connection to client lost 2022-12-09 15:42:11.424 UTC [519753] LOG: could not send data to client: Broken pipe 2022-12-09 15:42:11.424 UTC [519753] FATAL: connection to client lost 2022-12-09 15:42:37.653 UTC [521507] LOG: could not send data to client: Broken pipe 2022-12-09 15:42:37.653 UTC [521507] FATAL: connection to client lost 2022-12-09 15:43:34.469 UTC [522743] LOG: could not send data to client: Broken pipe 2022-12-09 15:43:34.469 UTC [522743] FATAL: connection to client lost TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 430) 2022-12-09 15:43:44.272 UTC [522120] LOG: could not receive data from client: Connection reset by peer 2022-12-09 15:43:47.381 UTC [336681] LOG: server process (PID 522114) was terminated by signal 6: Aborted 2022-12-09 15:43:47.381 UTC [336681] DETAIL: Failed process was running: select public.test_found() as c0, public.dblink_current_query() as c1, case when pg_catalog.pg_last_wal_receive_lsn() < pg_catalog.pg_current_wal_lsn() then ref_0.random else ref_0.random end as c2, pg_catalog.phraseto_tsquery( cast(pg_catalog.get_current_ts_config() as regconfig), cast(cast(coalesce(public.dblink_connect_u( cast(pg_catalog.timeofday() as text), cast(public.connection_parameters() as text)), pg_catalog.to_char( cast(cast(null as "interval") as "interval"), cast(pg_catalog.current_query() as text))) as text) as text)) as c3 from public.random_tbl as ref_0 right join sch3.chr_fdw as ref_1 on (cast(null as tsquery) <@ (select tsquery from public.tab_core_types limit 1 offset 5) ) where (pg_catalog.int8send( cast(cast(null as int8) as int8)) ~~ cast(coalesce(public.hmac( cast(pg_catalog.cstring_send( cast(pg_catalog.regroleout( cast(cast(null as regrole) as regrole)) as cstrin 2022-12-09 15:43:47.381 UTC [336681] LOG: terminating any other active server processes 2022-12-09 15:43:47.387 UTC [522266] LOG: could not send data to client: Broken pipe ################################################ 2022-12-11 12:35:53.840 UTC [1739971] LOG: out of file descriptors: Too many open files; release and retry 2022-12-11 12:35:53.840 UTC [1739971] STATEMENT: select public.lquery_in( cast(public.citextout( cast(public.citext( cast(pg_catalog.bpchar( cast(cast(null as bpchar) as bpchar), cast(subq_0.c1 as int4), cast(case when (62 is NULL) and ((true) or (true)) then (select pg_catalog.bool_or(b) from sch23.bool) else (select pg_catalog.bool_or(b) from sch23.bool) end as bool)) as bpchar)) as public.citext)) as cstring)) as c0, public.reraise_test() as c1, sample_4.c1 as c2, pg_catalog.tstzrange( cast(pg_catalog.clock_timestamp() as timestamptz), cast(pg_catalog.pg_stat_get_bgwriter_stat_reset_time() as timestamptz), cast((select t from sch32.txt limit 1 offset 3) as text)) as c3 from sch8.txt as ref_0 inner join (select sample_0.a as c0, sample_0.a as c1, sample_0.a as c2, sample_0.a as c3, sample_0.a as c4, sample_0.a as c5, sample_0.a as c6 from fkpart5.fk4 as sample_0 tablesample system (3.8) where sample_0.a is NULL limit 177) as subq_0 on (cast(null as public.ltree) = (select t from public.ltreetest limit 1 offset 4) ) left join (select ref_1.t as c0, subq_1.c5 as c1, 66 as c2 from sch8.vec_fdw as ref_1, lateral (select sample_1.even as c0, sample_1.two as c1, sample_1.fivethous as c2, sample_1.fivethous as c3, sample_1.two as c4, ref_1.o as c5, ref_1.i as c6 from public.tenk2 as sample_1 tablesample system (5.7) where (select public.logging_agg_strict(t) from sch23.txt) ~* cast(null as text) limit 139) as subq_1 where cast(null as uuid) < cast(null as uuid) limit 139) as subq_2 on (subq_0.c5 is NULL) inner join public.plt1 as sample_2 tablesample system (0.6) right join public.fprt1 as sample_3 tablesample system (6.5) right join (select ref_2.f as c0, ref_2.f as c1, ref_2.f as c2 from sch29.flot as ref_2 where cast(null as jsonb) <= cast(null as jsonb) limit 62) as subq_3 right join import_source.t5 as sample_4 tablesample system (3.3) inner join import_dest2.t1 as ref_3 right join public.table_with_pkey as sample_5 tablesample system (1.3) on (cast(null as bpchar) ~~* (select t from sch27.txt limit 1 offset 4) ) on (true) on ((select timestamptz from public.tab_core_types limit 1 offset 1) <> (select timestamptzcol from public.brintest limit 1 offset 3) ) on (sample_4.c2 > sample_4.c2) on (sample_2.b = ref_3.c1 ) on (subq_2.c2 = sample_4.c1 ) where false limit 84 2022-12-11 12:35:53.845 UTC [1806036] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:53.845 UTC [1806036] FATAL: connection to client lost 2022-12-11 12:35:54.357 UTC [1806042] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:54.357 UTC [1806042] FATAL: connection to client lost 2022-12-11 12:35:54.969 UTC [1806049] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:54.969 UTC [1806049] FATAL: connection to client lost 2022-12-11 12:35:55.018 UTC [1806050] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:55.018 UTC [1806050] FATAL: connection to client lost 2022-12-11 12:35:55.123 UTC [1806051] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:55.123 UTC [1806051] FATAL: connection to client lost 2022-12-11 12:35:55.610 UTC [1806052] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:55.610 UTC [1806052] FATAL: connection to client lost 2022-12-11 12:35:55.730 UTC [1806053] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:55.730 UTC [1806053] FATAL: connection to client lost 2022-12-11 12:35:55.817 UTC [1806058] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:55.817 UTC [1806058] FATAL: connection to client lost 2022-12-11 12:35:57.141 UTC [1806060] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:57.141 UTC [1806060] FATAL: connection to client lost 2022-12-11 12:35:57.753 UTC [1806066] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:57.753 UTC [1806066] FATAL: connection to client lost 2022-12-11 12:35:58.164 UTC [1806072] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:58.164 UTC [1806072] FATAL: connection to client lost 2022-12-11 12:35:58.824 UTC [1806080] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:58.824 UTC [1806080] FATAL: connection to client lost 2022-12-11 12:35:58.965 UTC [1806081] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:58.965 UTC [1806081] FATAL: connection to client lost 2022-12-11 12:35:59.260 UTC [1806082] LOG: could not send data to client: Broken pipe 2022-12-11 12:35:59.260 UTC [1806082] FATAL: connection to client lost 2022-12-11 12:36:00.604 UTC [1806099] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:00.604 UTC [1806099] FATAL: connection to client lost 2022-12-11 12:36:01.960 UTC [1806118] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:01.960 UTC [1806118] FATAL: connection to client lost 2022-12-11 12:36:03.109 UTC [1806125] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:03.109 UTC [1806125] FATAL: connection to client lost 2022-12-11 12:36:03.194 UTC [1806126] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:03.194 UTC [1806126] FATAL: connection to client lost 2022-12-11 12:36:04.707 UTC [1806235] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:04.707 UTC [1806235] FATAL: connection to client lost 2022-12-11 12:36:05.296 UTC [1806241] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:05.296 UTC [1806241] FATAL: connection to client lost 2022-12-11 12:36:05.484 UTC [1806242] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:05.484 UTC [1806242] FATAL: connection to client lost 2022-12-11 12:36:05.620 UTC [1806243] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:05.620 UTC [1806243] FATAL: connection to client lost 2022-12-11 12:36:05.663 UTC [1806244] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:05.663 UTC [1806244] FATAL: connection to client lost 2022-12-11 12:36:05.784 UTC [1806245] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:05.784 UTC [1806245] FATAL: connection to client lost 2022-12-11 12:36:05.863 UTC [1806246] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:05.863 UTC [1806246] FATAL: connection to client lost 2022-12-11 12:36:05.981 UTC [1806252] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:05.981 UTC [1806252] FATAL: connection to client lost 2022-12-11 12:36:06.020 UTC [1806253] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:06.020 UTC [1806253] FATAL: connection to client lost 2022-12-11 12:36:06.161 UTC [1806254] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:06.161 UTC [1806254] FATAL: connection to client lost 2022-12-11 12:36:06.313 UTC [1806255] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:06.313 UTC [1806255] FATAL: connection to client lost 2022-12-11 12:36:07.639 UTC [1806262] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:07.639 UTC [1806262] FATAL: connection to client lost 2022-12-11 12:36:07.880 UTC [1806263] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:07.880 UTC [1806263] FATAL: connection to client lost 2022-12-11 12:36:08.529 UTC [1806269] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:08.529 UTC [1806269] FATAL: connection to client lost 2022-12-11 12:36:10.989 UTC [1806366] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:10.989 UTC [1806366] FATAL: connection to client lost 2022-12-11 12:36:11.936 UTC [1806457] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:11.936 UTC [1806457] FATAL: connection to client lost 2022-12-11 12:36:12.298 UTC [1806458] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:12.298 UTC [1806458] FATAL: connection to client lost 2022-12-11 12:36:12.688 UTC [1806467] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:12.688 UTC [1806467] FATAL: connection to client lost 2022-12-11 12:36:13.005 UTC [1806473] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:13.005 UTC [1806473] FATAL: connection to client lost 2022-12-11 12:36:14.021 UTC [1806480] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:14.021 UTC [1806480] FATAL: connection to client lost 2022-12-11 12:36:14.357 UTC [1806481] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:14.357 UTC [1806481] FATAL: connection to client lost 2022-12-11 12:36:14.602 UTC [1806482] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:14.602 UTC [1806482] FATAL: connection to client lost 2022-12-11 12:36:15.333 UTC [1806489] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:15.333 UTC [1806489] FATAL: connection to client lost 2022-12-11 12:36:15.989 UTC [1806493] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:15.989 UTC [1806493] FATAL: connection to client lost 2022-12-11 12:36:16.245 UTC [1806515] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:16.245 UTC [1806515] FATAL: connection to client lost 2022-12-11 12:36:16.317 UTC [1806532] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:16.317 UTC [1806532] FATAL: connection to client lost 2022-12-11 12:36:16.862 UTC [1806609] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:16.873 UTC [1806609] FATAL: connection to client lost 2022-12-11 12:36:17.170 UTC [1806680] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:17.170 UTC [1806680] FATAL: connection to client lost 2022-12-11 12:36:17.405 UTC [1806738] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:17.405 UTC [1806738] FATAL: connection to client lost 2022-12-11 12:36:18.061 UTC [1806886] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:18.061 UTC [1806886] FATAL: connection to client lost 2022-12-11 12:36:18.320 UTC [1806938] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:18.320 UTC [1806938] FATAL: connection to client lost 2022-12-11 12:36:18.843 UTC [1807035] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:18.843 UTC [1807035] FATAL: connection to client lost 2022-12-11 12:36:19.209 UTC [1807113] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:19.209 UTC [1807113] FATAL: connection to client lost 2022-12-11 12:36:20.263 UTC [1807296] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:20.263 UTC [1807296] FATAL: connection to client lost 2022-12-11 12:36:21.356 UTC [1807495] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:21.356 UTC [1807495] FATAL: connection to client lost 2022-12-11 12:36:21.458 UTC [1807521] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:21.458 UTC [1807521] FATAL: connection to client lost 2022-12-11 12:36:22.489 UTC [1807708] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:22.489 UTC [1807708] FATAL: connection to client lost 2022-12-11 12:36:23.671 UTC [1807957] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:23.671 UTC [1807957] FATAL: connection to client lost 2022-12-11 12:36:23.748 UTC [1807970] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:23.748 UTC [1807970] FATAL: connection to client lost 2022-12-11 12:36:24.541 UTC [1807983] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:24.541 UTC [1807983] FATAL: connection to client lost 2022-12-11 12:36:24.702 UTC [1808144] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:24.702 UTC [1808144] FATAL: connection to client lost 2022-12-11 12:36:24.894 UTC [1808179] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:24.894 UTC [1808179] FATAL: connection to client lost 2022-12-11 12:36:25.774 UTC [1808478] FATAL: sorry, too many clients already 2022-12-11 12:36:25.776 UTC [1808477] FATAL: sorry, too many clients already 2022-12-11 12:36:25.776 UTC [1808479] FATAL: sorry, too many clients already 2022-12-11 12:36:25.778 UTC [1808485] FATAL: sorry, too many clients already 2022-12-11 12:36:25.779 UTC [1808487] FATAL: sorry, too many clients already 2022-12-11 12:36:25.796 UTC [1808498] FATAL: sorry, too many clients already 2022-12-11 12:36:26.413 UTC [1808565] FATAL: sorry, too many clients already 2022-12-11 12:36:26.561 UTC [1808566] FATAL: sorry, too many clients already 2022-12-11 12:36:26.711 UTC [1808567] FATAL: sorry, too many clients already 2022-12-11 12:36:27.001 UTC [1808568] FATAL: sorry, too many clients already 2022-12-11 12:36:27.345 UTC [1808574] FATAL: sorry, too many clients already 2022-12-11 12:36:27.461 UTC [1808575] FATAL: sorry, too many clients already 2022-12-11 12:36:27.569 UTC [1808576] FATAL: sorry, too many clients already 2022-12-11 12:36:27.653 UTC [1808577] FATAL: sorry, too many clients already 2022-12-11 12:36:27.811 UTC [1808578] FATAL: sorry, too many clients already 2022-12-11 12:36:28.213 UTC [1808584] LOG: could not send data to client: Broken pipe 2022-12-11 12:36:28.213 UTC [1808584] FATAL: connection to client lost TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 430) 2022-12-11 12:36:29.403 UTC [1808585] LOG: could not receive data from client: Connection reset by peer 2022-12-11 12:36:30.450 UTC [1632383] LOG: server process (PID 1739971) was terminated by signal 6: Aborted 2022-12-11 12:36:30.450 UTC [1632383] DETAIL: Failed process was running: insert into sch18.pnt ( p ) values ( (select p from sch20.pnt_fdw limit 1 offset 79) ) 2022-12-11 12:36:30.450 UTC [1632383] LOG: terminating any other active server processes ################################################ 2022-11-30 12:27:27.523 UTC [271497] LOG: out of file descriptors: Too many open files; release and retry 2022-11-30 12:27:27.523 UTC [271497] STATEMENT: update sch18.dt set d = cast(nullif(sch18.dt.d, sch18.dt.d) as date) returning pg_catalog.pg_client_encoding() as c0, cast(coalesce(pg_catalog.pg_conf_load_time(), case when pg_catalog.random() is NULL then pg_catalog.pg_stat_get_last_autovacuum_time( cast(pg_catalog.pg_my_temp_schema() as oid)) else pg_catalog.pg_stat_get_last_autovacuum_time( cast(pg_catalog.pg_my_temp_schema() as oid)) end ) as timestamptz) as c1, pg_catalog.justify_interval( cast(case when ((select f1 from public.invalid_check_con limit 1 offset 5) is not NULL) or ((((select p from sch20.pnt_fdw limit 1 offset 71) >^ (select p from sch30.pnt limit 1 offset 4) ) or ((((select bitv from public.caster limit 1 offset 3) <= (select bitv from public.caster limit 1 offset 4) ) or ((false) and (cast(null as name) ~~ (select t from others.measurement_y1975_fdw limit 1 offset 5) ))) or ((select home_base from public.slow_emp4000 limit 1 offset 6) ~= cast(null as box)))) or (((select pg_catalog.min(last_msg_send_time) from pg_catalog.pg_stat_subscription) > sch18.dt.t) or (cast(null as xid) <> (select pg_catalog.bit_or(i) from public.tstu) ))) then public.tstz_dist( cast(cast(null as timestamptz) as timestamptz), cast((select creation_time from pg_catalog.pg_cursors limit 1 offset 4) as timestamptz)) else public.tstz_dist( cast(cast(null as timestamptz) as timestamptz), cast((select creation_time from pg_catalog.pg_cursors limit 1 offset 4) as timestamptz)) end as "interval")) as c2, pg_catalog.json_build_object() as c3, pg_catalog.pg_control_system() as c4, pg_catalog.json_build_object() as c5, pg_catalog.xpath( cast(public.dblink_connect( cast(pg_catalog.timeofday() as text), cast(public.connection_parameters() as text)) as text), cast(pg_catalog.query_to_xml( cast(public.whoami() as text), cast(pg_catalog.pg_jit_available() as bool), cast(pg_catalog.pg_rotate_logfile() as bool), cast(pg_catalog.pg_current_logfile() as text)) as xml)) as c6 TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 430) 2022-11-30 12:27:28.001 UTC [271498] LOG: could not receive data from client: Connection reset by peer 2022-11-30 12:27:28.905 UTC [221737] LOG: server process (PID 271497) was terminated by signal 6: Aborted 2022-11-30 12:27:28.905 UTC [221737] DETAIL: Failed process was running: update sch18.dt set d = cast(nullif(sch18.dt.d, sch18.dt.d) as date) returning pg_catalog.pg_client_encoding() as c0, cast(coalesce(pg_catalog.pg_conf_load_time(), case when pg_catalog.random() is NULL then pg_catalog.pg_stat_get_last_autovacuum_time( cast(pg_catalog.pg_my_temp_schema() as oid)) else pg_catalog.pg_stat_get_last_autovacuum_time( cast(pg_catalog.pg_my_temp_schema() as oid)) end ) as timestamptz) as c1, pg_catalog.justify_interval( cast(case when ((select f1 from public.invalid_check_con limit 1 offset 5) is not NULL) or ((((select p from sch20.pnt_fdw limit 1 offset 71) >^ (select p from sch30.pnt limit 1 offset 4) ) or ((((select bitv from public.caster limit 1 offset 3) <= (select bitv from public.caster limit 1 offset 4) ) or ((false) and (cast(null as name) ~~ (select t from others.measurement_y1975_fd 2022-11-30 12:27:28.905 UTC [221737] LOG: terminating any other active server processes ################################################ 2022-11-22 13:44:04.604 UTC [1508667] LOG: could not send data to client: Broken pipe 2022-11-22 13:44:04.604 UTC [1508667] FATAL: connection to client lost 2022-11-22 13:44:04.706 UTC [1508668] LOG: could not send data to client: Broken pipe 2022-11-22 13:44:04.706 UTC [1508668] FATAL: connection to client lost 2022-11-22 13:44:05.374 UTC [1508675] LOG: could not send data to client: Broken pipe 2022-11-22 13:44:05.374 UTC [1508675] FATAL: connection to client lost 2022-11-22 13:44:05.413 UTC [1508040] LOG: process 1508040 still waiting for ShareLock on virtual transaction 513/212 after 5000.879 ms 2022-11-22 13:44:05.413 UTC [1508040] DETAIL: Process holding the lock: 1508053. Wait queue: 1508033, 1508064, 1508038, 1508044, 1508040. 2022-11-22 13:44:05.413 UTC [1508040] STATEMENT: REINDEX INDEX CONCURRENTLY sch7.chr_c_idx4; 2022-11-22 13:44:07.293 UTC [1508676] LOG: could not send data to client: Broken pipe 2022-11-22 13:44:07.293 UTC [1508676] FATAL: connection to client lost TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 419) 2022-11-22 13:44:08.486 UTC [1508687] LOG: could not receive data from client: Connection reset by peer 2022-11-22 13:44:09.724 UTC [1315578] LOG: server process (PID 1456482) was terminated by signal 6: Aborted 2022-11-22 13:44:09.724 UTC [1315578] DETAIL: Failed process was running: select subq_0.c2 as c0 from sch20.dt as sample_0 tablesample system (9.8) , lateral (select public.gen_random_uuid() as c0, sample_1.r_id as c1, pg_catalog.pg_notification_queue_usage() as c2, 17 as c3 from others.measurement_y2021_fdw as ref_0 left join public.timetzcmp as sample_1 tablesample system (6.5) on (sample_0.d is NULL) where (true) or (case when false then cast(null as polygon) else cast(null as polygon) end ~= (select polygon from public.tab_core_types limit 1 offset 6) )) as subq_0 where public.test_found() is not NULL limit 109 2022-11-22 13:44:09.724 UTC [1315578] LOG: terminating any other active server processes ################################################ 2022-11-19 13:26:40.056 UTC [1484625] LOG: could not send data to client: Broken pipe 2022-11-19 13:26:40.056 UTC [1484625] FATAL: connection to client lost 2022-11-19 13:26:40.399 UTC [1484628] LOG: could not send data to client: Broken pipe 2022-11-19 13:26:40.399 UTC [1484628] FATAL: connection to client lost 2022-11-19 13:26:40.713 UTC [1484629] LOG: could not send data to client: Broken pipe 2022-11-19 13:26:40.713 UTC [1484629] FATAL: connection to client lost 2022-11-19 13:26:41.601 UTC [1484635] LOG: could not send data to client: Broken pipe 2022-11-19 13:26:41.601 UTC [1484635] FATAL: connection to client lost 2022-11-19 13:26:41.747 UTC [1484643] LOG: could not send data to client: Broken pipe 2022-11-19 13:26:41.747 UTC [1484643] FATAL: connection to client lost 2022-11-19 13:26:41.917 UTC [1484644] LOG: could not send data to client: Broken pipe 2022-11-19 13:26:41.917 UTC [1484644] FATAL: connection to client lost 2022-11-19 13:26:42.325 UTC [1484649] LOG: could not send data to client: Broken pipe 2022-11-19 13:26:42.325 UTC [1484649] FATAL: connection to client lost 2022-11-19 13:26:42.476 UTC [1484652] LOG: could not send data to client: Broken pipe 2022-11-19 13:26:42.476 UTC [1484652] FATAL: connection to client lost TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 419) 2022-11-19 13:26:43.703 UTC [1484658] LOG: could not receive data from client: Connection reset by peer 2022-11-19 13:26:45.109 UTC [1484353] LOG: process 1484353 still waiting for ShareLock on virtual transaction 760/55 after 5001.582 ms 2022-11-19 13:26:45.109 UTC [1484353] DETAIL: Process holding the lock: 1484351. Wait queue: 1484353. 2022-11-19 13:26:45.109 UTC [1484353] STATEMENT: REINDEX INDEX CONCURRENTLY sch11.pnt_p_idx; 2022-11-19 13:26:45.161 UTC [1484627] LOG: process 1484627 still waiting for ShareLock on virtual transaction 1065/47 after 5002.366 ms 2022-11-19 13:26:45.161 UTC [1484627] DETAIL: Process holding the lock: 1484357. Wait queue: 1484627, 1484637, 1484651, 1484648. 2022-11-19 13:26:45.161 UTC [1484627] STATEMENT: REINDEX INDEX CONCURRENTLY sch25.txt_t_idx; 2022-11-19 13:26:45.749 UTC [1379904] LOG: server process (PID 1447940) was terminated by signal 6: Aborted 2022-11-19 13:26:45.749 UTC [1379904] DETAIL: Failed process was running: select pg_catalog.getdatabaseencoding() as c0, case when pg_catalog.statement_timestamp() is not NULL then pg_catalog.pg_get_function_arguments( cast(cast(null as oid) as oid)) else pg_catalog.pg_get_function_arguments( cast(cast(null as oid) as oid)) end as c1, public.test_found() as c2, ref_0.n as c3, ref_0.n as c4, public.myaggn08b( cast(ref_0.n as "numeric")) over (partition by ref_0.n order by ref_0.n) as c5, 35 as c6, pg_catalog.pg_my_temp_schema() as c7, pg_catalog.json_build_array() as c8, pg_catalog.pg_my_temp_schema() as c9, pg_catalog.jsonb_build_object() as c10, public.make_table() as c11, 91 as c12, public.int8alias1in( cast(pg_catalog.timetztypmodout( cast( pg_catalog.bit_or( cast(8 as int4)) over (partition by ref_0.n order by ref_0.n) as int4)) as cstring)) as c13, pg_catalog.pg_replication_origin_session_is_setup() as c14 from sch18.num_fdw as ref_0 where pg_catalog.inet_client_port() === 2022-11-19 13:26:45.749 UTC [1379904] LOG: terminating any other active server processes ################################################ 2022-10-10 12:46:01.941 UTC [887918] LOG: could not send data to client: Broken pipe 2022-10-10 12:46:01.941 UTC [887918] FATAL: connection to client lost 2022-10-10 12:46:11.034 UTC [889217] LOG: could not send data to client: Broken pipe 2022-10-10 12:46:11.034 UTC [889217] FATAL: connection to client lost 2022-10-10 12:46:14.295 UTC [889711] LOG: could not send data to client: Broken pipe 2022-10-10 12:46:14.295 UTC [889711] FATAL: connection to client lost 2022-10-10 12:46:27.973 UTC [891019] LOG: could not send data to client: Broken pipe 2022-10-10 12:46:27.973 UTC [891019] FATAL: connection to client lost 2022-10-10 12:46:28.952 UTC [891384] LOG: could not send data to client: Broken pipe 2022-10-10 12:46:28.952 UTC [891384] FATAL: connection to client lost TRAP: FailedAssertion("!(((allPgXact[proc->pgprocno].xid) != ((TransactionId) 0)))", File: "procarray.c", Line: 419) 2022-10-10 12:46:34.414 UTC [889798] LOG: could not receive data from client: Connection reset by peer 2022-10-10 12:46:35.496 UTC [872082] LOG: server process (PID 889797) was terminated by signal 6: Aborted 2022-10-10 12:46:35.496 UTC [872082] DETAIL: Failed process was running: update t set a = t.a returning cast(public.dblink_connect( cast(pg_catalog.timeofday() as text), cast('dbname=''postgres'' port=54321' as text)) as text) as c0, (select b from s_fdw limit 1 offset 6) as c15 ; 2022-10-10 12:46:35.496 UTC [872082] LOG: terminating any other active server processes ################################################ - robins
Hi, On 2023-02-15 14:46:13 +1030, Robins Tharakan wrote: > Thanks for taking a look and possibly you're correct with your > assumption. I mean I see a ton of FATALs but let me know if I am > mistaken in assuming them to be harmless (since they just convey that > the client's gone away)? Those are indeed not very interesting - although it'd be interesting to know what caused the clients to go away. > Nonetheless, I have provided error logs going back till Oct 22 just in > case the engine can recover from some of those scenarios. Two things > about the test scenario that may be relevant: > > 1. Since performance was the least of my worries, the postgres server > and the client workload are on the same box. Add dblink / FDW to this > mix, and it is easy to end up with a ton of loopback connections > (think SELECT dblink_conect() FROM pg_catalog.pg_class) - IMO > noteworthy, since there are a ton of "Broken pipe"s and one instance > of 'too many file descriptors'. I think the "too many file descriptors" bit might be the interesting part. I suspect the reason you're not seeing this on newer versions is that 13+ has commit 3d475515a15f70a4a3f36fbbba93db6877ff8346 Author: Tom Lane <tgl@sss.pgh.pa.us> Date: 2020-02-24 17:28:33 -0500 Account explicitly for long-lived FDs that are allocated outside fd.c. But I can't yet explain precisely why that causes the assertion failures. A vague guess is that we fail to write 2PC state files due to the lack of FD accounting, throw an error due to that, and then fail with that assert during handling the error. It might be worth trying to reproduce the issue with a much lower ulimit -S -n, to reach the problematic state more quickly. A reproducer would be very useufl. > 2. All versions are subjected to similar workload and it is possible > that v13+ has generally improved in this area, and thus this possibly > crashes less? Unsure. What range of versions / commits are you testing this workload on? Are you testing 11 as well? Because I don't see why we'd have the issue on 12, but not 11. Greetings, Andres Freund
Hi, On Wed, 15 Feb 2023 at 15:36, Andres Freund <andres@anarazel.de> wrote: > > What range of versions / commits are you testing this workload on? > Are you testing 11 as well? Because I don't see why we'd have the issue on 12, > but not 11. My bad, should have explained this upfront. The tests I run are *always* on STABLE (or master). IIRC I had encountered an error in v10 / v11 and had disabled testing those majors. Since currently, I am only testing v12+, this may exist in previous major versions, just not visible in my testing. > It might be worth trying to reproduce the issue with a much lower ulimit -S > -n, to reach the problematic state more quickly. A reproducer would be very > useful.... Those are indeed not very interesting - although it'd be interesting > to know what caused the clients to go away. I am travelling the coming few weeks, but would keep this in mind and revert once I have something to share. - robins