[Lockmeter 2.5] BKL with 51ms hold time, prove me wrong

[Lockmeter 2.5] BKL with 51ms hold time, prove me wrong

[Hanna Linder]

My original purpose was to verify my lockmeter port is producing 
valid data so I was comparing to readprofile results. However, I saw 
these high hold times and wanted to show them to you. Here is the 
whole lockmeter output file: 
http://prdownloads.sourceforge.net/lse/lockmeter.rmapm

Below is a snippet of lockmeter data from running Andrew Morton's
rmap-test -m -i 10 -n 50 -s 600 -t 100 foo
on a 2-way PIII 256MB RAM 500MHz System

If my port of the lockmeter tool is correct then this high hold
time is a bad thing. If the lockmeter tool is incorrect please let 
me know. Here is the link to a lockmeter patch (originally written 
by John Hawkes, I simply ported it): 
http://prdownloads.sourceforge.net/lse/lockmeter1.5-2.5.64-1.diff

Thanks.

Hanna

___________________________________________________________________________
System: Linux w-hlinder2 2.5.66-mjb2lm #3 SMP Thu Apr 10 18:58:09 PDT 2003 i686
Total counts

All (2) CPUs

Start time: Thu Apr 10 19:03:39 2003
End   time: Thu Apr 10 19:08:19 2003
Delta Time: 280.24 sec.
Hash table slots in use:      217.
Global read lock slots in use: 161.

- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
SPINLOCKS         HOLD            WAIT
  UTIL  CON    MEAN(  MAX )   MEAN(  MAX )(% CPU)     TOTAL NOWAIT SPIN RJECT  NAME

       13.7%  2.4us(  51ms)  1.1us(  22ms)(0.15%)   6360789 86.3% 11.2%  2.6%  *TOTAL*

 0.12%    0%  0.3us(  22ms)    0us                  1033785  100%    0%    0%  journal_datalist_lock
 0.04%    0% 2348us(  22ms)    0us                       43  100%    0%    0%    journal_commit_transaction+0x2a0

 0.59% 0.82%   13us(  51ms)   89us(  22ms)(0.02%)    126172 99.2% 0.82%    0%  kernel_flag
 0.02%    0%   26ms(  51ms)    0us                        2  100%    0%    0%    ext3_delete_inode+0x34
 0.06% 48.7%   79us(  22ms)   35us(  20ms)(0.01%)      2115 51.3% 48.7%    0%    schedule+0x48c

 0.00% 36.0%  2.9us(  12us)  1.1us( 3.0us)(0.00%)        25 64.0% 36.0%    0%  runqueues
 0.00% 36.0%  2.9us(  12us)  1.1us( 3.0us)(0.00%)        25 64.0% 36.0%    0%    load_balance+0x148

    0%  100%                   0us                   134325    0%    0%  100%  cache_alloc_refill+0x15c
    0%  100%                   0us                    14658    0%    0%  100%  cache_alloc_refill+0x1f0
 0.03%    0%  7.4us(  24us)    0us                    10472  100%    0%    0%  cache_alloc_refill+0x78
    0%  100%                   0us                    14658    0%    0%  100%  cache_alloc_refill+0xcc
 
 0.62%    0% 5084us(  48ms)    0us                      339  100%    0%    0%  unmap_vmas+0x1c0

Re: [Lockmeter 2.5] BKL with 51ms hold time, prove me wrong

[Andrew Morton]

Hanna Linder <hannal@us.ibm.com> wrote:
>
> 
> My original purpose was to verify my lockmeter port is producing 
> valid data so I was comparing to readprofile results. However, I saw 
> these high hold times and wanted to show them to you. Here is the 
> whole lockmeter output file: 
> http://prdownloads.sourceforge.net/lse/lockmeter.rmapm
> 
> Below is a snippet of lockmeter data from running Andrew Morton's
> rmap-test -m -i 10 -n 50 -s 600 -t 100 foo
> on a 2-way PIII 256MB RAM 500MHz System

I'm a bit surprised that even slow machine like that would take 50
milliseconds to truncate 128MB of file, but it's not impossible I guess. 
Truncate is not really a fastpath.  ext3 in -mm doesn't have any lock_kernels
in it.

Re: [Lockmeter 2.5] BKL with 51ms hold time, prove me wrong

[Hanna Linder]

--On Thursday, April 10, 2003 06:50:06 PM -0700 Andrew Morton <akpm@digeo.com> wrote:

> I'm a bit surprised that even slow machine like that would take 50
> milliseconds to truncate 128MB of file, but it's not impossible I guess. 
> Truncate is not really a fastpath.  ext3 in -mm doesn't have any lock_kernels
> in it.

Sure enough. I ported lockmeter to 2.5.67-mm1 and ran the same rmap-test
and lo and behold all the ext3 issues went away. However, the one remaining
long hold time moved to the top (unmap_vmas):
___________________________________________________________________________________________
System: Linux w-hlinder2 2.5.67-mm1 #1 SMP Fri Apr 11 12:31:38 PDT 2003 i686

SPINLOCKS         HOLD            WAIT
  UTIL  CON    MEAN(  MAX )   MEAN(  MAX )(% CPU)     TOTAL NOWAIT SPIN RJECT  NAME

       19.2%  2.0us(  49ms)  1.1us(9767us)(0.58%)   5506902 80.8% 16.6%  2.5%  *TOTAL*

 0.30% 0.00%  0.4us(9728us) 2598us(3751us)(0.01%)    672210  100% 0.00%    0%  journal_datalist_lock 

 0.26% 0.01%  1.1us(9759us) 4116us(9767us)(0.04%)    211510  100% 0.01%    0%  kernel_flag

 0.00% 10.9%  2.2us(  14us)  1.0us( 1.9us)(0.00%)       137 89.1% 10.9%    0%  runqueues
 0.00% 42.9%  1.6us(  14us)  1.0us( 1.9us)(0.00%)        35 57.1% 42.9%    0%    load_balance+0x138
 0.00%    0%  2.3us( 3.9us)    0us                      102  100%    0%    0%    wake_up_forked_process+0x3c

  3.1%    0%   11ms(  49ms)    0us                      245  100%    0%    0%  unmap_vmas+0x1c0

------------

Here is the port of lockmeter to the 2.5.67-mm1 kernel. If you would consider
putting it in your tree that would be great and I would work on porting the
rest of the architectures. 

http://prdownloads.sourceforge.net/lse/lockmeter1.5-2.5.67-mm1.patch?download

Here is also the whole locmeter output of this run if 
you are interested.

http://prdownloads.sourceforge.net/lse/lockstat-mm1.rmapm?download

Thanks a lot!

Hanna Linder
IBM Linux Technology Center
hannal@us.ibm.com

Re: [Lockmeter 2.5] BKL with 51ms hold time, prove me wrong

[Andrew Morton]

Hanna Linder <hannal@us.ibm.com> wrote:
>
> 
> Sure enough. I ported lockmeter to 2.5.67-mm1 and ran the same rmap-test
> and lo and behold all the ext3 issues went away. However, the one remaining
> long hold time moved to the top (unmap_vmas):

Ah, but the unmap_vmas lock was not kernel_flag, was it?  It'll be
page_table_lock.

That's OK I think.  The only time this is likely to bite anyone is if you
have a threaded application in which one thread it doing a massive munmap()
while another one is handling a pagefault, running mmap(), etc.  And given
that _establishing_ that large mapping in the first place takes tons of CPU,
the relative loss from the long hold time is small.

Famous last words.

> 
> Here is the port of lockmeter to the 2.5.67-mm1 kernel. If you would consider
> putting it in your tree that would be great and I would work on porting the
> rest of the architectures. 
> 
> http://prdownloads.sourceforge.net/lse/lockmeter1.5-2.5.67-mm1.patch?download

OK, that's pretty unintrusive.

Re: [Lockmeter 2.5] BKL with 51ms hold time, prove me wrong

[Dave Hansen]

Hanna Linder wrote:
> My original purpose was to verify my lockmeter port is producing 
> valid data so I was comparing to readprofile results. However, I saw 
> these high hold times and wanted to show them to you. Here is the 
> whole lockmeter output file: 
> http://prdownloads.sourceforge.net/lse/lockmeter.rmapm
> 
> Below is a snippet of lockmeter data from running Andrew Morton's
> rmap-test -m -i 10 -n 50 -s 600 -t 100 foo
> on a 2-way PIII 256MB RAM 500MHz System
> 
> If my port of the lockmeter tool is correct then this high hold
> time is a bad thing. If the lockmeter tool is incorrect please let 
> me know. Here is the link to a lockmeter patch (originally written 
> by John Hawkes, I simply ported it): 
> http://prdownloads.sourceforge.net/lse/lockmeter1.5-2.5.64-1.diff

This isn't much of a surprise, nor is is likely a problem in your
lockmeter port.  The offender is ext3_delete_inode.  The BKL was only
taken here twice out of the 126172 lock_kernel() which were profiled.
The 51ms happened once and the other time, the lock was released much
more quickly.

  SPINLOCKS     HOLD        WAIT
  UTIL  CON  MEAN( MAX ) MEAN( MAX)(% CPU) TOTAL NOWAIT SPIN RJECT
 0.02%    0% 26ms( 51ms)  0us                  2   100%    0%    0%

The odds are that the 22ms wait in ext3_writepage and the 20ms wait in
schedule were due to this single hold.  Actually, the schedule one could
very well be caused by the reacquisiton after ext3_delete_inode() hit
something that made it sleep with the BKL held.

I've thought that it would be helpful to have lockmeter special-case the
reacquire_kernel() in schedule, to properly attribute the time to the
original offender.
-- 
Dave Hansen
haveblue@us.ibm.com