Re: UPDATEDs slowing SELECTs in a fully cached database - Mailing list pgsql-performance
From | lars |
---|---|
Subject | Re: UPDATEDs slowing SELECTs in a fully cached database |
Date | |
Msg-id | 4E1CD580.3030100@yahoo.com Whole thread Raw |
In response to | Re: UPDATEDs slowing SELECTs in a fully cached database (Merlin Moncure <mmoncure@gmail.com>) |
Responses |
Re: UPDATEDs slowing SELECTs in a fully cached database
(Merlin Moncure <mmoncure@gmail.com>)
|
List | pgsql-performance |
On 07/12/2011 02:38 PM, Merlin Moncure wrote: > > Something is not adding up here. Perhaps there is an alternate route > to WAL logged activity from selects I'm not thinking of. Right now > I'm thinking to run the selects on table 'a' and the inserts > concurrently on table 'b' and seeing how that behaves. Another way to > get to the bottom is to oprofile the selecting-during-load backend to > see where the time is getting spent. Alternative way to do this is > to strace attach to the selecting-during-load backend to see if it's > really writing to the WAL (I'm really curious about this). > > Another interesting test would be to try and reproduce the results on > native machine. It should be possible to do this on your workstation > with a more modestly sized scaling factor. > > merlin > Just tried with two of my test tables. Updates on 'a' have no (measurable) effect on select from 'b'. Back to the first case, here's an strace from the backend doing the select right after the updates. "Q\0\0\0`select count(*) from test1 "..., 8192, 0, NULL, NULL) = 97 gettimeofday({1310512219, 723762}, NULL) = 0 open("base/16385/33032", O_RDWR) = 8 lseek(8, 0, SEEK_END) = 1073741824 open("base/16385/33032.1", O_RDWR|O_CREAT, 0600) = 9 lseek(9, 0, SEEK_END) = 1073741824 open("base/16385/33032.2", O_RDWR|O_CREAT, 0600) = 10 lseek(10, 0, SEEK_END) = 191348736 open("base/16385/33035", O_RDWR) = 11 lseek(11, 0, SEEK_END) = 1073741824 open("base/16385/33035.1", O_RDWR|O_CREAT, 0600) = 12 lseek(12, 0, SEEK_END) = 3571712 lseek(10, 0, SEEK_END) = 191348736 brk(0x28ad000) = 0x28ad000 mmap(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5f28ca0000 mmap(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5f28c5f000 munmap(0x7f5f28c5f000, 266240) = 0 munmap(0x7f5f28ca0000, 135168) = 0 open("pg_xlog/00000001000000BB00000012", O_RDWR) = 13 lseek(13, 1564672, SEEK_SET) = 1564672 write(13, "f\320\1\0\1\0\0\0\273\0\0\0\0\340\27\22`\32\0\00000002833!000"..., 2400256) = 2400256 fdatasync(13) = 0 semop(229383, {{9, 1, 0}}, 1) = 0 gettimeofday({1310512219, 885287}, NULL) = 0 sendto(5, "\2\0\0\0\300\3\0\0\1@\0\0\t\0\0\0\1\0\0\0\0\0\0\0\353\4\0\0@\0\2\0"..., 960, 0, NULL, 0) = 960 sendto(5, "\2\0\0\0\300\3\0\0\1@\0\0\t\0\0\0\0\0\0\0\0\0\0\0009\n\0\0@\0\2\0"..., 960, 0, NULL, 0) = 960 sendto(5, "\2\0\0\0\300\3\0\0\1@\0\0\t\0\0\0\0\0\0\0\0\0\0\0v\n\0\0@\0\2\0"..., 960, 0, NULL, 0) = 960 sendto(5, "\2\0\0\0\270\1\0\0\0\0\0\0\4\0\0\0\0\0\0\0\0\0\0\0\275\4\0\0\377\177\0\0"..., 440, 0, NULL, 0) = 440 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 So the backend definitely writing to the WAL, directly and synchronously. Selecting the same set of rows again: "Q\0\0\0`select count(*) from test1 "..., 8192, 0, NULL, NULL) = 97 gettimeofday({1310512344, 823728}, NULL) = 0 lseek(10, 0, SEEK_END) = 191348736 lseek(12, 0, SEEK_END) = 3571712 lseek(10, 0, SEEK_END) = 191348736 brk(0x28d5000) = 0x28d5000 brk(0x2915000) = 0x2915000 brk(0x2897000) = 0x2897000 gettimeofday({1310512344, 831043}, NULL) = 0 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\10\201\0\0?\0\2\0"..., 232, 0, NULL, 0) = 232 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 No writing to the WAL. -- Lars
pgsql-performance by date: