pg.ddx.io pgsql-performance@postgresql.org mailing list archive help / color / mirror / Atom feed From: lars <lhofhansl@yahoo.com>
To: Jeff Janes <jeff.janes@gmail.com>
Cc: Kevin Grittner <Kevin.Grittner@wicourts.gov>
Cc: Ivan Voras <ivoras@freebsd.org>
Cc: pgsql-performance@postgresql.org
Subject: Re: UPDATEDs slowing SELECTs in a fully cached database
Date: Fri, 15 Jul 2011 17:21:28 -0700
Message-ID: <4E20D988.3040007@yahoo.com> (raw )
In-Reply-To: <CAMkU=1z2oriZAv4D2hb55+PX=Q5j8dfxpaZpHhGuYic168B18A@mail.gmail.com >
References: <4E16479D.3050605@yahoo.com >
<4E1A0CBC.6090009@yahoo.com >
<4E1A31AB.9010201@postnewspapers.com.au >
<1310359653.80687.YahooMailRC@web121705.mail.ne1.yahoo.com >
<4E1AEDAB020000250003F1C3@gw.wicourts.gov >
<4E1B41EA.90104@yahoo.com >
<4E1B05CC020000250003F1E6@gw.wicourts.gov >
<CAHyXU0wPhZsQ_pMzfUWW0O=t_+2uwF-CJQNw-nuaxkjbi2zPEQ@mail.gmail.com >
<4E1B810D.4070404@yahoo.com >
<4E1B90AF.1020408@yahoo.com >
<ivho9v$6dp$1@dough.gmane.org >
<4E1C9A05.7060005@yahoo.com >
<4E1C5563020000250003F252@gw.wicourts.gov >
<4E1CA8E9.6090108@yahoo.com >
<4E1CB56E.7080801@yahoo.com >
<4E1D697C020000250003F29A@gw.wicourts.gov >
<4E1DE28D.6020207@yahoo.com >
<4E1DA0C2020000250003F2B1@gw.wicourts.gov >
<4E1E1F0C.70005@yahoo.com >
<CAMkU=1z2oriZAv4D2hb55+PX=Q5j8dfxpaZpHhGuYic168B18A@mail.gmail.com >
On 07/14/2011 04:03 PM, Jeff Janes wrote:
> On Wed, Jul 13, 2011 at 3:41 PM, lars<lhofhansl@yahoo.com> wrote:
>> On 07/13/2011 11:42 AM, Kevin Grittner wrote:
>>> So transactions without an XID *are* sensitive to
>>> synchronous_commit. That's likely a useful clue.
>>>
>>> How much did it help the run time of the SELECT which followed the
>>> UPDATE?
>> It has surprisingly little impact on the SELECT side:
> If your fsync is truly fsyncing, it seems like it should have
> considerable effect.
>
> Could you strace with both -ttt and -T, with and without synchronous commit?
>
> Cheers,
>
> Jeff
Ok, here we go:
"Q\0\0\0_select count(*) from test w"..., 8192, 0, NULL, NULL) = 96
<5.357152>
1310774187.750791 gettimeofday({1310774187, 750809}, NULL) = 0 <0.000022>
1310774187.751023 lseek(12, 0, SEEK_END) = 329908224 <0.000023>
1310774187.751109 lseek(15, 0, SEEK_END) = 396607488 <0.000022>
1310774187.751186 lseek(18, 0, SEEK_END) = 534175744 <0.000022>
1310774187.751360 lseek(12, 0, SEEK_END) = 329908224 <0.000023>
1310774187.753389 brk(0x248e000) = 0x248e000 <0.000026>
1310774187.753953 brk(0x24ce000) = 0x24ce000 <0.000023>
1310774187.755158 brk(0x254e000) = 0x254e000 <0.000024>
1310774187.766605 brk(0x2450000) = 0x2450000 <0.000170>
1310774187.766852 lseek(23, 4513792, SEEK_SET) = 4513792 <0.000023>
1310774187.766927 write(23,
"f\320\1\0\1\0\0\0\320\0\0\0\0\340D-\22\0\0\0\30@!000000000"..., 32768)
= 32768 <0.000075>
1310774187.767071 fdatasync(23) = 0 <0.002618>
1310774187.769760 gettimeofday({1310774187, 769778}, NULL) = 0 <0.000022>
1310774187.769848 sendto(5,
"\2\0\0\0\350\0\0\0\1@\0\0\2\0\0\0\1\0\0\0\0\0\0\0\r\201\0\0>\0\2\0"...,
232, 0, NULL, 0) = 232 <0.000064>
1310774187.769993 sendto(6,
"T\0\0\0\36\0\1count\0\0\0\0\0\0\0\0\0\0\24\0\10\377\377\377\377\0\0D"...,
66, 0, NULL, 0) = 66 <0.000199>
(23 is the WAL fd) vs.
"Q\0\0\0_select count(*) from test w"..., 8192, 0, NULL, NULL) = 96
<7.343720>
1310774306.978767 gettimeofday({1310774306, 978785}, NULL) = 0 <0.000021>
1310774306.978994 lseek(12, 0, SEEK_END) = 330883072 <0.000024>
1310774306.979080 lseek(15, 0, SEEK_END) = 397131776 <0.000021>
1310774306.979157 lseek(18, 0, SEEK_END) = 534732800 <0.000022>
1310774306.979332 lseek(12, 0, SEEK_END) = 330883072 <0.000022>
1310774306.983096 brk(0x248e000) = 0x248e000 <0.000026>
1310774306.983653 brk(0x24ce000) = 0x24ce000 <0.000023>
1310774306.984667 brk(0x254e000) = 0x254e000 <0.000023>
1310774306.996040 brk(0x2450000) = 0x2450000 <0.000168>
1310774306.996298 gettimeofday({1310774306, 996317}, NULL) = 0 <0.000021>
1310774306.996388 sendto(5,
"\2\0\0\0\350\0\0\0\1@\0\0\2\0\0\0\1\0\0\0\0\0\0\0\r\201\0\0>\0\2\0"...,
232, 0, NULL, 0) = 232 <0.000078>
1310774306.996550 sendto(6,
"T\0\0\0\36\0\1count\0\0\0\0\0\0\0\0\0\0\24\0\10\377\377\377\377\0\0D"...,
66, 0, NULL, 0) = 66 <0.000202>
So the difference is only 2ms. The size of the WAL buffers written is on
32k,
Here's an example with more dirty rows (I basically let the updater run
for a while dirtying very many rows).
"Q\0\0\0_select count(*) from test w"..., 8192, 0, NULL, NULL) = 96
<23.690018>
1310775141.398780 gettimeofday({1310775141, 398801}, NULL) = 0 <0.000028>
1310775141.399018 lseek(12, 0, SEEK_END) = 372514816 <0.000023>
1310775141.399105 lseek(15, 0, SEEK_END) = 436232192 <0.000022>
1310775141.399185 lseek(18, 0, SEEK_END) = 573620224 <0.000023>
1310775141.399362 lseek(12, 0, SEEK_END) = 372514816 <0.000024>
1310775141.414017 brk(0x2490000) = 0x2490000 <0.000028>
1310775141.414575 brk(0x24d0000) = 0x24d0000 <0.000025>
1310775141.415600 brk(0x2550000) = 0x2550000 <0.000024>
1310775141.417757 semop(229383, {{0, -1, 0}}, 1) = 0 <0.000024>
...
1310775141.448998 semop(229383, {{0, -1, 0}}, 1) = 0 <0.000025>
1310775141.453134 brk(0x2452000) = 0x2452000 <0.000167>
1310775141.453377 fadvise64(22, 0, 0, POSIX_FADV_DONTNEED) = 0 <0.000025>
1310775141.453451 close(22) = 0 <0.000032>
1310775141.453537 open("pg_xlog/00000001000000D1000000C2", O_RDWR) = 22
<0.000059>
1310775141.453696 write(22,
"f\320\3\0\1\0\0\0\321\0\0\0\0\0\0\3023\356\17N\23l\vN\0\0\0\1\0
\0\0"..., 5365760) = 5365760 <0.005991>
1310775141.459798 write(22,
"f\320\1\0\1\0\0\0\321\0\0\0\0\340Q\302`\5\0\00000000915!000"...,
9019392) = 9019392 <0.010062>
1310775141.469965 fdatasync(22) = 0 <0.231385>
1310775141.701424 semop(229383, {{2, 1, 0}}, 1) = 0 <0.000031>
1310775141.702657 gettimeofday({1310775141, 702682}, NULL) = 0 <0.000028>
1310775141.702765 sendto(5,
"\2\0\0\0\350\0\0\0\1@\0\0\2\0\0\0\1\0\0\0\0\0\0\0\r\201\0\0>\0\2\0"...,
232, 0, NULL, 0) = 232 <0.000071>
1310775141.702942 sendto(6,
"T\0\0\0\36\0\1count\0\0\0\0\0\0\0\0\0\0\24\0\10\377\377\377\377\0\0D"...,
66, 0, NULL, 0) = 66 <0.000220>
vs
"Q\0\0\0_select count(*) from test w"..., 8192, 0, NULL, NULL) = 96
<55.595425>
1310775406.842823 gettimeofday({1310775406, 842842}, NULL) = 0 <0.000026>
1310775406.843092 lseek(12, 0, SEEK_END) = 382787584 <0.000023>
1310775406.843179 lseek(15, 0, SEEK_END) = 457596928 <0.000042>
1310775406.843280 lseek(18, 0, SEEK_END) = 594968576 <0.000023>
1310775406.843459 lseek(12, 0, SEEK_END) = 382787584 <0.000022>
1310775406.860266 brk(0x2490000) = 0x2490000 <0.000046>
1310775406.860968 brk(0x24d0000) = 0x24d0000 <0.000095>
1310775406.862449 brk(0x2550000) = 0x2550000 <0.000112>
1310775406.865095 semop(229383, {{2, -1, 0}}, 1) = 0 <0.111698>
...
1310775407.027235 semop(229383, {{2, -1, 0}}, 1) = 0 <0.000039>
1310775407.027503 semop(229383, {{2, -1, 0}}, 1) = 0 <2.215137>
1310775409.243291 semop(229383, {{1, 1, 0}}, 1) = 0 <0.000029>
...
1310775409.246963 semop(229383, {{2, -1, 0}}, 1) = 0 <0.000024>
1310775409.252029 brk(0x2452000) = 0x2452000 <0.000168>
1310775409.252288 gettimeofday({1310775409, 252307}, NULL) = 0 <0.000021>
1310775409.252393 sendto(5,
"\2\0\0\0\350\0\0\0\1@\0\0\2\0\0\0\2\0\0\0\0\0\0\0\r\201\0\0>\0\2\0"...,
232, 0, NULL, 0) = 232 <0.000078>
1310775409.252557 sendto(6,
"T\0\0\0\36\0\1count\0\0\0\0\0\0\0\0\0\0\24\0\10\377\377\377\377\0\0D"...,
66, 0, NULL, 0) = 66 <0.000201>
No WAL, but checkout that one expensive semop! 2s!!
-- Lars
view thread (57+ messages) latest in thread
Message-ID: <4E20D988.3040007@yahoo.com>
Permalink: ../4E20D988.3040007@yahoo.com/
Also on: postgresql.org/message-id/4E20D988.3040007@yahoo.com
copy link · copy postgr.es
reply Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-performance@postgresql.org
Cc: lhofhansl@yahoo.com, jeff.janes@gmail.com, Kevin.Grittner@wicourts.gov, ivoras@freebsd.org
Subject: Re: UPDATEDs slowing SELECTs in a fully cached database
In-Reply-To: <4E20D988.3040007@yahoo.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox