BKL with 51ms hold time, prove me wrong

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

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
[email protected]

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.

OK, that's pretty unintrusive.

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
[email protected]