【发布时间】：2016-11-20 05:58:15
【问题描述】：
我们在 postgres 日志中观察到较长的 COMMIT 时间和较高的 I/O 等待时间。 x86_64-unknown-linux-gnu 上的 Postgres 版本 PostgreSQL 9.1.14，由 gcc (Ubuntu/Linaro 4.6.3-1ubuntu5) 4.6.3 编译，64 位
iotop 显示以下输出
TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
04:01:25 15676 be/4 postgres 0.00 B/s 0.00 B/s 0.00 % 99.99 % postgres: masked masked 10.2.21.22(37713) idle
04:01:16 15676 be/4 postgres 0.00 B/s 0.00 B/s 0.00 % 99.99 % postgres: masked masked 10.2.21.22(37713) idle
04:01:15 15675 be/4 postgres 0.00 B/s 0.00 B/s 0.00 % 99.99 % postgres: masked masked 10.2.21.22(37712) idle in transaction
04:00:51 15407 be/4 postgres 173.52 K/s 0.00 B/s 0.00 % 99.99 % postgres: masked masked 10.2.21.22(37670) idle
04:02:12 16054 be/4 postgres 0.00 B/s 0.00 B/s 0.00 % 96.63 % postgres: masked masked 10.2.21.22(37740) idle
04:04:11 16578 be/4 postgres 0.00 B/s 23.66 K/s 0.00 % 95.39 % postgres: masked masked 10.2.21.22(37793) idle
04:00:59 15570 be/4 postgres 0.00 B/s 0.00 B/s 0.00 % 85.27 % postgres: masked masked 10.2.21.22(37681) COMMIT
04:02:11 16051 be/4 postgres 0.00 B/s 0.00 B/s 0.00 % 80.07 % postgres: masked masked 10.2.21.22(37737) idle
04:01:23 15660 be/4 postgres 0.00 B/s 15.75 K/s 0.00 % 52.99 % postgres: masked masked 10.2.21.22(37693) idle
04:01:35 15658 be/4 postgres 0.00 B/s 39.42 K/s 0.00 % 39.18 % postgres: masked masked 10.2.21.22(37691) idle in transaction
04:01:59 15734 be/4 postgres 1288.75 K/s 0.00 B/s 0.00 % 30.35 % postgres: masked masked 10.2.21.22(37725) idle
04:01:02 15656 be/4 postgres 7.89 K/s 0.00 B/s 0.00 % 30.06 % postgres: masked masked 10.2.21.22(37689) idle
04:02:28 16064 be/4 postgres 1438.18 K/s 15.72 K/s 0.00 % 23.72 % postgres: masked masked 10.2.21.22(37752) SELECT
04:03:30 16338 be/4 postgres 433.52 K/s 15.76 K/s 0.00 % 22.59 % postgres: masked masked 10.2.21.22(37775) idle in transaction
04:01:43 15726 be/4 postgres 0.00 B/s 7.88 K/s 0.00 % 20.77 % postgres: masked masked 10.2.21.22(37717) idle
04:01:23 15570 be/4 postgres 0.00 B/s 15.75 K/s 0.00 % 19.81 % postgres: masked masked 10.2.21.22(37681) idle
04:02:51 16284 be/4 postgres 441.56 K/s 7.88 K/s 0.00 % 17.11 % postgres: masked masked 10.2.21.22(37761) idle
04:03:39 16343 be/4 postgres 497.22 K/s 63.14 K/s 0.00 % 13.77 % postgres: masked masked 10.2.21.22(37780) idle
04:02:40 16053 be/4 postgres 204.88 K/s 31.52 K/s 0.00 % 11.31 % postgres: masked masked 10.2.21.22(37739) BIND
04:01:13 15646 be/4 postgres 0.00 B/s 47.24 K/s 0.00 % 11.17 % postgres: masked masked 10.2.21.22(37682) BIND
04:01:13 15660 be/4 postgres 94.49 K/s 0.00 B/s 0.00 % 10.80 % postgres: masked masked 10.2.21.22(37693) COMMIT
在高峰期提交时间最长可达 60 秒。 该问题始于一周前，并且似乎发生在每小时的第一分钟。 申请没有变化。 当时没有运行可能导致此问题的批处理作业。 我们通过停止所有作业/抓取进程来消除这种情况。
我们使用 pg_repack 从 99% 的表中删除了膨胀。 缓慢的 COMMIT 操作在一个不再有膨胀的表上。
使用了 RAID10 配置。 存储是磁性 EBS。 同步提交已开启。 Postgres 正在使用 fdatasync()。 AWS 支持声称存储是健康的。
strace 显示一堆 semop 调用需要很多时间，只有一个缓慢的 fdatasync 调用。
$ egrep "<[0-9][0-9]\." t.*
t.31944:1479632446.159939 semop(6029370, {{11, -1, 0}}, 1) = 0 <15.760687>
t.32000:1479632447.872642 semop(6127677, {{0, -1, 0}}, 1) = 0 <14.095245>
t.32001:1479632444.780242 semop(6094908, {{15, -1, 0}}, 1) = 0 <17.113239>
t.32151:1479632493.655164 select(8, [3 6 7], NULL, NULL, {60, 0}) = 1 (in [3], left {46, 614240}) <14.339090>
t.32198:1479632451.200194 semop(5963832, {{7, -1, 0}}, 1) = 0 <11.095583>
t.32200:1479632445.740529 semop(6094908, {{13, -1, 0}}, 1) = 0 <16.153911>
t.32207:1479632451.329028 semop(6062139, {{7, -1, 0}}, 1) = 0 <10.970497>
t.32226:1479632446.384585 semop(6029370, {{8, -1, 0}}, 1) = 0 <15.565608>
t.32289:1479632451.044155 fdatasync(106) = 0 <10.849081>
t.32289:1479632470.284825 semop(5996601, {{14, -1, 0}}, 1) = 0 <10.686889>
t.32290:1479632444.608746 semop(5963832, {{8, -1, 0}}, 1) = 0 <17.284606>
t.32301:1479632445.757671 semop(6127677, {{8, -1, 0}}, 1) = 0 <16.137046>
t.32302:1479632445.504563 semop(6094908, {{4, -1, 0}}, 1) = 0 <16.389120>
t.32303:1479632445.889161 semop(6029370, {{6, -1, 0}}, 1) = 0 <16.005659>
t.32304:1479632446.377368 semop(6062139, {{12, -1, 0}}, 1) = 0 <15.554953>
t.32305:1479632448.269680 semop(6062139, {{14, -1, 0}}, 1) = 0 <13.717228>
t.32306:1479632450.465661 semop(5963832, {{3, -1, 0}}, 1) = 0 <11.783744>
t.32307:1479632448.959793 semop(6062139, {{8, -1, 0}}, 1) = 0 <13.289375>
t.32308:1479632446.948341 semop(6062139, {{10, -1, 0}}, 1) = 0 <15.001958>
t.32315:1479632451.534348 semop(6127677, {{12, -1, 0}}, 1) = 0 <10.765300>
t.32316:1479632450.209942 semop(6094908, {{3, -1, 0}}, 1) = 0 <12.039340>
t.32317:1479632451.032158 semop(6094908, {{7, -1, 0}}, 1) = 0 <11.217471>
t.32318:1479632451.088017 semop(5996601, {{12, -1, 0}}, 1) = 0 <11.161855>
t.32320:1479632452.161327 semop(5963832, {{14, -1, 0}}, 1) = 0 <10.138437>
t.32321:1479632451.070412 semop(5963832, {{13, -1, 0}}, 1) = 0 <11.179321>
pg_test_fsync 输出可用。
非常感谢任何其他指针。 谢谢！
【问题讨论】：
-
你能想到一周前发生了什么变化吗？版本升级、操作系统安全补丁安装等？甚至是应用程序中其他看似无关的更改。尽管您没有运行任何批处理作业，但您的数据库服务器和应用服务器中的 crontab 是否完全为空？
-
你能帮我看看更多的事情吗？首先，如果数据库在 RDS - AWS 中，你能看看它的监控，看看是否有任何东西与缓慢的提交有关。 RDS 为您提供了两周的窗口，因此您也可以回顾以前的时间。如果不是 AWS，你的本地监控是怎么说的？其次，是什么让你说它似乎发生在每小时的第一分钟？是否有可能其他人每小时都在访问您的数据库？如果它不是关键任务，我们有没有办法用一些虚拟数据来测试你的假设？第三 - 如果您的日志来自旧......
-
第三 - 如果您过去的日志没有被轮换，我们可以将它们与新日志进行比较，看看是否有任何东西弹出。第四，您是否有任何机会有一个快照、预优化，您可以将其放到测试服务器上以查看奇怪的行为是否与重新打包有关？非常感谢。
-
@LeftyGBalogh RDS 也在讨论中，但它为只读副本引入了显着滞后，我们计划使用两个不同的数据库进行读写操作，其中读写数据库之间的同步至关重要。
-
你们怎么看这个？要获得更好的数据库性能，请在 EBS 上运行主服务器和从服务器。如果我们必须停止实例，我们可以让奴隶成为主人。然后在短暂的情况下切换到 master。
标签： amazon-web-services postgresql-9.1