2021年8月3日 星期二

Logical Replication replication slot "XXX" is active for PID XXX 發生原因與解決方法

在 Postgres 資料一般使用 Streaming Replication 用來同步 Standby 的,此方法為整個資料庫 Instance 進行同步,藉由傳送資料庫日誌檔案 WAL 來進行同步,Standby 僅支援讀取功能。

而 Logical Replication 為 Postgres 資料庫表層級的同步機制,為 Primary 對 Primary 進行資料同步,從 PGSQL 10 開始引進,並持續在後續版本中有進行改善。

Logical Replication 是一個 PUB - SUB 的架構,在發布端(PUB)會將 WAL 資訊進行解碼,再透過 text 或是 binary(PG14) 的方式同步資料過去訂閱端(SUB),而在發布端會有一個 Logical Replication slot 用來記錄目前同步的 WAL 位置,此處必須要注意到,Logical Replication slot 會導致還沒有進行同步的 WAL 無法被 Archive 歸檔,如果同步有狀況有可能導致 pg_wal 目錄持續累積 WAL 檔案,最後造成空間不足資料庫掛掉。

在 PGSQl 13 版引進了新的設定 max_slot_wal_keep_size ,此設定可以指定最多為 Logical Replication 所保留的 WAL 檔案大小,藉由此設定來避免PUB端空間不足,雖然此設定有可能會導致須整個重建 Logical Replication ,但對於 PUB端的保護還是很重要的,因此不建議關閉此設定,而 PG13 以前的版本若使用 Logical Replication 由於缺乏保護機制,必須定期檢查確保同步正常。

下面討論一種會導致資料庫 Logical Replication 同步異常的狀況。

Logical Replication 會在 PUB 端透過一個 wal_sender 的程序進行 Logical Decoding 解碼,並將解碼出來的資訊傳送至 SUB 端,而在進行 Decoding 過程中,必須要將 WAL 資訊完整掃過,因此,此處要了解到,不論被發布的表格是某異動與否,只要資料庫本生有在進行交易產生 WAL,wal_sender 就必須做對應的檢視擷取資訊,因此有可能會發生一種比較特殊的狀況,網路連線都正常,Publication Table 也沒有異動,但是卻發生 wal_sender 或是 wal_receiver 發生 timeout 的狀況。

本處是用 EPAS 11 做測試,此情境適在目前各大版本都可能會發生,當網路出狀況的時候,抑或著事有大量 WAL 資料寫入造成 wal_sender 在進行 Logical Deconding 時需耗費大量時間以致於 SUB 端發生 timeout 的情況。

下面是在測試環境設定 wal_receiver_timeout = 2s 的極端狀況來進行測試。

以下為 SUB 端的 LOG

2021-07-19 18:16:37 CST LOG:  logical replication apply worker for subscription "subt" has started
2021-07-19 18:16:44 CST ERROR:  terminating logical replication worker due to timeout
2021-07-19 18:16:44 CST LOG:  background worker "logical replication worker" (PID 4886) exited with exit code 1
2021-07-19 18:16:44 CST LOG:  logical replication apply worker for subscription "subt" has started
2021-07-19 18:16:44 CST ERROR:  could not start WAL streaming: ERROR:  replication slot "subt" is active for PID 4887
2021-07-19 18:16:44 CST LOG:  background worker "logical replication worker" (PID 4890) exited with exit code 1

以下為 PUB 端的 LOG

2021-07-19 18:16:37 CST user=enterprisedb PID=4887 DEBUG:  received replication command: IDENTIFY_SYSTEM
2021-07-19 18:16:37 CST user=enterprisedb PID=4887 DEBUG:  received replication command: START_REPLICATION SLOT "subt" LOGICAL 0/55BAB328 (proto_version '1', publication_names '"pubt"')
2021-07-19 18:16:37 CST user=enterprisedb PID=4887 DEBUG:  cannot stream from 0/55BAB328, minimum is 0/64ABA4D8, forwarding
2021-07-19 18:16:37 CST user=enterprisedb PID=4887 LOG:  starting logical decoding for slot "subt"
2021-07-19 18:16:37 CST user=enterprisedb PID=4887 DETAIL:  Streaming transactions committing after 0/64ABA4D8, reading WAL from 0/55BA6D10.
2021-07-19 18:16:37 CST user=enterprisedb PID=4887 LOG:  logical decoding found consistent point at 0/55BA6D10
2021-07-19 18:16:37 CST user=enterprisedb PID=4887 DETAIL:  There are no running transactions.
2021-07-19 18:16:44 CST user=enterprisedb PID=4891 DEBUG:  received replication command: IDENTIFY_SYSTEM
2021-07-19 18:16:44 CST user=enterprisedb PID=4891 DEBUG:  received replication command: START_REPLICATION SLOT "subt" LOGICAL 0/55BAB328 (proto_version '1', publication_names '"pubt"')
2021-07-19 18:16:44 CST user=enterprisedb PID=4891 ERROR:  replication slot "subt" is active for PID 4887

在上面的 Log 資訊我們可以觀察到以下資訊

1. 首先 Sub 端的 Logical Replication 發生 timeout 此時 Pub 端的 wal_sender 並不知情,仍持續進行解碼運作並且占用 Replication slots。

2. Sub 端嘗試重新建立 Replication 但發現 Replication slot (一次只能一個 Process 使用)還被占用無法建立因此失敗報錯( replication slot "XXX" is active for PID XXX ),並且持續重新嘗試。

3. Pub 端處理完解碼要傳送資料回 Sub端,但是發現原本 Sub 端的 Process 已經連不到了,因此結束程序,

4. 在前一步驟將 Replication Slot 釋放出來了,Sub 端成功連上 Pub 端建立同步,但是又因為等待太久發生 timeout。

5. 進入前面 1 - 4 步驟的循環。

上面的 Log 訊息有經過調整顯示詳細程度還有內容,而在一般環境下由於上面的 timeout 情境,我們會在 Pub 端不斷看到  replication slot "XXX" is active for PID XXX 的訊息。

此訊息發生代表著兩邊一直沒有成功建立同步,而會使 Replication slot 所記錄的位置無法推進,因此造成 wal 檔案持續累積在 pg_wal 目錄中。

處理方法很簡單,只需要調整 Pub/Sub 端的設定,wal_sender_timeout 與 wal_receiver_timeout 數值,預設為兩分鐘,視情況可以調整至 5~10分鐘,就可恢復正常同步。


參考連結:

https://dba.stackexchange.com/questions/262444/could-not-start-wal-streaming-replication-slot-is-active?answertab=active#tab-top