I would have expected more, but this is what I have bt full #0 InitPredicateLocks () at predicate.c:1250 i = <optimized out> info = {num_partitions = 1, ssize = 140731424825288, dsize = 1, max_dsize = 0, ffactor = 140731424836952, keysize = 140356326474085, entrysize = 140728909791233, hash = 0x7ffe96960d58, match = 0x16da2d1, keycopy = 0x7ffe96960d58, alloc = 0x1703af0, hcxt = 0x16da2d0, hctl = 0x0} max_table_size = 117899280 requestSize = <optimized out> found = 0 '\000'
Dave Cramer On 19 January 2017 at 12:05, Dave Cramer <davecra...@gmail.com> wrote: > I'll try to get the stack trace from the core dump, have to build master > first > > Dave Cramer > > On 19 January 2017 at 12:01, Jorge Solórzano <jor...@gmail.com> wrote: > >> Robert, the logs I get from postgres (at least the section that matters) >> is here: >> If you need something else just ask... >> >> 2017-01-19 08:54:57.319 CST [31734] DEBUG: CommitTransaction(1) name: >>> unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0 >>> 2017-01-19 08:54:57.321 CST [31734] DEBUG: parse S_1: DROP TABLE >>> rollbacktest CASCADE >>> 2017-01-19 08:54:57.321 CST [31734] STATEMENT: DROP TABLE rollbacktest >>> CASCADE >>> 2017-01-19 08:54:57.321 CST [31734] DEBUG: StartTransaction(1) name: >>> unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0 >>> 2017-01-19 08:54:57.321 CST [31734] STATEMENT: DROP TABLE rollbacktest >>> CASCADE >>> 2017-01-19 08:54:57.321 CST [31734] LOG: duration: 0.289 ms >>> 2017-01-19 08:54:57.321 CST [31734] DEBUG: bind <unnamed> to S_1 >>> 2017-01-19 08:54:57.321 CST [31734] LOG: duration: 0.073 ms >>> 2017-01-19 08:54:57.321 CST [31734] LOG: execute S_1: DROP TABLE >>> rollbacktest CASCADE >>> 2017-01-19 08:54:57.321 CST [31734] ERROR: table "rollbacktest" does >>> not exist >>> 2017-01-19 08:54:57.321 CST [31734] STATEMENT: DROP TABLE rollbacktest >>> CASCADE >>> 2017-01-19 08:54:57.322 CST [31734] DEBUG: parse S_2: CREATE TABLE >>> rollbacktest (a int, str text) >>> 2017-01-19 08:54:57.322 CST [31734] STATEMENT: CREATE TABLE >>> rollbacktest (a int, str text) >>> 2017-01-19 08:54:57.322 CST [31734] DEBUG: StartTransaction(1) name: >>> unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0 >>> 2017-01-19 08:54:57.322 CST [31734] STATEMENT: CREATE TABLE >>> rollbacktest (a int, str text) >>> 2017-01-19 08:54:57.322 CST [31734] LOG: duration: 0.279 ms >>> 2017-01-19 08:54:57.323 CST [31734] DEBUG: bind <unnamed> to S_2 >>> 2017-01-19 08:54:57.323 CST [31734] LOG: duration: 0.163 ms >>> 2017-01-19 08:54:57.323 CST [31734] LOG: execute S_2: CREATE TABLE >>> rollbacktest (a int, str text) >>> 2017-01-19 08:54:57.324 CST [31734] DEBUG: building index >>> "pg_toast_163960_index" on table "pg_toast_163960" >>> 2017-01-19 08:54:57.324 CST [31734] STATEMENT: CREATE TABLE >>> rollbacktest (a int, str text) >>> 2017-01-19 08:54:57.327 CST [31734] LOG: duration: 4.232 ms >>> 2017-01-19 08:54:57.327 CST [31734] DEBUG: CommitTransaction(1) name: >>> unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 270571/1/5 >>> 2017-01-19 08:54:57.329 CST [31734] DEBUG: parse S_3: >>> 2017-01-19 08:54:57.329 CST [31734] STATEMENT: >>> 2017-01-19 08:54:57.329 CST [31734] DEBUG: StartTransaction(1) name: >>> unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0 >>> 2017-01-19 08:54:57.329 CST [31734] STATEMENT: >>> 2017-01-19 08:54:57.329 CST [31734] LOG: duration: 0.148 ms >>> 2017-01-19 08:54:57.329 CST [31734] DEBUG: bind <unnamed> to S_3 >>> 2017-01-19 08:54:57.329 CST [31734] LOG: duration: 0.088 ms >>> 2017-01-19 08:54:57.329 CST [31734] DEBUG: CommitTransaction(1) name: >>> unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0 >>> 2017-01-19 08:54:57.330 CST [31734] DEBUG: parse S_4: BEGIN >>> 2017-01-19 08:54:57.330 CST [31734] STATEMENT: BEGIN >>> 2017-01-19 08:54:57.330 CST [31734] DEBUG: StartTransaction(1) name: >>> unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0 >>> 2017-01-19 08:54:57.330 CST [31734] STATEMENT: BEGIN >>> 2017-01-19 08:54:57.331 CST [31734] LOG: duration: 0.189 ms >>> 2017-01-19 08:54:57.331 CST [31734] DEBUG: bind <unnamed> to S_4 >>> 2017-01-19 08:54:57.331 CST [31734] LOG: duration: 0.105 ms >>> 2017-01-19 08:54:57.331 CST [31734] LOG: execute S_4: BEGIN >>> 2017-01-19 08:54:57.331 CST [31734] LOG: duration: 0.154 ms >>> 2017-01-19 08:54:57.331 CST [31734] DEBUG: parse S_5: insert into >>> rollbacktest(a, str) values (0, 'test') >>> 2017-01-19 08:54:57.331 CST [31734] STATEMENT: insert into >>> rollbacktest(a, str) values (0, 'test') >>> 2017-01-19 08:54:57.331 CST [31734] LOG: duration: 0.277 ms >>> 2017-01-19 08:54:57.332 CST [31734] DEBUG: bind <unnamed> to S_5 >>> 2017-01-19 08:54:57.332 CST [31734] LOG: duration: 0.168 ms >>> 2017-01-19 08:54:57.332 CST [31734] LOG: execute S_5: insert into >>> rollbacktest(a, str) values (0, 'test') >>> 2017-01-19 08:54:57.332 CST [31734] LOG: duration: 0.233 ms >>> 2017-01-19 08:54:57.333 CST [31734] DEBUG: parse S_6: select * from >>> rollbacktest >>> 2017-01-19 08:54:57.333 CST [31734] STATEMENT: select * from >>> rollbacktest >>> 2017-01-19 08:54:57.333 CST [31734] LOG: duration: 0.093 ms >>> 2017-01-19 08:54:57.333 CST [31734] DEBUG: bind <unnamed> to S_6 >>> 2017-01-19 08:54:57.333 CST [31734] LOG: duration: 0.188 ms >>> 2017-01-19 08:54:57.333 CST [31734] LOG: execute S_6: select * from >>> rollbacktest >>> 2017-01-19 08:54:57.333 CST [31734] LOG: duration: 0.094 ms >>> 2017-01-19 08:54:57.334 CST [31734] DEBUG: parse S_7: select 1/0 >>> 2017-01-19 08:54:57.334 CST [31734] STATEMENT: select 1/0 >>> 2017-01-19 08:54:57.334 CST [31734] LOG: duration: 0.174 ms >>> 2017-01-19 08:54:57.334 CST [31734] DEBUG: bind <unnamed> to S_7 >>> 2017-01-19 08:54:57.334 CST [31734] ERROR: division by zero >>> 2017-01-19 08:54:57.334 CST [31734] STATEMENT: select 1/0 >>> 2017-01-19 08:54:57.335 CST [31734] DEBUG: bind <unnamed> to S_3 >>> 2017-01-19 08:54:57.412 CST [31690] DEBUG: reaping dead processes >>> 2017-01-19 08:54:57.412 CST [31690] DEBUG: server process (PID 31734) >>> was terminated by signal 11: Segmentation fault >>> 2017-01-19 08:54:57.412 CST [31690] LOG: server process (PID 31734) was >>> terminated by signal 11: Segmentation fault >>> 2017-01-19 08:54:57.412 CST [31690] LOG: terminating any other active >>> server processes >>> 2017-01-19 08:54:57.412 CST [31690] DEBUG: sending SIGQUIT to process >>> 31694 >>> 2017-01-19 08:54:57.412 CST [31690] DEBUG: sending SIGQUIT to process >>> 31693 >>> 2017-01-19 08:54:57.412 CST [31690] DEBUG: sending SIGQUIT to process >>> 31695 >>> 2017-01-19 08:54:57.412 CST [31690] DEBUG: sending SIGQUIT to process >>> 31696 >>> 2017-01-19 08:54:57.412 CST [31690] DEBUG: sending SIGQUIT to process >>> 31697 >>> 2017-01-19 08:54:57.412 CST [31693] DEBUG: shmem_exit(-1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.412 CST [31693] DEBUG: shmem_exit(-1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.412 CST [31693] DEBUG: proc_exit(-1): 0 callbacks >>> to make >>> 2017-01-19 08:54:57.412 CST [31696] WARNING: terminating connection >>> because of crash of another server process >>> 2017-01-19 08:54:57.412 CST [31696] 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. >>> 2017-01-19 08:54:57.412 CST [31696] HINT: In a moment you should be >>> able to reconnect to the database and repeat your command. >>> 2017-01-19 08:54:57.412 CST [31696] DEBUG: shmem_exit(-1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.412 CST [31696] DEBUG: shmem_exit(-1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.412 CST [31696] DEBUG: proc_exit(-1): 0 callbacks >>> to make >>> 2017-01-19 08:54:57.412 CST [31695] DEBUG: shmem_exit(-1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.412 CST [31695] DEBUG: shmem_exit(-1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.412 CST [31695] DEBUG: proc_exit(-1): 0 callbacks >>> to make >>> 2017-01-19 08:54:57.412 CST [31697] DEBUG: writing stats file >>> "pg_stat/global.stat" >>> 2017-01-19 08:54:57.412 CST [31694] DEBUG: shmem_exit(-1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.412 CST [31697] DEBUG: writing stats file >>> "pg_stat/db_12254.stat" >>> 2017-01-19 08:54:57.412 CST [31694] DEBUG: shmem_exit(-1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.412 CST [31694] DEBUG: proc_exit(-1): 0 callbacks >>> to make >>> 2017-01-19 08:54:57.412 CST [31697] DEBUG: removing temporary stats >>> file "pg_stat_tmp/db_12254.stat" >>> 2017-01-19 08:54:57.412 CST [31697] DEBUG: writing stats file >>> "pg_stat/db_16385.stat" >>> 2017-01-19 08:54:57.413 CST [31697] DEBUG: removing temporary stats >>> file "pg_stat_tmp/db_16385.stat" >>> 2017-01-19 08:54:57.413 CST [31697] DEBUG: writing stats file >>> "pg_stat/db_0.stat" >>> 2017-01-19 08:54:57.413 CST [31690] DEBUG: reaping dead processes >>> 2017-01-19 08:54:57.413 CST [31697] DEBUG: removing temporary stats >>> file "pg_stat_tmp/db_0.stat" >>> 2017-01-19 08:54:57.413 CST [31690] DEBUG: reaping dead processes >>> 2017-01-19 08:54:57.413 CST [31697] DEBUG: shmem_exit(-1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.413 CST [31697] DEBUG: shmem_exit(-1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.413 CST [31697] DEBUG: proc_exit(-1): 0 callbacks >>> to make >>> 2017-01-19 08:54:57.413 CST [31690] DEBUG: reaping dead processes >>> 2017-01-19 08:54:57.413 CST [31690] DEBUG: reaping dead processes >>> 2017-01-19 08:54:57.413 CST [31690] LOG: all server processes >>> terminated; reinitializing >>> 2017-01-19 08:54:57.413 CST [31690] DEBUG: shmem_exit(1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.413 CST [31690] DEBUG: shmem_exit(1): 5 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.413 CST [31690] DEBUG: cleaning up dynamic shared >>> memory control segment with ID 141917387 >>> 2017-01-19 08:54:57.418 CST [31690] DEBUG: invoking >>> IpcMemoryCreate(size=574734336) >>> 2017-01-19 08:54:57.431 CST [31690] DEBUG: SlruScanDirectory invoking >>> callback on pg_notify/0000 >>> 2017-01-19 08:54:57.431 CST [31690] DEBUG: removing file >>> "pg_notify/0000" >>> 2017-01-19 08:54:57.431 CST [31690] DEBUG: dynamic shared memory system >>> will support 288 segments >>> 2017-01-19 08:54:57.431 CST [31690] DEBUG: created dynamic shared >>> memory control segment 1621489222 (6928 bytes) >>> 2017-01-19 08:54:57.432 CST [31690] DEBUG: forked new backend, >>> pid=31737 socket=10 >>> 2017-01-19 08:54:57.432 CST [31736] LOG: database system was >>> interrupted; last known up at 2017-01-19 08:54:25 CST >>> 2017-01-19 08:54:57.432 CST [31737] LOG: connection received: >>> host=172.16.45.144 port=59096 >>> 2017-01-19 08:54:57.432 CST [31737] FATAL: the database system is in >>> recovery mode >>> 2017-01-19 08:54:57.432 CST [31737] DEBUG: shmem_exit(1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.432 CST [31737] DEBUG: shmem_exit(1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.432 CST [31737] DEBUG: proc_exit(1): 1 callbacks to >>> make >>> 2017-01-19 08:54:57.432 CST [31737] DEBUG: exit(1) >>> 2017-01-19 08:54:57.432 CST [31737] DEBUG: shmem_exit(-1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.432 CST [31737] DEBUG: shmem_exit(-1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.432 CST [31737] DEBUG: proc_exit(-1): 0 callbacks >>> to make >>> 2017-01-19 08:54:57.433 CST [31690] DEBUG: reaping dead processes >>> 2017-01-19 08:54:57.433 CST [31690] DEBUG: server process (PID 31737) >>> exited with exit code 1 >>> 2017-01-19 08:54:57.437 CST [31690] DEBUG: forked new backend, >>> pid=31738 socket=10 >>> 2017-01-19 08:54:57.437 CST [31738] LOG: connection received: >>> host=172.16.45.144 port=59098 >>> 2017-01-19 08:54:57.437 CST [31738] FATAL: the database system is in >>> recovery mode >>> 2017-01-19 08:54:57.437 CST [31738] DEBUG: shmem_exit(1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.437 CST [31738] DEBUG: shmem_exit(1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.437 CST [31738] DEBUG: proc_exit(1): 1 callbacks to >>> make >>> 2017-01-19 08:54:57.437 CST [31738] DEBUG: exit(1) >>> 2017-01-19 08:54:57.437 CST [31738] DEBUG: shmem_exit(-1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.437 CST [31738] DEBUG: shmem_exit(-1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.437 CST [31738] DEBUG: proc_exit(-1): 0 callbacks >>> to make >>> 2017-01-19 08:54:57.438 CST [31690] DEBUG: reaping dead processes >>> 2017-01-19 08:54:57.438 CST [31690] DEBUG: server process (PID 31738) >>> exited with exit code 1 >>> 2017-01-19 08:54:57.439 CST [31690] DEBUG: forked new backend, >>> pid=31739 socket=10 >>> 2017-01-19 08:54:57.440 CST [31739] LOG: connection received: >>> host=172.16.45.144 port=59100 >>> 2017-01-19 08:54:57.440 CST [31739] FATAL: the database system is in >>> recovery mode >>> 2017-01-19 08:54:57.440 CST [31739] DEBUG: shmem_exit(1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.440 CST [31739] DEBUG: shmem_exit(1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.440 CST [31739] DEBUG: proc_exit(1): 1 callbacks to >>> make >>> 2017-01-19 08:54:57.440 CST [31739] DEBUG: exit(1) >>> 2017-01-19 08:54:57.440 CST [31739] DEBUG: shmem_exit(-1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.440 CST [31739] DEBUG: shmem_exit(-1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.440 CST [31739] DEBUG: proc_exit(-1): 0 callbacks >>> to make >>> 2017-01-19 08:54:57.441 CST [31690] DEBUG: reaping dead processes >>> 2017-01-19 08:54:57.441 CST [31690] DEBUG: server process (PID 31739) >>> exited with exit code 1 >>> 2017-01-19 08:54:57.442 CST [31690] DEBUG: forked new backend, >>> pid=31740 socket=10 >>> 2017-01-19 08:54:57.444 CST [31740] LOG: connection received: >>> host=172.16.45.144 port=59102 >>> 2017-01-19 08:54:57.444 CST [31740] FATAL: the database system is in >>> recovery mode >>> 2017-01-19 08:54:57.444 CST [31740] DEBUG: shmem_exit(1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.444 CST [31740] DEBUG: shmem_exit(1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.444 CST [31740] DEBUG: proc_exit(1): 1 callbacks to >>> make >>> 2017-01-19 08:54:57.444 CST [31740] DEBUG: exit(1) >>> 2017-01-19 08:54:57.444 CST [31740] DEBUG: shmem_exit(-1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.444 CST [31740] DEBUG: shmem_exit(-1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.444 CST [31740] DEBUG: proc_exit(-1): 0 callbacks >>> to make >>> 2017-01-19 08:54:57.445 CST [31690] DEBUG: reaping dead processes >>> 2017-01-19 08:54:57.445 CST [31690] DEBUG: server process (PID 31740) >>> exited with exit code 1 >>> 2017-01-19 08:54:57.448 CST [31690] DEBUG: forked new backend, >>> pid=31741 socket=10 >>> 2017-01-19 08:54:57.449 CST [31741] LOG: connection received: >>> host=172.16.45.144 port=59104 >>> 2017-01-19 08:54:57.450 CST [31741] FATAL: the database system is in >>> recovery mode >>> 2017-01-19 08:54:57.450 CST [31741] DEBUG: shmem_exit(1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.450 CST [31741] DEBUG: shmem_exit(1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.450 CST [31741] DEBUG: proc_exit(1): 1 callbacks to >>> make >>> 2017-01-19 08:54:57.450 CST [31741] DEBUG: exit(1) >>> 2017-01-19 08:54:57.450 CST [31741] DEBUG: shmem_exit(-1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.450 CST [31741] DEBUG: shmem_exit(-1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.450 CST [31741] DEBUG: proc_exit(-1): 0 callbacks >>> to make >>> 2017-01-19 08:54:57.452 CST [31690] DEBUG: reaping dead processes >>> 2017-01-19 08:54:57.453 CST [31690] DEBUG: server process (PID 31741) >>> exited with exit code 1 >>> 2017-01-19 08:54:57.454 CST [31690] DEBUG: forked new backend, >>> pid=31742 socket=10 >>> 2017-01-19 08:54:57.455 CST [31742] LOG: connection received: >>> host=172.16.45.144 port=59106 >>> 2017-01-19 08:54:57.455 CST [31742] FATAL: the database system is in >>> recovery mode >>> 2017-01-19 08:54:57.455 CST [31742] DEBUG: shmem_exit(1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.455 CST [31742] DEBUG: shmem_exit(1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.455 CST [31742] DEBUG: proc_exit(1): 1 callbacks to >>> make >>> 2017-01-19 08:54:57.455 CST [31742] DEBUG: exit(1) >>> 2017-01-19 08:54:57.455 CST [31742] DEBUG: shmem_exit(-1): 0 >>> before_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.455 CST [31742] DEBUG: shmem_exit(-1): 0 >>> on_shmem_exit callbacks to make >>> 2017-01-19 08:54:57.455 CST [31742] DEBUG: proc_exit(-1): 0 callbacks >>> to make >>> 2017-01-19 08:54:57.455 CST [31690] DEBUG: reaping dead processes >>> 2017-01-19 08:54:57.455 CST [31690] DEBUG: server process (PID 31742) >>> exited with exit code 1 >>> 2017-01-19 08:54:57.458 CST [31690] DEBUG: forked new backend, >>> pid=31743 socket=10 >>> >> >> >> >> On Thu, Jan 19, 2017 at 10:53 AM, Robert Haas <robertmh...@gmail.com> >> wrote: >> >>> On Thu, Jan 19, 2017 at 10:59 AM, Jorge Solórzano <jor...@gmail.com> >>> wrote: >>> > I have isolated the tests run by the pgjdbc project, I have disabled >>> the >>> > replication (wal_level = minimal) and the error is still present so it >>> seems >>> > that this error is not related to the replication, the test that cause >>> the >>> > error is AutoRollbackTestSuite, I have enable DEBUG mesages in >>> postgresql >>> > and pgjdbc and this is what I get: >>> > >>> > https://drive.google.com/drive/folders/0ByHbu-sR29gda2d2LUFpV0lPdUk >>> >>> Can somebody paste the stack trace into an email, here? There's >>> reference to it upthread, but it's not obvious where it actually is. >>> >>> -- >>> Robert Haas >>> EnterpriseDB: http://www.enterprisedb.com >>> The Enterprise PostgreSQL Company >>> >> >> >