原文地址：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分鐘）內完成）
總結
Postgres日志檔案包含大量有用的資料，您可以對其進行分析，以使您的系統更快地運行以及除錯生產問題，該資料易于獲得，但通常很難決議， 本文試圖指出值得在生產系統上過濾日志行的方法， 如果您不想在第三方日志記錄系統中設定自己的過濾器，請嘗試使用pganalyze Postgres Log Insights：pganalyze中內置的實時PostgreSQL日志分析和日志監視系統，轉載請註明出處，本文鏈接：https://www.uj5u.com/shujuku/1168.html
標籤：PostgreSQL
上一篇：在 PostgreSQL 中使用碼農很忙 IP 地址資料庫
下一篇：PG虛擬檔案描述符（VFD）機制——FD LRU池一：postgresql-8.4.1/src/backend/storage/file/fd.c