Re: UPDATEDs slowing SELECTs in a fully cached database

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