( i sent this mail yesterday, but it vanished, this time, I'm making it
smaller by extracting some info and putting it on webserver, maybe it
will be accepted this time )
hi
i have 9.1.4 pg on linux on ext3 system with dedicated disks. xlogs are
on different disks than data directory.
every so often, especially when IO is higher due to more writes, I have
strange situation - IO seems to stop, and a lot of postgres processes in
ps output are in "semtimedop" state - including, but not limiting to
- writer process and wal writer process.
I have some logging enabled, and this I found interesting:
2012-08-15 05:09:17 UTC [] [30306]: [344763-1] user=,db= LOG: checkpoint starting: time
2012-08-15 05:09:47 UTC [] [30306]: [344764-1] user=,db= LOG: checkpoint complete: wrote 96676 buffers (0.7%); 0
transactionlog file(s) added, 0 removed, 36 recycled; write=28.492 s, sync=1.186 s, total=30.033 s; sync files=517,
longest=0.572s, average=0.002 s
2012-08-15 05:09:47 UTC [] [30306]: [344765-1] user=,db= LOG: checkpoint starting: time
2012-08-15 05:10:37 UTC [] [30306]: [344766-1] user=,db= LOG: checkpoint complete: wrote 85017 buffers (0.6%); 0
transactionlog file(s) added, 0 removed, 35 recycled; write=40.953 s, sync=8.812 s, total=50.219 s; sync files=492,
longest=8.238s, average=0.017 s
2012-08-15 05:10:37 UTC [] [30306]: [344767-1] user=,db= LOG: checkpoint starting: time
2012-08-15 05:11:04 UTC [] [30306]: [344768-1] user=,db= LOG: checkpoint complete: wrote 29349 buffers (0.2%); 0
transactionlog file(s) added, 0 removed, 30 recycled; write=26.377 s, sync=0.274 s, total=26.711 s; sync files=561,
longest=0.034s, average=0.000 s
2012-08-15 05:11:07 UTC [] [30306]: [344769-1] user=,db= LOG: checkpoint starting: time
2012-08-15 05:11:35 UTC [] [30306]: [344770-1] user=,db= LOG: checkpoint complete: wrote 104768 buffers (0.8%); 0
transactionlog file(s) added, 0 removed, 10 recycled; write=26.997 s, sync=0.921 s, total=27.928 s; sync files=526,
longest=0.192s, average=0.001 s
please note times of write and sync for the checkpoitn started at 05:09:47!
in the same time, write traffic to data directory disks basically stops:
when Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm
%util
2012-08-15 05:09:03 UTC cciss/c0d0 0.00 2556.40 226.20 4883.20 1850.40 29758.40 12.37 16.79 3.28
0.17 86.48
2012-08-15 05:09:08 UTC cciss/c0d0 0.20 2816.00 277.20 4594.20 2272.80 29640.80 13.10 15.52 3.19
0.18 88.78
2012-08-15 05:09:13 UTC cciss/c0d0 1.60 2823.80 346.60 4446.60 2854.40 29081.60 13.33 15.99 3.34
0.18 88.46
2012-08-15 05:09:18 UTC cciss/c0d0 0.20 1180.20 272.40 1972.40 2225.60 12610.40 13.22 7.34 3.27
0.37 83.34
2012-08-15 05:09:22 UTC cciss/c0d0 0.60 2443.40 273.00 4713.80 2272.80 28629.60 12.39 15.87 3.18
0.15 74.66
2012-08-15 05:09:27 UTC cciss/c0d0 0.40 2511.60 229.40 4877.00 1902.40 29555.20 12.32 16.20 3.17
0.16 81.92
2012-08-15 05:09:32 UTC cciss/c0d0 2.00 1625.00 369.60 2991.80 3000.80 18468.80 12.77 11.26 3.35
0.29 97.08
2012-08-15 05:09:37 UTC cciss/c0d0 1.20 770.80 352.60 1408.00 2839.20 8715.20 13.13 5.80 3.29
0.50 88.58
2012-08-15 05:09:43 UTC cciss/c0d0 0.60 3649.50 427.54 5837.13 3425.15 37946.51 13.21 19.66 3.14
0.15 93.63
2012-08-15 05:09:48 UTC cciss/c0d0 0.60 3267.20 291.40 5251.60 2406.40 34076.00 13.16 18.69 3.37
0.17 96.72
2012-08-15 05:09:52 UTC cciss/c0d0 0.60 433.20 284.40 774.60 2317.60 4831.20 13.50 3.55 3.35
0.77 81.06
2012-08-15 05:10:05 UTC cciss/c0d0 0.20 0.00 138.40 0.00 1112.00 0.00 16.07 0.63 4.60 3.35
46.38
2012-08-15 05:10:05 UTC cciss/c0d0 0.60 3.00 173.00 1.00 1394.40 16.00 16.21 0.69 3.97 2.90
50.38
2012-08-15 05:10:08 UTC cciss/c0d0 0.00 12.00 224.80 1.40 1800.00 53.60 16.39 0.92 4.07 2.63
59.60
2012-08-15 05:10:12 UTC cciss/c0d0 0.60 2.80 150.00 1.00 1233.60 15.20 16.54 0.61 4.06 2.95
44.52
2012-08-15 05:10:17 UTC cciss/c0d0 0.60 20.00 198.40 15.00 1592.80 140.00 16.24 0.82 3.84 2.63
56.14
2012-08-15 05:10:23 UTC cciss/c0d0 0.40 13.37 162.48 3.19 1314.17 66.27 16.67 0.71 4.30 3.18
52.69
2012-08-15 05:10:28 UTC cciss/c0d0 0.40 0.40 286.60 3.80 2321.60 16.80 16.10 1.08 3.72 2.08
60.48
2012-08-15 05:10:32 UTC cciss/c0d0 0.40 7465.40 292.00 14183.80 2367.20 86532.00 12.28 137.31 9.46
0.07 97.16
2012-08-15 05:10:38 UTC cciss/c0d0 1.00 4164.20 291.40 7299.20 2356.80 45919.20 12.72 106.13 14.03
0.13100.00
2012-08-15 05:10:42 UTC cciss/c0d0 2.80 900.00 305.20 1658.20 2520.80 10232.80 12.99 6.13 3.12
0.43 83.86
2012-08-15 05:10:48 UTC cciss/c0d0 0.40 798.00 291.00 1493.00 2428.00 9164.00 13.00 5.60 3.14
0.44 78.32
2012-08-15 05:10:53 UTC cciss/c0d0 1.40 810.40 320.40 1469.80 2688.80 9120.80 13.19 5.53 3.09
0.46 83.00
2012-08-15 05:10:58 UTC cciss/c0d0 0.80 885.00 321.80 1491.00 2728.80 9504.80 13.50 5.58 3.08
0.44 80.48
every 30 seconds, I log output of "ps axo
user,pid,ppid,pgrp,%cpu,%mem,rss,lstart,nice,nlwp,sgi_p,cputime,tty,wchan:25,args"
and, while I can't show too much information, postgres processes look
like this:
( copy of ps output is on http://depesz.com/various/ps.output.txt )
so, as you can see these are not new backends - have been running for
some time already. but all of them somehow end up in semtimedop - even
selects (no, these are not writing select - just plain select fields
from table where some_condition).
any ideas? any questions I might answer to give you better chance of
helping me?
one more information - we are using pgbouncer, and today i modified the
config so that always at least 200 connections are there (we usually use
~ 20) - this made the spikes of connections disappear, and everything
seems to be sailing much more smoothly.
not sure if it helps in diagnosing.
Best regards,
depesz
--
The best thing about modern society is how easy it is to avoid contact with it.
http://depesz.com/
