PostgreSQL 跟蹤checkpointer出現死鎖

gdb跟蹤checkpointer程式,出現死鎖,Mark一下.

跟蹤checkpointer程式,檢視共享記憶體中的信(heckpointerShmem->requests)

(gdb) p CheckpointerShmem->requests[150] ... $16 = {rnode = {spcNode = 1663, dbNode = 16402, relNode = 26185}, forknum = MAIN_FORKNUM, segno = 0} (gdb) p CheckpointerShmem->requests[200] Cannot access memory at address 0xf9fb18 ... 

然後,請求checkpoint的程式報錯

testdb=# update t_wal_ckpt set c2 = 'C2#'||substr(c2,4,40); UPDATE 8192 testdb=# checkpoint; 2019-01-07 12:30:32.114 CST [1418] PANIC:  stuck spinlock detected at RequestCheckpoint, checkpointer.c:1050 2019-01-07 12:30:32.114 CST [1418] STATEMENT:  checkpoint; 2019-01-07 12:30:37.081 CST [1390] PANIC:  stuck spinlock detected at FirstCallSinceLastCheckpoint, checkpointer.c:1376 2019-01-07 12:30:38.610 CST [1370] LOG:  background writer process (PID 1390) was terminated by signal 6: Aborted 2019-01-07 12:30:38.610 CST [1370] LOG:  terminating any other active server processes 2019-01-07 12:30:38.611 CST [1392] WARNING:  terminating connection because of crash of another server process 2019-01-07 12:30:38.611 CST [1392] 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-01-07 12:30:38.611 CST [1392] HINT:  In a moment you should be able to reconnect to the database and repeat your command. 2019-01-07 12:30:38.613 CST [1558] WARNING:  terminating connection because of crash of another server process 2019-01-07 12:30:38.613 CST [1558] 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-01-07 12:30:38.613 CST [1558] HINT:  In a moment you should be able to reconnect to the database and repeat your command. PANIC:  stuck spinlock detected at RequestCheckpoint, checkpointer.c:1050 server closed the connection unexpectedly     This probably means the server terminated abnormally     before or while processing the request. The connection to the server was lost. Attempting reset: 2019-01-07 12:30:54.041 CST [1560] FATAL:  the database system is in recovery mode Failed. !>  

嘗試重新連線,發現DB已coredump.

[xdb@localhost ~]$  [xdb@localhost ~]$ psql -d testdb 2019-01-07 14:10:16.114 CST [1629] FATAL:  the database system is in recovery mode psql: FATAL:  the database system is in recovery mode 

執行恢復

[xdb@localhost ~]$ pg_ctl start pg_ctl: another server might be running; trying to start server anyway waiting for server to start....2019-01-07 14:11:50.821 CST [1632] FATAL:  lock file "postmaster.pid" already exists 2019-01-07 14:11:50.821 CST [1632] HINT:  Is another postmaster (PID 1370) running in data directory "/data/xdb/pg111db"?  stopped waiting pg_ctl: could not start server Examine the log output. [xdb@localhost ~]$ find /data/xdb -name postmaster.pid /data/xdb/pg111db/postmaster.pid [xdb@localhost ~]$ rm -rf /data/xdb/pg111db/postmaster.pid [xdb@localhost ~]$ pg_ctl start waiting for server to start....2019-01-07 14:12:44.578 CST [1639] LOG:  could not bind IPv6 address "::1": Address already in use [xdb@localhost ~]$ ps -ef|grep postgres xdb       1370     1  0 12:01 pts/0    00:00:02 /appdb/atlasdb/pg11.1/bin/postgres xdb       1389  1370  0 12:01 ?        00:00:00 [postgres] <defunct> xdb       1641  1332  0 14:12 pts/0    00:00:00 grep --color=auto postgres [xdb@localhost ~]$ kill -9 1370 [xdb@localhost ~]$ pg_ctl start waiting for server to start....2019-01-07 14:13:33.125 CST [1648] LOG:  listening on IPv6 address "::1", port 5432 2019-01-07 14:13:33.125 CST [1648] LOG:  listening on IPv4 address "127.0.0.1", port 5432 2019-01-07 14:13:33.142 CST [1648] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432" .2019-01-07 14:13:34.361 CST [1649] LOG:  database system was interrupted; last known up at 2019-01-07 12:26:22 CST 2019-01-07 14:13:34.818 CST [1649] LOG:  database system was not properly shut down; automatic recovery in progress 2019-01-07 14:13:34.863 CST [1649] LOG:  redo starts at 1/48F9ED08 .2019-01-07 14:13:35.467 CST [1649] LOG:  invalid record length at 1/4914FF58: wanted 24, got 0 2019-01-07 14:13:35.467 CST [1649] LOG:  redo done at 1/4914FF30 2019-01-07 14:13:35.467 CST [1649] LOG:  last completed transaction was at log time 2019-01-07 12:28:37.521542+08 2019-01-07 14:13:35.977 CST [1648] LOG:  database system is ready to accept connections  done server started 

經分析,是因為共享記憶體結構中的CheckpointerShmem->ckpt_lck導致的.
在跟蹤checkpointer程式時,執行

SpinLockRelease(&CheckpointerShmem->ckpt_lck); 

釋放lock後,不再出現上述問題.