Re: atrocious update performance - Mailing list pgsql-performance
| From | Rosser Schwarz |
|---|---|
| Subject | Re: atrocious update performance |
| Date | |
| Msg-id | 002a01c40c45$f736d8a0$2500fa0a@CardServices.TCI.com Whole thread Raw |
| In response to | Re: atrocious update performance (Tom Lane <tgl@sss.pgh.pa.us>) |
| Responses |
Re: atrocious update performance
(Tom Lane <tgl@sss.pgh.pa.us>)
Re: atrocious update performance (Greg Spiegelberg <gspiegelberg@cranel.com>) |
| List | pgsql-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.
pgsql-performance by date: