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日志分析和日志监视系统。