Re: atrocious update performance

while you weren't looking, Tom Lane wrote:

> What's not immediately evident is whether the excess I/O accounted for
> all of the slowdown. Could you retry the strace with -r and -T options
> so we can see how much time is being spent inside and outside the
> syscalls?

Unlike the previous run (this is a trace of the explain), this one went
immediately. No delay.

I also have, per Aaron's request, a trace -ct against the backend running
the explain analyze. I killed it well before "a few minutes"; it's just
shy of 900K. I don't think I'll be forwarding that on to the list, though
I can put it up on a web server somewhere easily enough.

Try <http://www.totalcardinc.com/pg/postmaster.trace>.

# `strace -rT -p 25075`
0.000000 read(0, "\r", 1) = 1 <5.514983>
5.516215 write(1, "\n", 1) = 1 <0.000034>
0.000545 rt_sigprocmask(SIG_BLOCK, [INT], [33], 8) = 0 <0.000013>
0.000200 ioctl(0, SNDCTL_TMR_STOP, {B38400 opost isig icanon echo ...})
= 0
<0.000032>
0.000162 rt_sigprocmask(SIG_SETMASK, [33], NULL, 8) = 0 <0.000013>
0.000120 rt_sigaction(SIGINT, {0x804d404, [], SA_RESTORER|SA_RESTART,
0x420
276f8}, {0x401ec910, [], SA_RESTORER, 0x420276f8}, 8) = 0 <0.000015>
0.000154 rt_sigaction(SIGTERM, {SIG_DFL}, {0x401ec910, [], SA_RESTORER,
0x4
20276f8}, 8) = 0 <0.000014>
0.000136 rt_sigaction(SIGQUIT, {SIG_DFL}, {0x401ec910, [], SA_RESTORER,
0x4
20276f8}, 8) = 0 <0.000013>
0.000134 rt_sigaction(SIGALRM, {SIG_DFL}, {0x401ec910, [], SA_RESTORER,
0x4
20276f8}, 8) = 0 <0.000012>
0.000164 rt_sigaction(SIGTSTP, {SIG_DFL}, {0x401ec910, [], SA_RESTORER,
0x4
20276f8}, 8) = 0 <0.000013>
0.000140 rt_sigaction(SIGTTOU, {SIG_DFL}, {0x401ec910, [], SA_RESTORER,
0x4
20276f8}, 8) = 0 <0.000013>
0.000135 rt_sigaction(SIGTTIN, {SIG_DFL}, {0x401ec910, [], SA_RESTORER,
0x4
20276f8}, 8) = 0 <0.000013>
0.000135 rt_sigaction(SIGWINCH, {SIG_DFL}, {0x401ec9d0, [],
SA_RESTORER, 0x
420276f8}, 8) = 0 <0.000014>
0.000250 rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0 <0.000013>
0.000138 send(3, "Q\0\0\0}explain update account.cust"..., 126, 0) =
126 <0
.000032>
0.000164 rt_sigaction(SIGPIPE, {SIG_DFL}, {SIG_IGN}, 8) = 0 <0.000013>
0.000132 poll([{fd=3, events=POLLIN|POLLERR, revents=POLLIN}], 1, -1) =
1 <
0.222093>
0.222388 recv(3, "T\0\0\0#\0\1QUERY
PLAN\0\0\0\0\0\0\0\0\0\0\31\377\377\377
"..., 16384, 0) = 394 <0.000031>
0.000360 ioctl(0, SNDCTL_TMR_TIMEBASE, {B38400 opost isig icanon echo
...})
= 0 <0.000019>
0.000137 ioctl(1, SNDCTL_TMR_TIMEBASE, {B38400 opost isig icanon echo
...})
= 0 <0.000013>
0.000135 ioctl(1, TIOCGWINSZ, {ws_row=64, ws_col=80, ws_xpixel=0,
ws_ypixel
=0}) = 0 <0.000015>
0.000175 write(1, " "..., 92) = 92
<0.000038
>
0.000184 write(1, "--------------------------------"..., 92) = 92
<0.000025
>
0.000154 write(1, " Merge Join (cost=0.00..232764."..., 59) = 59
<0.000023
>
0.000136 write(1, " Merge Cond: ((\"outer\".origid)"..., 65) = 65
<0.0000
23>
0.000134 write(1, " -> Index Scan using ix_origi"..., 88) = 88
<0.000025
>
0.000129 write(1, " -> Index Scan using ix_debti"..., 91) = 91
<0.000025
>
0.000136 write(1, "(4 rows)\n", 9) = 9 <0.000022>
0.000116 write(1, "\n", 1) = 1 <0.000021>
0.000144 rt_sigprocmask(SIG_BLOCK, NULL, [33], 8) = 0 <0.000013>
0.000121 rt_sigaction(SIGINT, {0x804d404, [], SA_RESTORER|SA_RESTART,
0x420
276f8}, {0x804d404, [], SA_RESTORER|SA_RESTART, 0x420276f8}, 8) = 0
<0.000015>
0.000208 rt_sigprocmask(SIG_BLOCK, [INT], [33], 8) = 0 <0.000013>
0.000129 ioctl(0, TIOCGWINSZ, {ws_row=64, ws_col=80, ws_xpixel=0,
ws_ypixel
=0}) = 0 <0.000013>
0.000102 ioctl(0, TIOCSWINSZ, {ws_row=64, ws_col=80, ws_xpixel=0,
ws_ypixel
=0}) = 0 <0.000014>
0.000105 ioctl(0, SNDCTL_TMR_TIMEBASE, {B38400 opost isig icanon echo
...})
= 0 <0.000013>
0.000127 ioctl(0, SNDCTL_TMR_STOP, {B38400 opost isig -icanon -echo
...}) =
0 <0.000028>
0.000147 rt_sigprocmask(SIG_SETMASK, [33], NULL, 8) = 0 <0.000012>
0.000114 rt_sigaction(SIGINT, {0x401ec910, [], SA_RESTORER,
0x420276f8}, {0
x804d404, [], SA_RESTORER|SA_RESTART, 0x420276f8}, 8) = 0 <0.000012>
0.000149 rt_sigaction(SIGTERM, {0x401ec910, [], SA_RESTORER,
0x420276f8}, {
SIG_DFL}, 8) = 0 <0.000013>
0.000136 rt_sigaction(SIGQUIT, {0x401ec910, [], SA_RESTORER,
0x420276f8}, {
SIG_DFL}, 8) = 0 <0.000012>
0.000136 rt_sigaction(SIGALRM, {0x401ec910, [], SA_RESTORER,
0x420276f8}, {
SIG_DFL}, 8) = 0 <0.000012>
0.000136 rt_sigaction(SIGTSTP, {0x401ec910, [], SA_RESTORER,
0x420276f8}, {
SIG_DFL}, 8) = 0 <0.000013>
0.000136 rt_sigaction(SIGTTOU, {0x401ec910, [], SA_RESTORER,
0x420276f8}, {
SIG_DFL}, 8) = 0 <0.000012>
0.000136 rt_sigaction(SIGTTIN, {0x401ec910, [], SA_RESTORER,
0x420276f8}, {
SIG_DFL}, 8) = 0 <0.000013>
0.000212 rt_sigaction(SIGWINCH, {0x401ec9d0, [], SA_RESTORER,
0x420276f8},
{SIG_DFL}, 8) = 0 <0.000012>
0.000188 write(1, "\r\rtci=# \rtci=# ", 15) = 15 <0.000019>
0.000112 rt_sigprocmask(SIG_BLOCK, NULL, [33], 8) = 0 <0.000012>
0.000110 read(0, "\\", 1) = 1 <18.366895>
18.368284 write(1, "\rtci=# \\\rtci=# \\", 16) = 16 <0.000029>
0.000134 rt_sigprocmask(SIG_BLOCK, NULL, [33], 8) = 0 <0.000013>
0.000125 read(0, "q", 1) = 1 <0.117572>
0.117719 write(1, "\rtci=# \\q\rtci=# \\q", 18) = 18 <0.000020>
0.000118 rt_sigprocmask(SIG_BLOCK, NULL, [33], 8) = 0 <0.000012>
0.000107 read(0, "\r", 1) = 1 <1.767409>
1.767604 write(1, "\n", 1) = 1 <0.000032>
0.000140 rt_sigprocmask(SIG_BLOCK, [INT], [33], 8) = 0 <0.000013>
0.000138 ioctl(0, SNDCTL_TMR_STOP, {B38400 opost isig icanon echo ...})
= 0
<0.000030>
0.000143 rt_sigprocmask(SIG_SETMASK, [33], NULL, 8) = 0 <0.000013>
0.000111 rt_sigaction(SIGINT, {0x804d404, [], SA_RESTORER|SA_RESTART,
0x420
276f8}, {0x401ec910, [], SA_RESTORER, 0x420276f8}, 8) = 0 <0.000014>
0.000153 rt_sigaction(SIGTERM, {SIG_DFL}, {0x401ec910, [], SA_RESTORER,
0x4
20276f8}, 8) = 0 <0.000013>
0.000134 rt_sigaction(SIGQUIT, {SIG_DFL}, {0x401ec910, [], SA_RESTORER,
0x4
20276f8}, 8) = 0 <0.000013>
0.000134 rt_sigaction(SIGALRM, {SIG_DFL}, {0x401ec910, [], SA_RESTORER,
0x4
20276f8}, 8) = 0 <0.000013>
0.000133 rt_sigaction(SIGTSTP, {SIG_DFL}, {0x401ec910, [], SA_RESTORER,
0x4
20276f8}, 8) = 0 <0.000013>
0.000134 rt_sigaction(SIGTTOU, {SIG_DFL}, {0x401ec910, [], SA_RESTORER,
0x4
20276f8}, 8) = 0 <0.000013>
0.000134 rt_sigaction(SIGTTIN, {SIG_DFL}, {0x401ec910, [], SA_RESTORER,
0x4
20276f8}, 8) = 0 <0.000012>
0.000134 rt_sigaction(SIGWINCH, {SIG_DFL}, {0x401ec9d0, [],
SA_RESTORER, 0x
420276f8}, 8) = 0 <0.000014>
0.001271 rt_sigaction(SIGINT, {SIG_DFL}, {0x804d404, [],
SA_RESTORER|SA_RES
TART, 0x420276f8}, 8) = 0 <0.000013>
0.000532 rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0 <0.000014>
0.000145 send(3, "X\0\0\0\4", 5, 0) = 5 <0.000028>
0.000126 rt_sigaction(SIGPIPE, {SIG_DFL}, {SIG_IGN}, 8) = 0 <0.000013>
0.000140 close(3) = 0 <0.000033>
0.000147 rt_sigaction(SIGPIPE, {SIG_DFL}, {SIG_DFL}, 8) = 0 <0.000013>
0.000197 open("/var/lib/pgsql/.psql_history", O_WRONLY|O_CREAT|O_TRUNC,
060
0) = 3 <0.000168>
0.000694 write(3, "\\d payment.batch\nalter sequence "..., 16712) =
16712 <
0.000209>
0.000311 close(3) = 0 <0.000057>
0.055587 munmap(0x40030000, 4096) = 0 <0.000032>
0.000130 exit_group(0) = ?

/rls

--
Rosser Schwarz
Total Card, Inc.