Re: UPDATEDs slowing SELECTs in a fully cached database

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



On 07/14/2011 04:03 PM, Jeff Janes wrote:
On Wed, Jul 13, 2011 at 3:41 PM, lars<lhofhansl@xxxxxxxxx>  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


--
Sent via pgsql-performance mailing list (pgsql-performance@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance


[Postgresql General]     [Postgresql PHP]     [PHP Users]     [PHP Home]     [PHP on Windows]     [Kernel Newbies]     [PHP Classes]     [PHP Books]     [PHP Databases]     [Yosemite]

  Powered by Linux