Date: Fri, 26 Oct 2007 12:46:14 -0400
From: "Jignesh K. Shah" <J.K.Shah@Sun.COM>
Subject: Re: [HACKERS] 8.3beta1 testing on Solaris
In-reply-to: <47220B96.4080009@sun.com>
To: "Jignesh K. Shah" <J.K.Shah@Sun.COM>
Cc: Tom Lane <tgl@sss.pgh.pa.us>, Josh Berkus <josh@agliodbs.com>,
	pgsql-performance@postgresql.org,
	Gregory Stark <stark@enterprisedb.com>, pgsql-hackers@postgresql.org
Message-id: <472219D6.6030001@sun.com>
MIME-version: 1.0
Content-type: text/plain; format=flowed; charset=ISO-8859-1
Content-transfer-encoding: 7BIT
References: <4720FB72.8060800@sun.com> <871wbi95nb.fsf@oxford.xeocode.com>
	<29721.1193359867@sss.pgh.pa.us> <200710251956.56744.josh@agliodbs.com>
	<2139.1193369168@sss.pgh.pa.us> <4721ED75.7090607@sun.com>
	<47220B96.4080009@sun.com>
User-Agent: Thunderbird 2.0.0.6 (Macintosh/20070728)

Also to give perspective on the equivalent writes on CLOG

I used the following script which runs for 10 sec to track all writes to 
the clog directory and here is what it came up with... (This is with 500 
users running)

# cat write.d
#!/usr/sbin/dtrace -s
syscall::write:entry
/execname=="postgres" && 
dirname(fds[arg0].fi_pathname)=="/export/home0/igen/pgdata/pg_clog"/
{
    @write[fds[arg0].fi_pathname,arg1] = count();
}
tick-10sec
{
exit(0);
}

# ./write.d
dtrace: script './write.d' matched 2 probes
CPU     ID                    FUNCTION:NAME
  3   1026                      :tick-10sec

  /export/home0/igen/pgdata/pg_clog/001E               
-2753028277088                1
#
I modified read.d to do a 5sec read
# ./read.d
dtrace: script './read.d' matched 3 probes
CPU     ID                    FUNCTION:NAME
  0      1                           :BEGIN
  0   1027                       :tick-5sec

  /export/home0/igen/pgdata/pg_clog/001F               
-2753028268896                1
  /export/home0/igen/pgdata/pg_clog/001F               
-2753028252512                1
  /export/home0/igen/pgdata/pg_clog/001F               
-2753028285280                2
  /export/home0/igen/pgdata/pg_clog/001F               
-2753028277088                3
  /export/home0/igen/pgdata/pg_clog/001F               
-2753028236128                3
  /export/home0/igen/pgdata/pg_clog/001E               
-2753028285280                5
  /export/home0/igen/pgdata/pg_clog/001E               
-2753028236128                9
  /export/home0/igen/pgdata/pg_clog/001E               
-2753028277088               13
  /export/home0/igen/pgdata/pg_clog/001E               
-2753028268896               15
  /export/home0/igen/pgdata/pg_clog/001E               
-2753028252512               27
#

So the ratio of reads vs writes to clog files is pretty huge..


-Jignesh


Jignesh K. Shah wrote:
> Tom,
>
> Here is what I did:
>
> I started aggregating all read information:
>
> First I also had added group by pid    (arg0,arg1, pid) and the counts 
> were all coming as 1
>
> Then I just grouped by filename and location (arg0,arg1 of reads) and 
> the counts came back as
>
> # cat read.d
> #!/usr/sbin/dtrace -s
> syscall::read:entry
> /execname=="postgres"/
> {
>    @read[fds[arg0].fi_pathname, arg1] = count();
> }
>
>
> # ./read.d
> dtrace: script './read.d' matched 1 probe
> ^C
>
>  /export/home0/igen/pgdata/pg_clog/0014               
> -2753028293472                1
>  /export/home0/igen/pgdata/pg_clog/0014               
> -2753028277088                1
>  /export/home0/igen/pgdata/pg_clog/0015               
> -2753028244320                2
>  /export/home0/igen/pgdata/pg_clog/0015               
> -2753028268896               14
>  /export/home0/igen/pgdata/pg_clog/0015               
> -2753028260704               25
>  /export/home0/igen/pgdata/pg_clog/0015               
> -2753028252512               27
>  /export/home0/igen/pgdata/pg_clog/0015               
> -2753028277088               28
>  /export/home0/igen/pgdata/pg_clog/0015               
> -2753028293472               37
>
>
> FYI  I pressed ctrl-c within like less than a second
>
> So to me this seems that multiple processes are reading the same page 
> from different pids. (This was with about 600 suers active.
>
> Aparently we do have a problem that we are reading the same buffer 
> address again.  (Same as not being cached anywhere or not finding it 
> in cache anywhere).
>
> I reran lock wait script on couple of processes and did not see 
> CLogControlFileLock  as a problem..
>
> # ./83_lwlock_wait.d 14341
>
>             Lock Id            Mode           Count
>       WALInsertLock       Exclusive               1
>       ProcArrayLock       Exclusive              16
>
>             Lock Id   Combined Time (ns)
>       WALInsertLock               383109
>       ProcArrayLock            198866236
>
> # ./83_lwlock_wait.d 14607
>
>             Lock Id            Mode           Count
>       WALInsertLock       Exclusive               2
>       ProcArrayLock       Exclusive              15
>
>             Lock Id   Combined Time (ns)
>       WALInsertLock                55243
>       ProcArrayLock             69700140
>
> #
>
> What will help you find out why it is reading the same page again?
>
>
> -Jignesh
>
>
>
> Jignesh K. Shah wrote:
>> I agree with Tom..  somehow I think  increasing NUM_CLOG_BUFFERS is 
>> just avoiding the symptom to a later value.. I promise to look more 
>> into it before making any recommendations to increase NUM_CLOG_BUFFERs.
>>
>>
>> Because though "iGen"  showed improvements in that area by increasing 
>> num_clog_buffers , EAStress had shown no improvements.. Plus the 
>> reason I think this is not the problem in 8.3beta1 since the Lock 
>> Output clearly does not show CLOGControlFile as to be the issue which 
>> I had seen in earlier case.  So I dont think that increasing 
>> NUM_CLOG_BUFFERS will change thing here.
>>
>> Now I dont understand the code pretty well yet I see three hotspots 
>> and not sure if they are related to each other
>> * ProcArrayLock waits  - causing Waits          as reported by 
>> 83_lockwait.d script
>> * SimpleLRUReadPage - causing read IOs             as reported by 
>> iostat/rsnoop.d
>> * GetSnapshotData - causing CPU utilization  as reported by hotuser
>>
>> But I will shut up and do more testing.
>>
>> Regards,
>> Jignesh
>>
>>
>>
>> Tom Lane wrote:
>>> Josh Berkus <josh@agliodbs.com> writes:
>>>  
>>>> Actually, 32 made a significant difference as I recall ... do you 
>>>> still have the figures for that, Jignesh?
>>>>     
>>>
>>> I'd want to see a new set of test runs backing up any call for a change
>>> in NUM_CLOG_BUFFERS --- we've changed enough stuff around this area 
>>> that
>>> benchmarks using code from a few months back shouldn't carry a lot of
>>> weight.
>>>
>>>             regards, tom lane
>>>   
>>
>> ---------------------------(end of broadcast)---------------------------
>> TIP 5: don't forget to increase your free space map settings