专注,勤学,慎思。戒骄戒躁,谦虚谨慎

just do it

导航

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

posted on 2020-08-05 13:43  MSSQL123  阅读(1123)  评论(0编辑  收藏  举报