7
我们在postgres日志和高I/O等待时间中观察到很长的COMMIT时间。 Postgres的版本的PostgreSQL 9.1.14在x86_64未知-Linux的GNU，与gcc（Ubuntu的/ Linaro的4.6.3-1ubuntu5）4.6.3，编译64位长的COMMIT持续时间，postgres中的高I/O等待9.1
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。 同步提交已打开。 PostgreSQL正在使用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输出可用。
任何其他指针非常感谢。 谢谢！
IOPS
您能否为我看看更多的东西 - 首先，如果数据库位于RDS-AWS中，您是否可以查看其监控，并查看是否有任何与慢提交相关的事情。 RDS为您提供了一个为期两周的窗口，让您回顾以前的时光。如果它不是AWS，那么您的本地监测会说什么？其次，在每个小时的第一分钟，似乎发生了什么？其他人是否有可能每小时打你的DB？如果它不是一个关键任务，有没有办法让我们用一些虚拟数据来测试你的假设？第三 - 如果你的日志来自旧... –
第三 - 如果你的日志来自过去的日子还没有旋转，我们可以比较它们与新的日志，看看是否有任何东西弹出。第四，你是否有机会获得快照，预优化，以便将其放到测试服务器上，以查看奇怪行为是否与重新包装有关？非常感谢。 –