Postgres 日志监控：阻塞，死锁，Checkpoint 优化（译）
部分运维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日志分析和日志监视系统。目录 返回
首页