Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication

Поиск
Список
Период
Сортировка
От Jorge Solórzano
Тема Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication
Дата
Msg-id CA+cVU8MmccSRU1p1YTfFMLKcEk5h5_R_HRertTw92D9SQtr1bQ@mail.gmail.com
обсуждение исходный текст
Ответ на Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication  (Robert Haas <robertmhaas@gmail.com>)
Ответы Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication  (Dave Cramer <davecramer@gmail.com>)
Re: [HACKERS] [JDBC] SEGFAULT in HEAD with replication  (Robert Haas <robertmhaas@gmail.com>)
Re: [HACKERS] SEGFAULT in HEAD with replication  (Dave Cramer <davecramer@gmail.com>)
Re: [HACKERS] SEGFAULT in HEAD with replication  (Robert Haas <robertmhaas@gmail.com>)
Список pgsql-hackers
Дерево обсуждения
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 <robertmhaas@gmail.com> wrote:
On Thu, Jan 19, 2017 at 10:59 AM, Jorge Solórzano <jorsol@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

В списке pgsql-hackers по дате отправления:

Предыдущее
От: Tom Lane
Дата:
Сообщение: Re: [HACKERS] [COMMITTERS] pgsql: Generate fmgr prototypes automatically
Следующее
От: Dave Cramer
Дата:
Сообщение: Re: [HACKERS] SEGFAULT in HEAD with replication