Message-ID: <4E1CD580.3030100@yahoo.com>
Date: Tue, 12 Jul 2011 16:15:12 -0700
From: lars <lhofhansl@yahoo.com>
User-Agent: Mozilla/5.0 (X11; U; Linux x86_64; en-US;
	rv:1.9.2.18) Gecko/20110621 Fedora/3.1.11-1.fc14 Thunderbird/3.1.11
MIME-Version: 1.0
To: Merlin Moncure <mmoncure@gmail.com>
CC: Kevin Grittner <Kevin.Grittner@wicourts.gov>,
	Ivan Voras <ivoras@freebsd.org>, pgsql-performance@postgresql.org
Subject: Re: UPDATEDs slowing SELECTs in a fully cached database
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>
	<CAHyXU0zFwKcVPU23HJDxmuf+W-c_HzoROwGN11suyTeSvGVRaw@mail.gmail.com>
In-Reply-To: 
 <CAHyXU0zFwKcVPU23HJDxmuf+W-c_HzoROwGN11suyTeSvGVRaw@mail.gmail.com>
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit

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