0

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?

4
  • 1
    This is not a panic; "task postgres:141196 blocked for more than 120 seconds" means exactly what it says. There is a bug in the XFS file system, or the storage is extremely overloaded, or (the connection to) the storage failed.
    – CL.
    Commented Jul 16, 2023 at 17:04
  • Would you have any suggestions on which logs to look at to prove any of the above? There is an over 15% IO wait at the time of crash, but I am not sure what parameters to change to resolve this issue.
    – Abhishek B
    Commented Jul 17, 2023 at 7:07
  • It smells like a problem in the storage, but I can't say if it is the hardware or the software. I recommend setting log_min_duration_statements so that you can find statements that hang for a long time, and also log_checkpoints = on. The latter has helped me before by proving that there were occasional long sync times, which must be a storage problem. Commented Jul 17, 2023 at 7:27
  • log_min_duration_statement = 1000 and log_checkpoints = on are 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.
    – Abhishek B
    Commented Jul 17, 2023 at 7:49

0

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Browse other questions tagged or ask your own question.