Not sure if this should have been a stackoverflow question or dba.stackexchange, but here it is.
I have 2 servers both of them have Postgresql15-server installed. Both the nodes share the disk, which gets mounted on the active node. All of this is managed by Pacemaker. At any given point, this is what the cluster resource manager (crm_mon) output looks like:
Stack: corosync
Current DC: host2 (version 1.1.23-1.el7_9.1-9acf116022) - partition with quorum
Last updated: Sat Jul 15 01:19:09 2023
Last change: Fri Jul 14 19:15:14 2023 by root via cibadmin on host1
2 nodes configured
11 resource instances configured (2 DISABLED)
Online: [ host1 host2 ]
Active resources:
Resource Group: pgsql-Hgroup-PPINFO01
PPINFO01-datavg (ocf::heartbeat:LVM): Started host1
PPINFO01-datavgFS (ocf::heartbeat:Filesystem): Started host1
pgsql-PPINFO01 (ocf::heartbeat:pgsql): Started host1
vip-master-PPINFO01 (ocf::heartbeat:IPaddr2): Started host1
FailoverStop (ocf::heartbeat:failoverstop): Started host1
Resource Group: pgsql-Lgroup-PPINFO01
PPINFO01-archvg (ocf::heartbeat:LVM): Started host1
PPINFO01-backupvg (ocf::heartbeat:LVM): Started host1
PPINFO01-archvgFS (ocf::heartbeat:Filesystem): Started host1
PPINFO01-backupvgFS (ocf::heartbeat:Filesystem): Started host1
Node Attributes:
* Node host1:
* Node host2:
Migration Summary:
* Node host1:
* Node host2:
Last evening, Postgres on host1 froze and was unresponsive. This caused Pacemaker to failover to the other node, but there also, the filesystem could not be mounted. This switching over continued for a while before the DB became normal again. I have been trying to understand the root cause of this. This has been happening for years on this DB which is about 5TB. Earlier it mostly happened when there was a big partition table being dropped. But yesterday there was no such action. Nothing in the Postgres logs suggests anything extra ordinary. Here are the Postgres logs at the exact moment it happened.
2023-07-14 18:16:39.950 JST,"postgres","template1",78827,"[local]",64b11277.133eb,4,"idle",2023-07-14 18:16:39 JST,,0,LOG,00000,"disconnection: session time: 0:00:00.004 user=postgres database=template1 host=[local]",,,,,,,,,"psql","client backend",,0
2023-07-14 18:16:47.125 JST,,,78317,,64b1126c.131ed,1,,2023-07-14 18:16:28 JST,32/26387,0,LOG,XX002,"valid left arget 80770 with leafblkno 80770 and scanblkno 80770 in index ""ix_dba_stat_index_relid""",,,,,"while vacuuming index ""ix_dba_stat_index_relid"" of relation ""dba_monitoring.dba_stat_index""",,,,"","autovacuum worker",,0
2023-07-14 18:16:47.151 JST,,,78317,,64b1126c.131ed,2,,2023-07-14 18:16:28 JST,32/26387,0,ERROR,XX002,"right sibling's left-link doesn't match: block 83479 links to 100527 instead of expected 81297 in index ""ix_dba_stat_index_relid""",,,,,"while vacuuming index ""ix_dba_stat_index_relid"" of relation ""dba_monitoring.dba_stat_index""automatic vacuum of table ""db_name.dba_monitoring.dba_stat_index""",,,,"","autovacuum worker",,0
2023-07-14 18:16:47.153 JST,,,79293,"[local]",64b1127f.135bd,1,"",2023-07-14 18:16:47 JST,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,"","not initialized",,0
2023-07-14 18:16:47.154 JST,"postgres","template1",79293,"[local]",64b1127f.135bd,2,"authentication",2023-07-14 18:16:47 JST,25/41858,0,LOG,00000,"connection authorized: user=postgres database=template1 application_name=psql",,,,,,,,,"","client backend",,-797221724103369660
2023-07-14 18:16:47.156 JST,"postgres","template1",79293,"[local]",64b1127f.135bd,3,"idle",2023-07-14 18:16:47 JST,25/41859,0,LOG,00000,"statement: select now();",,,,,,,,,"psql","client backend",,0
I checked the system logs and corosync logs on both the hosts and couldn't find the reason in them either. The same kind of logs can be seen related to the Kernel panic on these hosts when a big chunk of data is dropped.
Host1 syslog
2023-07-14T18:19:26.857784+09:00 host1 kernel: [1625184.083211] INFO: task postgres:141196 blocked for more than 120 seconds.
2023-07-14T18:19:26.857825+09:00 host1 kernel: [1625184.083270] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
2023-07-14T18:19:26.857829+09:00 host1 kernel: [1625184.083328] postgres D ffff9a40641b05e0 0 141196 140346 0x0000008
0
2023-07-14T18:19:26.857831+09:00 host1 kernel: [1625184.083335] Call Trace:
2023-07-14T18:19:26.857851+09:00 host1 kernel: [1625184.083346] [<ffffffffa0fb7ca9>] schedule+0x29/0x70
2023-07-14T18:19:26.857853+09:00 host1 kernel: [1625184.083396] [<ffffffffc0ce2cfc>] xfs_log_force_lsn+0x32c/0x370 [xfs]
2023-07-14T18:19:26.857855+09:00 host1 kernel: [1625184.083403] [<ffffffffa08e1020>] ? wake_up_state+0x20/0x20
2023-07-14T18:19:26.857857+09:00 host1 kernel: [1625184.083447] [<ffffffffc0cc251d>] xfs_file_fsync+0xfd/0x1c0 [xfs]
2023-07-14T18:19:26.857863+09:00 host1 kernel: [1625184.083452] [<ffffffffa0a92ba5>] do_fsync+0x55/0x80
2023-07-14T18:19:26.857865+09:00 host1 kernel: [1625184.083458] [<ffffffffa09467a6>] ? __audit_syscall_exit+0x1f6/0x2b0
2023-07-14T18:19:26.857867+09:00 host1 kernel: [1625184.083462] [<ffffffffa0a92e70>] SyS_fsync+0x10/0x20
2023-07-14T18:19:26.857869+09:00 host1 kernel: [1625184.083466] [<ffffffffa0fc539a>] system_call_fastpath+0x25/0x2a
2023-07-14T18:19:26.857871+09:00 host1 kernel: [1625184.083470] INFO: task postgres:141197 blocked for more than 120 seconds.
2023-07-14T18:19:26.857873+09:00 host1 kernel: [1625184.083520] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
2023-07-14T18:19:26.857905+09:00 host1 kernel: [1625184.083575] postgres D ffff9a40641b68e0 0 141197 140346 0x0000008
0
2023-07-14T18:19:26.857908+09:00 host1 kernel: [1625184.083580] Call Trace:
2023-07-14T18:19:26.857910+09:00 host1 kernel: [1625184.083586] [<ffffffffa0fb7ca9>] schedule+0x29/0x70
2023-07-14T18:19:26.857912+09:00 host1 kernel: [1625184.083631] [<ffffffffc0ce2cfc>] xfs_log_force_lsn+0x32c/0x370 [xfs]
2023-07-14T18:19:26.857914+09:00 host1 kernel: [1625184.083636] [<ffffffffa08e1020>] ? wake_up_state+0x20/0x20
2023-07-14T18:19:26.857916+09:00 host1 kernel: [1625184.083676] [<ffffffffc0cc251d>] xfs_file_fsync+0xfd/0x1c0 [xfs]
2023-07-14T18:19:26.857918+09:00 host1 kernel: [1625184.083680] [<ffffffffa0a92ba5>] do_fsync+0x55/0x80
2023-07-14T18:19:26.857923+09:00 host1 kernel: [1625184.083686] [<ffffffffa09467a6>] ? __audit_syscall_exit+0x1f6/0x2b0
2023-07-14T18:19:26.857925+09:00 host1 kernel: [1625184.083689] [<ffffffffa0a92e70>] SyS_fsync+0x10/0x20
2023-07-14T18:19:26.857927+09:00 host1 kernel: [1625184.083693] [<ffffffffa0fc539a>] system_call_fastpath+0x25/0x2a
2023-07-14T18:19:26.857929+09:00 host1 kernel: [1625184.083724] INFO: task kworker/u521:2:14504 blocked for more than 120 second
s.
2023-07-14T18:19:26.857931+09:00 host1 kernel: [1625184.083776] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Host1 corosync
Jul 14 18:19:34 [6729] host1 lrmd: warning: child_timeout_callback: pgsql-PPINFO01_monitor_7000 process (PID 85613) timed out
Jul 14 18:19:34 [6729] host1 lrmd: warning: operation_finished: pgsql-PPINFO01_monitor_7000:85613 - timed out after 60000ms
Jul 14 18:19:34 [6732] host1 crmd: error: process_lrm_event: Result of monitor operation for pgsql-PPINFO01 on host1: Timed Out | call=69 key=pgsql-PPINFO01_monitor_7000 timeout=60000ms
Jul 14 18:19:34 [6727] host1 cib: info: cib_process_request: Forwarding cib_modify operation for section status to all (origin=local/crmd/92)
Jul 14 18:19:34 [6727] host1 cib: info: cib_perform_op: Diff: --- 0.294.2 2
Host2 syslog
2023-07-14T18:19:34.979829+09:00 host2 crmd[6668]: notice: State transition S_IDLE -> S_POLICY_ENGINE
2023-07-14T18:19:35.018081+09:00 host2 pengine[6667]: warning: Processing failed monitor of pgsql-PPINFO01 on host1: unknown error
2023-07-14T18:19:35.025585+09:00 host2 pengine[6667]: notice: * Recover pgsql-PPINFO01 ( host1 )
2023-07-14T18:19:35.025919+09:00 host2 pengine[6667]: notice: * Restart vip-master-PPINFO01 ( host1 ) due to required pgsql-PPINFO01 start
2023-07-14T18:19:35.026223+09:00 host2 pengine[6667]: notice: * Restart FailoverStop ( host1 ) due to required vip-master-PPINFO01 start
2023-07-14T18:19:35.028054+09:00 host2 pengine[6667]: notice: Calculated transition 1823, saving inputs in /var/lib/pacemaker/pengine/pe-input-999.bz2
2023-07-14T18:19:35.063137+09:00 host2 pengine[6667]: warning: Processing failed monitor of pgsql-PPINFO01 on host1: unknown error
2023-07-14T18:19:35.067165+09:00 host2 pengine[6667]: warning: Forcing pgsql-PPINFO01 away from host1 after 1 failures (max=1)
Host2 corosync
Jul 14 18:19:34 [6668] host2 crmd: info: update_failcount: Updating failcount for pgsql-PPINFO01 on host1 after failed monitor: rc=1 (update=value++, time=1689326374)
Jul 14 18:19:34 [6668] host2 crmd: info: process_graph_event: Detected action (679.20) pgsql-PPINFO01_monitor_7000.69=unknown error: failed
My Postgres.conf settings related to memory are here
# Memory-related settings
# -----------------------
shared_buffers = 32GB # Physical memory 1/4
##DEBUG: mmap(1652555776) with MAP_HUGETLB failed, huge pages disabled: Cannot allocate memory
#huge_pages = try # on, off, or try
#temp_buffers = 16MB # depends on DB checklist
work_mem = 8MB
effective_cache_size = 64GB # Physical memory 1/2
maintenance_work_mem = 512MB
wal_buffers = 64MB
Both hosts have this config:
Architecture: x86_64
CPU op-mode(s): 32-bit, 64-bit
Byte Order: Little Endian
CPU(s): 36
On-line CPU(s) list: 0-35
Thread(s) per core: 1
Core(s) per socket: 18
Socket(s): 2
NUMA node(s): 4
Vendor ID: GenuineIntel
CPU family: 6
Model: 85
If it is a hardware failure, could it have been caused by any settings in Postgres on my side? If not, then how do I convince DELL/System admin that it is a hardware issue and what can be done about it?
log_min_duration_statementsso that you can find statements that hang for a long time, and alsolog_checkpoints = on. The latter has helped me before by proving that there were occasional long sync times, which must be a storage problem.log_min_duration_statement = 1000andlog_checkpoints = onare set already. I am pretty sure it is storage issue as well, but every time I approach DELL, they say there is nothing odd in the logs, so they can't help. I am just trying to figure out how I can prove it to them. As for the statements that usually take a long time are the drop table partition ones. This time when this error occurred, it was about 10 long queries on a table partition that is 1.5TB.