postgresql - 没有错误，无限加载 : where should I search?

Question

这是上下文，今天刚发生:

• Ubuntu 16.04，PostgreSQL 9.5
• 查询任何使用 PostgreSQL 的页面时无限加载(无消息)
• 使用 psql 运行任何查询时无限负载(无消息)
• /var/log/postgresql/postgresql-9.5-main.log 中没有特别的内容>
• /var/log/syslog 中没有特别的内容
• 服务器负载正常(每个处理器约 1%，内存几乎未使用，磁盘空间正常)

然后，运行 sudo service postgresql restart 后一切正常。

这种情况应该去哪里找呢？这是一个“普遍”的问题吗？没有日志，我不知道该怎么办。我如何才能相对“确定”它不会再随机发生？

旁注:这是我重新启动后 postgreSQL 日志的详细信息:

2017-03-16 12:20:52 CET [857-2] LOG:  received fast shutdown request
2017-03-16 12:20:52 CET [857-3] LOG:  aborting any active transactions
2017-03-16 12:20:52 CET [6829-1] XXXXX@YYYY FATAL:  terminating connection due to administrator command at character 15
2017-03-16 12:20:52 CET [6829-2] XXXXX@YYYY STATEMENT:  select * from "users" where "users"."id" = $1 and "users"."deleted_at" is null limit 1
2017-03-16 12:20:52 CET [6644-1] XXXXX@YYYY FATAL:  terminating connection due to administrator command at character 15
2017-03-16 12:20:52 CET [6644-2] XXXXX@YYYY STATEMENT:  select * from "users" where "users"."id" = $1 and "users"."deleted_at" is null limit 1
2017-03-16 12:20:52 CET [6649-1] XXXXX@YYYY FATAL:  terminating connection due to administrator command at character 15
2017-03-16 12:20:52 CET [6649-2] XXXXX@YYYY STATEMENT:  select * from "users" where "users"."id" = $1 and "users"."deleted_at" is null limit 1
2017-03-16 12:20:52 CET [6580-1] XXXXX@YYYY FATAL:  terminating connection due to administrator command at character 15
2017-03-16 12:20:52 CET [6580-2] XXXXX@YYYY STATEMENT:  select * from "users" where "users"."id" = $1 and "users"."deleted_at" is null limit 1
2017-03-16 12:20:52 CET [6768-1] XXXXX@YYYY FATAL:  terminating connection due to administrator command at character 15
2017-03-16 12:20:52 CET [6768-2] XXXXX@YYYY STATEMENT:  select * from "users" where "email" = $1 and "users"."deleted_at" is null limit 1
2017-03-16 12:20:52 CET [6253-1] XXXXX@YYYY FATAL:  terminating connection due to administrator command
2017-03-16 12:20:52 CET [6253-2] XXXXX@YYYY STATEMENT:  alter table "users" add column "email_confirmed" boolean not null default '1'
2017-03-16 12:20:52 CET [8465-1] XXXXX@YYYY FATAL:  terminating connection due to administrator command
2017-03-16 12:20:52 CET [913-2] LOG:  autovacuum launcher shutting down
2017-03-16 12:20:52 CET [6586-1] XXXXX@YYYY FATAL:  terminating connection due to administrator command at character 15
2017-03-16 12:20:52 CET [6586-2] XXXXX@YYYY STATEMENT:  select * from "users" where "users"."id" = $1 and "users"."deleted_at" is null limit 1
2017-03-16 12:20:52 CET [31969-1] XXXXX@YYYY FATAL:  terminating connection due to administrator command
2017-03-16 12:20:52 CET [6300-1] XXXXX@YYYY FATAL:  terminating connection due to administrator command
2017-03-16 12:20:52 CET [6974-1] XXXXX@YYYY FATAL:  the database system is shutting down
2017-03-16 12:20:52 CET [906-1] LOG:  shutting down
2017-03-16 12:20:52 CET [6980-1] XXXXX@YYYY FATAL:  the database system is shutting down
2017-03-16 12:20:52 CET [6978-1] XXXXX@YYYY FATAL:  the database system is shutting down
2017-03-16 12:20:52 CET [6975-1] XXXXX@YYYY FATAL:  the database system is shutting down
2017-03-16 12:20:52 CET [6977-1] XXXXX@YYYY FATAL:  the database system is shutting down
2017-03-16 12:20:52 CET [6976-1] XXXXX@YYYY FATAL:  the database system is shutting down
2017-03-16 12:20:52 CET [6983-1] XXXXX@YYYY FATAL:  the database system is shutting down
2017-03-16 12:20:52 CET [6979-1] XXXXX@YYYY FATAL:  the database system is shutting down
2017-03-16 12:20:52 CET [6982-1] XXXXX@YYYY FATAL:  the database system is shutting down
2017-03-16 12:20:52 CET [6981-1] XXXXX@YYYY FATAL:  the database system is shutting down
2017-03-16 12:20:52 CET [6985-1] XXXXX@YYYY FATAL:  the database system is shutting down
2017-03-16 12:20:52 CET [6984-1] XXXXX@YYYY FATAL:  the database system is shutting down
2017-03-16 12:20:52 CET [906-2] LOG:  database system is shut down
2017-03-16 12:20:53 CET [7002-1] LOG:  database system was shut down at 2017-03-16 12:20:52 CET 

Answer 1

这是导致您遇到问题的语句:

alter table "users" add column "email_confirmed" boolean not null default '1'

这样的 ALTER TABLE 需要表上的 ACCESS EXCLUSIVE 锁，这甚至与读访问冲突。

现在表 users 似乎是一个繁忙的表，这通常是没有问题的(除非两个事务试图写入同一行)因为它们需要的表锁不会相互冲突.

现在出现了 ALTER TABLE 并且必须等到表上的所有早期事务(至少持有表上的 ACCESS SHARE 锁)完成。 在 ALTER TABLE 之后开始的对表的所有查询都必须在它后面排队，因为它们需要的锁与 ALTER TABLE 的锁冲突> 需要。

一旦 ALTER TABLE 获得了它的 ACCESS EXCLUSIVE 锁，它应该很快完成，一切都会恢复正常。

现在剩下一个谜题了:日志中所有其他中断的查询看起来都是很短的查询，所以您为什么要等那么久并不明显——它们应该在几微秒内完成。

为了解释这一点，请记住锁不会在查询完成时释放，而是一直持有到事务结束。因此，如果您在一个事务中运行一个简短的查询，然后让该事务保持打开状态，这个空闲的数据库 session 将也阻塞ALTER TABLE。在正常情况下您可能不会注意到，特别是如果所有事务都是只读的，但在这种情况下它会被证明是有害的。

顺便说一句，保持开放的事务还有其他负面影响，特别是 VACUUM 无法完成它的工作，并且您的表和索引会变得臃肿。

您可以通过从 pg_stat_activity 系统 View 检查 state 来检查您的应用程序是否存在该问题。如果您经常看到 idle in transaction 的 session 并保持这种状态一段时间，那么您正在寻找问题的根本原因。这应该是固定的!

您也可以中断 ALTER TABLE 语句，而不是重新启动服务器。

如果您再次遇到此类问题，请查询pg_locks 系统 View 。您会看到运行 ALTER TABLE 的 session 有一个 granted = FALSE 的锁，因为它正在等待表锁。您还可以查看哪些其他 session 持有该表的锁。