案例說明：
主庫在業務高峰期間，客戶執行建表等DDL操作，主庫產生“AccessExclusiveLock ”鎖，導致大量的事務產生鎖衝突，大量的會話堆積，客戶端session訪問主庫失敗。備庫和主庫之間的PQping的心跳通訊測試也受到阻塞，在指定閾值（10次）範圍內，嘗試連線失敗後，觸發主備切換。

一、案例故障資訊

1）主庫sys_log日誌

=如下圖所示，在主庫上產生了“AccessExclusiveLock ”鎖，出現大量鎖衝突=

2022-03-23 11:36:00 CST [3165572]: [2241-1] user=bjoa,db=gzwwwoa,app=Kingbase8 JDBC Driver,client=192.3.89.9LOG:  process 3165572 still waiting for AccessExclusiveLock on tuple (551717,56) of relation 20499 of database 16461 after 1012.724 ms
2022-03-23 11:36:00 CST [3165572]: [2242-1] user=bjoa,db=gzwwwoa,app=Kingbase8 JDBC Driver,client=192.3.89.9DETAIL:  Process holding the lock: 3219816. Wait queue: 3172465, 3220570, 3211000, 3194976, 3195098, 3189287, 3194983, 3148868, 3219348, 3219365, 3219380, 3219672, 3220580, 3218107, 3219360, 3217745, 3211003, 3219456, 3219687, 3217717, 3211892, 3079421, 3218763, 3220067, 3217706, 3217630, 3217372, 3217375, 3194995, 3220143, 3124556, 3117826, 3194934, 3194832, 3218969, 3217628, 3119221, 3219787, 3219385, 3219345, 3217769, 3216508, 3214193, 3218108, 3216459, 3220223, 3218058, 3220627, 3220413, 3215490, 3220591, 3215493, 3120204, 3218892, 3168511, 3194835, 3220588, 3220546, 3217718, 3217629, 3217386, 3220586, 3217778, 3220178, 3218789, 3217707, 3218839, 3150225, 3167040, 3219539, 3169071, 3194836, 3195048, 3194988, 3220523, 3220100, 3217711, 3215655, 3218068, 3168514, 3220589, 3220583, 3218721, 3133538, 3216464, 3218089, 3219051, 3212018, 3161515, 3220060, 3216453, 3217761, 3220176, 3216469, 3218843, 3218492, 3212020, 3210997, 3217715, 3172444, 3217674, 3157246, 3217682, 3220212, 3191504, 3216431, 3220410, 3194889, 3219677, 3220099, 3218810, 3219364, 3218099, 3182051, 3220574, 3218029, 3212166, 3219418, 3220106, 3219772, 3216447, 3215484, 3214194, 3219366, 3195081, 3170956, 3159849, 3170355, 3219405, 3218967, 3217626, 3218115, 3173965, 3220056, 3216482, 3220381, 3219349, 3194845, 3220389, 3217064, 3161902, 3220057, 3218055, 3211895, 3217770, 3220119, 3220227, 3220529, 3220052, 3219065, 3176922, 3194369, 3218054, 3220065, 3212136, 3218105, 3217775, 3218060, 3195091, 3058330, 3220571, 3217739, 3220511, 3220059, 3219400, 3219412, 3219379, 3211893, 3220192, 3220557, 3219676, 3220112, 3219420, 3165574, 3220216, 3217767, 3219533, 3220602, 3194828, 3220097, 3219783, 3219327, 3219329, 3212247, 3220053, 3219766, 3192177, 3219673, 3212162, 3220568, 3212106, 3220527, 3215487, 3220046, 3220537, 3121709, 3153617, 3217422, 3218073, 3218804, 3216434, 3220168, 3140776, 3156690, 3220199, 3212201, 3194380, 3194821, 3220516, 3217371, 3212015, 3194824, 3219346, 3216427, 3216506, 3219347, 3218102, 3215687, 3194816, 3220600, 3210998, 3218483, 3220593, 3220364, 3220407, 3220396, 3218046, 3220544, 3219417, 3218968, 3220380, 3136699, 3220555, 3218110, 3171869, 3220111, 3220084, 3220569, 3195041, 3217768, 3212151, 3179922, 3220167, 3219388, 3215489, 3194699, 3220162, 3160067, 3194809, 3220115, 3220285, 3218771, 3218837, 3218104, 3216437, 3219769, 3217676, 3215481, 3215645, 3218768, 3220418, 3218812, 3175055, 3219799, 3218777, 3153616, 3215488, 3217771, 3218770, 2983432, 3218806, 3216483, 3220130, 3215674, 3218772, 3215672, 3219746, 3211897, 3217374, 3218823, 3220133, 3220228, 3219745, 3220181, 3217765, 3219810, 3215686, 3217727, 3170682, 3219536, 3194808, 3217390, 3212163, 3179926, 3218059, 3218026, 3218824, 3216432, 3212128, 3220506, 3169074, 3220556, 3172449, 3220522, 3220366, 3233821, 3218795, 3218808, 3220287, 3220338, 3219780, 3165572, 3218832, 3220538, 3220499, 3220224, 3215654, 3218841, 3217776, 3220374, 3219675, 3218756, 3215677, 3195087, 3219754.
2022-03-23 11:36:00 CST [3165572]: [2243-1] user=bjoa,db=gzwwwoa,app=Kingbase8 JDBC Driver,client=192.3.89.9CONTEXT:  SQL statement "DELETE FROM tbtemp_gettodolistmsg1"
	PL/SQL function fngettodolistmsg(integer,integer,refcursor) line 268 at SQL statement
 

2）備庫hamgr.log日誌

=如以下日誌所示，備庫在通過PQping() 函式和主庫執行心跳通訊測試，在超過閾值（10次）後，觸發主備切換。=

[2022-03-23 11:36:51] [WARNING] unable to ping "host=192.3.89.16 user=esrep dbname=esrep port=54321 connect_timeout=10 keepalives=1 keepalives_idle=10 keepalives_interval=1 keepalives_count=3"
[2022-03-23 11:36:51] [DETAIL] PQping() returned "PQPING_NO_RESPONSE"
[2022-03-23 11:36:51] [WARNING] unable to connect to upstream node "node16" (ID: 1)
[2022-03-23 11:36:51] [INFO] sleeping 6 seconds until next reconnection attempt
[2022-03-23 11:36:57] [INFO] checking state of node 1, 1 of 10 attempts
[2022-03-23 11:37:07] [WARNING] unable to ping "user=esrep connect_timeout=10 dbname=esrep host=192.3.89.16 port=54321 keepalives=1 keepalives_idle=10 keepalives_interval=1 keepalives_count=3 fallback_application_name=repmgr"
[2022-03-23 11:37:07] [DETAIL] PQping() returned "PQPING_NO_RESPONSE"
[2022-03-23 11:37:07] [INFO] sleeping 6 seconds until next reconnection attempt
......
[2022-03-23 11:38:57] [INFO] checking state of node 1, 10 of 10 attempts
[2022-03-23 11:39:07] [WARNING] unable to ping "user=esrep connect_timeout=10 dbname=esrep host=192.3.89.16 port=54321 keepalives=1 keepalives_idle=10 keepalives_interval=1 keepalives_count=3 fallback_application_name=repmgr"
[2022-03-23 11:39:07] [DETAIL] PQping() returned "PQPING_NO_RESPONSE"
[2022-03-23 11:39:07] [WARNING] unable to reconnect to node 1 after 10 attempts
[2022-03-23 11:39:07] [NOTICE] setting "wal_retrieve_retry_interval" to 86405000 milliseconds
[2022-03-23 11:39:07] [INFO] sleeping 5 seconds
[2022-03-23 11:39:12] [NOTICE] killing WAL receiver with PID 1794980
[2022-03-23 11:39:13] [INFO] WAL receiver with pid 1794980 killed
[2022-03-23 11:39:14] [NOTICE] killing WAL receiver with PID 1657239
[2022-03-23 11:39:15] [INFO] WAL receiver with pid 1657239 killed
[2022-03-23 11:39:16] [NOTICE] WAL receiver disconnected on all sibling nodes
[2022-03-23 11:39:16] [INFO] WAL receiver disconnected on all 0 sibling nodes
[2022-03-23 11:39:16] [INFO] 0 active sibling nodes registered
[2022-03-23 11:39:16] [INFO] primary and this node have the same location ("default")
[2022-03-23 11:39:16] [INFO] no other sibling nodes - we win by default
[2022-03-23 11:39:16] [NOTICE] setting "wal_retrieve_retry_interval" to 5000 ms
[2022-03-23 11:39:16] [NOTICE] this node is the only available candidate and will now promote itself
[2022-03-23 11:39:16] [INFO] try to ping the trusted_servers "192.3.89.1" before execute promote_command
[2022-03-23 11:39:18] [NOTICE] PING 192.3.89.1 (192.3.89.1) 56(84) bytes of data.

--- 192.3.89.1 ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1000ms
rtt min/avg/max/mdev = 0.152/0.159/0.166/0.007 ms

[2022-03-23 11:39:18] [NOTICE] successfully ping one or more of the trusted_servers "192.3.89.1"
[2022-03-23 11:39:20] [NOTICE] try to stop old primary db (host: "192.3.89.16")
[2022-03-23 11:39:20] [NOTICE] PING 192.3.89.60 (192.3.89.60) 56(84) bytes of data.

--- 192.3.89.60 ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1023ms
rtt min/avg/max/mdev = 0.423/0.575/0.728/0.152 ms

[2022-03-23 11:39:20] [WARNING] the virtual ip is already on other host, try to release it on old primary node (host: "192.3.89.16")
[2022-03-23 11:39:21] [INFO] stop database ...
[2022-03-23 11:39:21] [INFO] ES connection to host "192.3.89.16" succeeded, ready to release vip on it
[2022-03-23 11:39:23] [INFO] kill signal 9 to pid 2091799
[2022-03-23 11:39:23] [INFO] stop db done.
[2022-03-23 11:39:23] [NOTICE] old primary node (host: "192.3.89.16") does not hold the virtual ip 192.3.89.60/24 before we release it
[2022-03-23 11:39:23] [NOTICE] will acquire the virtual ip again
[2022-03-23 11:39:25] [NOTICE] PING 192.3.89.60 (192.3.89.60) 56(84) bytes of data.

--- 192.3.89.60 ping statistics ---
2 packets transmitted, 0 received, 100% packet loss, time 1001ms


[2022-03-23 11:39:25] [WARNING] ping host"192.3.89.60" failed
[2022-03-23 11:39:25] [DETAIL] average RTT value is not greater than zero
[2022-03-23 11:39:25] [INFO] loadvip result: 1, arping result: 1
[2022-03-23 11:39:25] [NOTICE] new primary node (ID: 2) acquire the virtual ip 192.3.89.60/24 success
[2022-03-23 11:39:25] [INFO] promote_command is:
  "/home/kingbase/cluster/cluster/KingbaseCluster/kingbase/bin/repmgr  standby promote -f /home/kingbase/cluster/cluster/KingbaseCluster/kingbase/etc/repmgr.conf"
NOTICE: promoting standby to primary
DETAIL: promoting server "node17" (ID: 2) using sys_promote()
NOTICE: waiting up to 60 seconds (parameter "promote_check_timeout") for promotion to complete
NOTICE: STANDBY PROMOTE successful
DETAIL: server "node17" (ID: 2) was successfully promoted to primary
 

三、案例分析

1）AccessExclusiveLock 鎖，一般是因為執行了以下操作（DDL）產生

2）PQping()函式
repmgr備庫對主庫狀態的監控是通過PQping()函式，PQping()函式是libpq介面下的函式：libpq庫是PostgreSQL的C介面。它是一組庫函式，允許客戶端程式與PostgreSQL互動。簡單地說，Libpq 可做三件事：與資料庫建立連線、傳送 操作資料庫的語句並處理結果。

3) 主備切換分析
主備之間通過libpq介面的PQping()函式做心跳測試，由於主庫產生鎖衝突，導致訪問主庫的會話堆積，致使備庫連線主庫PQping()失敗，在超過閾值（10次）後，發生主備切換。

4）確定現場業務操作

四、總結

本次主備切換可以判斷為，客戶在業務高峰期，執行DDL操作，主庫大量的鎖衝突，會話阻塞，導致主備之間心跳通訊測試失敗而引起。在生產環境業務高峰期間，應禁止執行DDL等操作，應該安排在業務低峰期間執行。