Postgres 日志監控：阻塞，死鎖，Checkpoint 優化（譯）

原文地址： https://pganalyze.com/blog/postgresql-log-monitoring-101-deadlocks-checkpoints-blocked-queries

 

部分運維PostgreSQL數據庫的人通常有很多工作要做，並且沒有足夠的時間來定期查看Postgres日志文件。
但是，這些日志通常包含一些關鍵細節，這些細節涉及新的應用程序代碼如何由於鎖定問題而影響數據庫，或者某些配置參數如何導致數據庫產生I/O瓶頸。
這篇文章重點介紹了通過查看並自動過濾Postgres日志可以發現的三個常見性能問題。

阻塞

與性能最相關的日志事件之一是block，原因是當前Session等待另一個已經被其他Session占用的（互斥）鎖。
在鎖爭用頻繁的系統上，您通常還會看到無法解釋的高CPU使用率疑問。

首先，為了啟用鎖定等待記錄，請在Postgres配置中設置 log_lock_waits = on。
如果查詢等待的時間超過deadlock_timeout（默認值為1s），則將發出類似以下的日志事件：

LOG: process 123 still waiting for ShareLock on transaction 12345678 after 1000.606 ms
STATEMENT: SELECT table WHERE id = 1 FOR UPDATE;
CONTEXT: while updating tuple (1,3) in relation “table”
DETAIL: Process holding the lock: 456. Wait queue: 123.

這些信息告訴我們，在update table的時候發生了一個鎖等待，另外一個事務鎖定了我們嘗試更新的數據行，類似阻塞在復雜事務過長地持有鎖的時候會經常發生。

在典型的Web應用程序中，一種常見的反面做法是：

Open a transaction
Update a timestamp field (e.g. updated_at in Ruby on Rails)
Make an API call to an external service
Commit the transaction

第二步中的update操作持有的鎖會一直持有到步驟4,這意味着如果API的調用要耗費幾秒鍾的話，這期間這個鎖會被一直持有。
如果系統中存在並發操作同一行數據的情況的話，你會看到步驟2會發生鎖征用的情況。
通常您必須返回具有完整查詢日志記錄的開發或staging 系統，以了解導致問題的事務的完整上下文。

死鎖

死鎖與被阻止的查詢有關，但略有不同，它們是死鎖，由於死鎖是針對另一個查詢的結果，因此導致查詢被取消。

重現死鎖的最簡單方法是執行以下操作：

--- session 1
BEGIN;
SELECT * FROM table WHERE id = 1 FOR UPDATE;
--- session 2
BEGIN;
SELECT * FROM table WHERE id = 2 FOR UPDATE;
SELECT * FROM table WHERE id = 1 FOR UPDATE; --- this will block waiting for session 1 to finish

--- session 1
SELECT * FROM table WHERE id = 2 FOR UPDATE; --- this can never finish as it deadlocks against session 2

在超出deadlock_timeout的時間之后，Postgresql會看到鎖的問題。

在deadlock_timeout之后，Postgres將再次看到鎖定問題。在這種情況下，死鎖雙方的等待不會有任何結果，並向日志發出以下信息：

2018-02-12 09:24:52.176 UTC [3098] ERROR:  deadlock detected
2018-02-12 09:24:52.176 UTC [3098] DETAIL:  Process 3098 waits for ShareLock on transaction 219201; blocked by process 3099.
    Process 3099 waits for ShareLock on transaction 219200; blocked by process 3098.
    Process 3098: SELECT * FROM table WHERE id = 2 FOR UPDATE;
    Process 3099: SELECT * FROM table WHERE id = 1 FOR UPDATE;
2018-02-12 09:24:52.176 UTC [3098] HINT:  See server log for query details.
2018-02-12 09:24:52.176 UTC [3098] CONTEXT:  while locking tuple (0,1) in relation "table"
2018-02-12 09:24:52.176 UTC [3098] STATEMENT:  SELECT * FROM table WHERE id = 2 FOR UPDATE;

您可能會認為死鎖永遠不會在生產中發生，但是不幸的事實是，大量使用ORM框架可以隱藏產生死鎖的循環依賴情況，當您使用復雜的事務時，一定要提防這一問題。

Checkpoints

最后但同樣重要的是checkpoint。對於那些不熟悉的人來說，檢查點是PostgreSQL保存緩存中的更改到數據文件持久化機制，以前這些更改只存在於共享緩沖區和WAL中。

它在一個地方(數據目錄)為您提供了數據的一致副本。
由於檢查點必須記錄數據庫緩存中的所有更改(之前已經寫入到WAL)，它們可能會產生相當多的I/O——特別是當您正在主動加載數據時。

生成檢查點的最簡單方法是調用Checkpoints，但是很少有人會在生產中經常這樣做。
相反，Postgres有一種自動觸發檢查點的機制，最常見的原因是時間或xlog(譯者注：Checkpoints會定時執行，也會因為xlog的使用率觸發)。
在打開log_checkpoints =1 之后，您可以在日志中看到如下內容:

Feb 09 08:30:07am PST 12772 LOG: checkpoint starting: time
Feb 09 08:15:50am PST 12772 LOG: checkpoint starting: xlog
Feb 09 08:10:39am PST 12772 LOG: checkpoint starting: xlog

或者時間維度的可視化來看，類似如下

有時Postgres也會輸出以下警告，提示您可以進行調整：

Feb 09 10:21:11am PST 5677 LOG: checkpoints are occurring too frequently (17 seconds apart)

使用檢查點時，您要避免它們頻繁發生，因為每個檢查點都會產生大量的I/O，並且會導致所有寫入WAL的更改都在寫為 full-page wirite之后立即發生。

理想情況下，您會看到checkpoint會有規律地定時發生，並且通常是按時間而不是受到xlog影響的。您可以通過以下配置設置來影響此行為：

• checkpoint_timeout：checkpoint定時執行的頻率（默認為每5分鍾）

• max_wal_size：觸發xlog檢查點之前將累積的最大WAL量（默認為1 GB）

• checkpoint_completion_target：檢查點完成的速度（默認值為0.5，這意味着它將在checkpoint_timeout的一半時間（即2.5分鍾）內完成）

在許多生產系統上，我已經看到可以增加max_wal_size來支持更高的寫入速率，也可以稍微增加checkpoint_timeout來避免基於時間的檢查點過於頻繁，以及將checkpoint_completion_target設置為0.9。

但是，您應該根據自己的系統和日志對所有這些進行調整，以便可以選擇適合您的設置的內容。還要注意，檢查點的使用頻率較低，這意味着服務器恢復將需要更長的時間，因為崩潰后啟動時，Postgres必須從前一個檢查點開始重播所有WAL。

總結

Postgres日志文件包含大量有用的數據，您可以對其進行分析，以使您的系統更快地運行以及調試生產問題。該數據易於獲得，但通常很難解析。

本文試圖指出值得在生產系統上過濾日志行的方法。

如果您不想在第三方日志記錄系統中設置自己的過濾器，請嘗試使用 pganalyze Postgres Log Insights：pganalyze中內置的實時PostgreSQL日志分析和日志監視系統。