[PATCH] Preemption Latency Measurement Tool

[PATCH] Preemption Latency Measurement Tool

[Robert Love]

Available at:
http://tech9.net/rml/linux/patch-rml-2.4.9-ac12-preempt-stats-1 and
http://tech9.net/rml/linux/patch-rml-2.4.10-pre12-preempt-stats-1
for 2.4.9-ac12 and 2.4.10-pre12, respectively.

This patch is provided thanks to MontaVista (http://mvista.com).

This patch enables a new kernel configure option, CONFIG_PREEMPT_TIMES,
which once enabled instructs the kernel preemption code to monitor
in-kernel latencies due to the various locking primitives and report the
20 worst recorded cases to /proc/latencytimes.

The patch obviously requires the preemption patch, available at
http://tech9.net/rml/linux

The patch won't start recording (I will change this...) until you read
from /proc/latencytimes once.  From then on, each read will return the
20 worst cases and reset the log.  Nonetheless, you don't want this in
the kernel if you don't plan to do use it, and I do _not_ want it
enabled during benchmarks.

The proc interface is fairly verbose.  It will give you a measurement of
the latency, what is causing the latency, the file line number and
filename where the lock (or whatever) began and the same for where it
ended.

The point is to track down long held locks and other problems that are
causing poor response.

Thus, most of you CC have noticed certain situations wherein even with
preemption you see high latencies (most of you with mp3 playback).  I
ask that, if you get the chance, to play with this patch and measuring
some latencies.  See where bad values lie.  Get a feeling for your
system... most of your latencies should be very small.  Right now, I
just read a sampling of my 8000 worst cases and the worst was 600us --
this is not bad.  Things over 5000us are interesting, especially if
consistent.

I appreciate any comments.  CC me and the list.  Enjoy.

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Ignacio Vazquez-Abrams]

I'm posting this in the hope that someone will find it useful.

Worst 20 latency times of 4647 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 35735  spin_lock        1   358/memory.c        c012c74a   379/memory.c
 14003  spin_lock        1   341/vmscan.c        c013977b   362/vmscan.c
 13701  spin_lock        1  1376/sched.c         c0118ef9   697/sched.c
 12533        BKL        7  2689/buffer.c        c0149acc   697/sched.c
 12459  spin_lock        7   547/sched.c         c0116ca3   697/sched.c
 10479  spin_lock        1   703/vmscan.c        c013a213   685/vmscan.c
 10443  spin_lock        1   669/inode.c         c015e8dd   696/inode.c
  9163   reacqBKL        1  1375/sched.c         c0118edb  1381/sched.c
  8727        BKL        9   164/inode.c         c0171885   188/inode.c
  8066   usb-uhci        d    76/softirq.c       c0120cf2   119/softirq.c
  8041        BKL        9   130/attr.c          c015fbd4   143/attr.c
  7982  spin_lock        8   547/sched.c         c0116ca3   204/namei.c
  6920   reacqBKL        5  1375/sched.c         c0118edb   697/sched.c
  6720  spin_lock        0  1376/sched.c         c0118ef9  1380/sched.c
  6567  spin_lock        0   661/vmscan.c        c013a0f2   764/vmscan.c
  6365  spin_lock        0   703/vmscan.c        c013a213   764/vmscan.c
  5680        BKL        1   452/exit.c          c011f6c6   697/sched.c
  5646  spin_lock        0   227/inode.c         c015df35   696/inode.c
  5428  spin_lock        1   710/inode.c         c015ea08   696/inode.c
  4933  spin_lock        0   547/sched.c         c0116ca3  1380/sched.c

This was taken after compiling several packages and running dbench a few
times.

I also ran it previously while running 'while true ; do python -c range\(3e7\)
; done', and the first line had minimum latencies of 10000, going as high as
about 96000 when swapping.

This is on an Athlon 1050/100 Asus A7V (KT133) with PC133 CL2 SDRAM running
2.4.9-ac12-preempt1.

-- 
Ignacio Vazquez-Abrams  <ignacio@openservices.net>

Re: [PATCH] Preemption Latency Measurement Tool

[safemode]

Is it possible to run the 20 worsst latency thing without having the pre-empt 
patch ?  I'd like to see how things run without the preempt patch and which 
ones are the slowest.   The last time i used the pre-empt patch i had worse 
audio performance than not.  Perhaps that's because i use alsa. 



On Wednesday 19 September 2001 21:40, Ignacio Vazquez-Abrams wrote:
> I'm posting this in the hope that someone will find it useful.
>
> Worst 20 latency times of 4647 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
>  35735  spin_lock        1   358/memory.c        c012c74a   379/memory.c
>  14003  spin_lock        1   341/vmscan.c        c013977b   362/vmscan.c
>  13701  spin_lock        1  1376/sched.c         c0118ef9   697/sched.c
>  12533        BKL        7  2689/buffer.c        c0149acc   697/sched.c
>  12459  spin_lock        7   547/sched.c         c0116ca3   697/sched.c
>  10479  spin_lock        1   703/vmscan.c        c013a213   685/vmscan.c
>  10443  spin_lock        1   669/inode.c         c015e8dd   696/inode.c
>   9163   reacqBKL        1  1375/sched.c         c0118edb  1381/sched.c
>   8727        BKL        9   164/inode.c         c0171885   188/inode.c
>   8066   usb-uhci        d    76/softirq.c       c0120cf2   119/softirq.c
>   8041        BKL        9   130/attr.c          c015fbd4   143/attr.c
>   7982  spin_lock        8   547/sched.c         c0116ca3   204/namei.c
>   6920   reacqBKL        5  1375/sched.c         c0118edb   697/sched.c
>   6720  spin_lock        0  1376/sched.c         c0118ef9  1380/sched.c
>   6567  spin_lock        0   661/vmscan.c        c013a0f2   764/vmscan.c
>   6365  spin_lock        0   703/vmscan.c        c013a213   764/vmscan.c
>   5680        BKL        1   452/exit.c          c011f6c6   697/sched.c
>   5646  spin_lock        0   227/inode.c         c015df35   696/inode.c
>   5428  spin_lock        1   710/inode.c         c015ea08   696/inode.c
>   4933  spin_lock        0   547/sched.c         c0116ca3  1380/sched.c
>
> This was taken after compiling several packages and running dbench a few
> times.
>
> I also ran it previously while running 'while true ; do python -c
> range\(3e7\) ; done', and the first line had minimum latencies of 10000,
> going as high as about 96000 when swapping.
>
> This is on an Athlon 1050/100 Asus A7V (KT133) with PC133 CL2 SDRAM running
> 2.4.9-ac12-preempt1.

Re: [PATCH] Preemption Latency Measurement Tool

[David Lang]

also how useful is the latency info once swapping starts? if you have
something that gets swapped out it will have horrible latency and skew the
results (or at the very least you won't know if the problem is disk IO or
fixable problems)

David Lang

 On Wed, 19 Sep 2001, safemode wrote:

> Date: Wed, 19 Sep 2001 22:23:21 -0400
> From: safemode <safemode@speakeasy.net>
> To: Ignacio Vazquez-Abrams <ignacio@openservices.net>,
>      linux-kernel@vger.kernel.org
> Subject: Re: [PATCH] Preemption Latency Measurement Tool
>
> Is it possible to run the 20 worsst latency thing without having the pre-empt
> patch ?  I'd like to see how things run without the preempt patch and which
> ones are the slowest.   The last time i used the pre-empt patch i had worse
> audio performance than not.  Perhaps that's because i use alsa.
>
>
>
> On Wednesday 19 September 2001 21:40, Ignacio Vazquez-Abrams wrote:
> > I'm posting this in the hope that someone will find it useful.
> >
> > Worst 20 latency times of 4647 measured in this period.
> >   usec      cause     mask   start line/file      address   end line/file
> >  35735  spin_lock        1   358/memory.c        c012c74a   379/memory.c
> >  14003  spin_lock        1   341/vmscan.c        c013977b   362/vmscan.c
> >  13701  spin_lock        1  1376/sched.c         c0118ef9   697/sched.c
> >  12533        BKL        7  2689/buffer.c        c0149acc   697/sched.c
> >  12459  spin_lock        7   547/sched.c         c0116ca3   697/sched.c
> >  10479  spin_lock        1   703/vmscan.c        c013a213   685/vmscan.c
> >  10443  spin_lock        1   669/inode.c         c015e8dd   696/inode.c
> >   9163   reacqBKL        1  1375/sched.c         c0118edb  1381/sched.c
> >   8727        BKL        9   164/inode.c         c0171885   188/inode.c
> >   8066   usb-uhci        d    76/softirq.c       c0120cf2   119/softirq.c
> >   8041        BKL        9   130/attr.c          c015fbd4   143/attr.c
> >   7982  spin_lock        8   547/sched.c         c0116ca3   204/namei.c
> >   6920   reacqBKL        5  1375/sched.c         c0118edb   697/sched.c
> >   6720  spin_lock        0  1376/sched.c         c0118ef9  1380/sched.c
> >   6567  spin_lock        0   661/vmscan.c        c013a0f2   764/vmscan.c
> >   6365  spin_lock        0   703/vmscan.c        c013a213   764/vmscan.c
> >   5680        BKL        1   452/exit.c          c011f6c6   697/sched.c
> >   5646  spin_lock        0   227/inode.c         c015df35   696/inode.c
> >   5428  spin_lock        1   710/inode.c         c015ea08   696/inode.c
> >   4933  spin_lock        0   547/sched.c         c0116ca3  1380/sched.c
> >
> > This was taken after compiling several packages and running dbench a few
> > times.
> >
> > I also ran it previously while running 'while true ; do python -c
> > range\(3e7\) ; done', and the first line had minimum latencies of 10000,
> > going as high as about 96000 when swapping.
> >
> > This is on an Athlon 1050/100 Asus A7V (KT133) with PC133 CL2 SDRAM running
> > 2.4.9-ac12-preempt1.
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
>

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Wed, 2001-09-19 at 21:13, David Lang wrote:
> also how useful is the latency info once swapping starts? if you have
> something that gets swapped out it will have horrible latency and skew the
> results (or at the very least you won't know if the problem is disk IO or
> fixable problems)

Its not that bad because the patch measures latency across points where
preemption was enabled and disabled -- the various kernel locking
mechanisms.

Thus either page fault holds a lock and it is a legimate latency
recorded over that specific lock, or it doesn't in which case its not an
issue.

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Wed, 2001-09-19 at 22:23, safemode wrote:
> Is it possible to run the 20 worsst latency thing without having the pre-empt
> patch ?  I'd like to see how things run without the preempt patch and which 
> ones are the slowest.   The last time i used the pre-empt patch i had worse 
> audio performance than not.  Perhaps that's because i use alsa. 

No, it requires the preemption patch.  It uses the preemption count code
in figuring out when code returns.  Besides, if you are non-preemption
and UP, you don't have many locking primitives anyhow (no concurrency
concerns there).

You honestly should not have _worse_ latency with the patch.  Even if
something was wrong, it should still be about the same.  However, most
people are reporting a many many times over reduction in latency.

Your point about using ALSA is one of the reasons I am interested in
this patch.  Most of the people reporting high-latencies remaining even
after the patch used ALSA.

If you try preemption again, along with this patch, we can find out what
is causing your problems.

If you just want to gauage how long it takes to execute code from A to B
in the kernel, there are various benchmarking tools as well as Andrew
Morton's excellent timepegs work.

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Dieter Nützel]

Am Donnerstag, 20. September 2001 00:44 schrieb Robert Love:
> Available at:
> http://tech9.net/rml/linux/patch-rml-2.4.9-ac12-preempt-stats-1 and
> http://tech9.net/rml/linux/patch-rml-2.4.10-pre12-preempt-stats-1
> for 2.4.9-ac12 and 2.4.10-pre12, respectively.
>
> This patch is provided thanks to MontaVista (http://mvista.com).

Great, thanks.

Here are some results for 2.4.10-pre12 (Andrea's VM :-)

Athlon II 1 GHz (0.18 µm)
MSI MS-6167 Rev 1.0B (Irongate C4)
640 MB PC100-2-2-2 SDRAM
IBM DDYS 18 GB U160 (on AHA-2940UW)
ReiserFS 3.6 on all partitions

Sound driver is the new kernel one for SB Live! (not ALSA).
No swap used during whole test.

2.4.10-pre12 + patch-rml-2.4.10-pre12-preempt-kernel-1 + 
patch-rml-2.4.10-pre12-preempt-stats-1

Hope my numbers help to find the right reason for the hiccups.
ReiserFS seems _NOT_ to be the culprit for this.
Maybe the scheduler it self?

-Dieter

KDE-2.2.1 noatun running MP3/Ogg-Vorbis
+
time ./dbench 16
Throughput 29.3012 MB/sec (NB=36.6265 MB/sec  293.012 MBit/sec)
7.450u 28.830s 1:13.10 49.6%    0+0k 0+0io 511pf+0w
load: 1140

Worst 20 latency times of 5583 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  5664  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  2586        BKL        1  1302/inode.c         c016f2f9  1381/sched.c
  2329        BKL        0  1302/inode.c         c016f2f9   842/inode.c
  2231        BKL        1  1302/inode.c         c016f2f9   697/sched.c
  2088        BKL        1  1437/namei.c         c014c42f   697/sched.c
  1992        BKL        0    30/inode.c         c016cdf1  1381/sched.c
  1953        BKL        1  1302/inode.c         c016f2f9    52/inode.c
  1952        BKL        0  1302/inode.c         c016f2f9  1380/sched.c
  1947        BKL        1    30/inode.c         c016cdf1   697/sched.c
  1923   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
  1908        BKL        0  1302/inode.c         c016f2f9  1306/inode.c
  1904        BKL        1   452/exit.c          c011af61   697/sched.c
  1892        BKL        1   129/attr.c          c015765d   697/sched.c
  1875        BKL        0  1437/namei.c         c014c42f  1381/sched.c
  1823  spin_lock        0   547/sched.c         c0112fe4  1381/sched.c
  1790   reacqBKL        0  1375/sched.c         c0114d94  1439/namei.c
  1779        BKL        1  1366/namei.c         c014c12c  1381/sched.c
  1762  spin_lock        0   547/sched.c         c0112fe4  1380/sched.c
  1756   reacqBKL        1  1375/sched.c         c0114d94    52/inode.c
  1754        BKL        0   927/namei.c         c014b2bf  1381/sched.c


time ./dbench 32
Throughput 28.0138 MB/sec (NB=35.0172 MB/sec  280.138 MBit/sec)
14.570u 61.520s 2:31.80 50.1%   0+0k 0+0io 911pf+0w
load: 2690

Worst 20 latency times of 8091 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  8347        BKL        1   533/inode.c         c016d96d   842/inode.c
  7808  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  6181        BKL        1  1302/inode.c         c016f2f9  1381/sched.c
  3325        BKL        1  1302/inode.c         c016f2f9   842/inode.c
  3314  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
  3014        BKL        1   129/attr.c          c015765d   697/sched.c
  2956        BKL        1  1302/inode.c         c016f2f9  1380/sched.c
  2954   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  2795        BKL        1   927/namei.c         c014b2bf   697/sched.c
  2750        BKL        1  1302/inode.c         c016f2f9   697/sched.c
  2667        BKL        1    30/inode.c         c016cdf1   697/sched.c
  2623  spin_lock        0  1376/sched.c         c0114db3  1380/sched.c
  2613  spin_lock        0  1376/sched.c         c0114db3  1306/inode.c
  2566   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
  2527        BKL        0  1437/namei.c         c014c42f   697/sched.c
  2526        BKL        0  1437/namei.c         c014c42f  1380/sched.c
  2525  spin_lock        1   547/sched.c         c0112fe4  1380/sched.c
  2513        BKL        0   927/namei.c         c014b2bf  1380/sched.c
  2442        BKL        0    30/inode.c         c016cdf1  1381/sched.c
  2353        BKL        0   452/exit.c          c011af61  1380/sched.c


time ./dbench 40
Throughput 24.664 MB/sec (NB=30.83 MB/sec  246.64 MBit/sec)
18.690u 77.980s 3:35.09 44.9%   0+0k 0+0io 1111pf+0w
load: 3734

Worst 20 latency times of 7340 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  9313  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  9040        BKL        1  1302/inode.c         c016f2f9  1306/inode.c
  8530        BKL        1  1302/inode.c         c016f2f9   842/inode.c
  8268   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  5432  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
  3630   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  3519        BKL        1  1437/namei.c         c014c42f  1380/sched.c
  3387        BKL        0  1302/inode.c         c016f2f9   697/sched.c
  3194  spin_lock        0   547/sched.c         c0112fe4  1380/sched.c
  3180  spin_lock        0   547/sched.c         c0112fe4  1381/sched.c
  3015  spin_lock        1   547/sched.c         c0112fe4   842/inode.c
  2894        BKL        0  1302/inode.c         c016f2f9  1381/sched.c
  2778  spin_lock        1  1376/sched.c         c0114db3  1380/sched.c
  2755        BKL        1  1302/inode.c         c016f2f9  1380/sched.c
  2676        BKL        1   452/exit.c          c011af61   697/sched.c
  2354        BKL        1   533/inode.c         c016d96d   697/sched.c
  2237        BKL        0    30/inode.c         c016cdf1   697/sched.c
  2104        BKL        0  1437/namei.c         c014c42f  1381/sched.c
  2097  spin_lock        0  1376/sched.c         c0114db3  1381/sched.c
  2082        BKL        0    30/inode.c         c016cdf1  1380/sched.c


time ./dbench 48
Throughput 24.5409 MB/sec (NB=30.6761 MB/sec  245.409 MBit/sec)
22.080u 97.560s 4:19.19 46.1%   0+0k 0+0io 1311pf+0w
load: 4622

Worst 20 latency times of 10544 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 12831        BKL        1    30/inode.c         c016cdf1    52/inode.c
 10869   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  9303        BKL        1  1302/inode.c         c016f2f9   697/sched.c
  9145        BKL        1  1302/inode.c         c016f2f9  1306/inode.c
  7984  spin_lock        1   547/sched.c         c0112fe4  1380/sched.c
  5983        BKL        1  1302/inode.c         c016f2f9   842/inode.c
  4947   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  4497  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
  4310  spin_lock        1  1376/sched.c         c0114db3  1380/sched.c
  4290   reacqBKL        0  1375/sched.c         c0114d94  1306/inode.c
  4002  spin_lock        1   547/sched.c         c0112fe4  1381/sched.c
  3822  spin_lock        0  1376/sched.c         c0114db3   697/sched.c
  3683        BKL        0  1302/inode.c         c016f2f9  1380/sched.c
  3422  spin_lock        1   547/sched.c         c0112fe4  1306/inode.c
  3193        BKL        0  1437/namei.c         c014c42f  1380/sched.c
  3006        BKL        1    30/inode.c         c016cdf1  1380/sched.c
  2990        BKL        1   129/attr.c          c015765d   697/sched.c
  2971        BKL        1  1437/namei.c         c014c42f  1381/sched.c
  2939        BKL        0   927/namei.c         c014b2bf  1381/sched.c
  2862        BKL        0  1302/inode.c         c016f2f9  1381/sched.c


KDE-2.2.1 noatun running MP3/Ogg-Vorbis

Worst 20 latency times of 2252 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
   237        BKL        0  2763/buffer.c        c01410aa   697/sched.c
   218  spin_lock        0   547/sched.c         c0112fe4  1381/sched.c
   215   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
   215        BKL        0  2763/buffer.c        c01410aa  1381/sched.c
   205        BKL        0   359/buffer.c        c013d1bc  1381/sched.c
   205       eth1        0   585/irq.c           c010886f   647/irq.c
   149  spin_lock        0   547/sched.c         c0112fe4   697/sched.c
   147        BKL        0   359/buffer.c        c013d1bc   697/sched.c
   135  spin_lock        0  1376/sched.c         c0114db3  1380/sched.c
   130   reacqBKL        0  1375/sched.c         c0114d94   697/sched.c
   111        BKL        0   452/exit.c          c011af61   697/sched.c
   105    unknown        1    76/softirq.c       c011c634   119/softirq.c
    86        BKL        4   712/tty_io.c        c018cf6b   714/tty_io.c
    61  spin_lock        0  1715/dev.c           c01dc4b3  1728/dev.c
    58        BKL        0   301/namei.c         c0149db1   303/namei.c
    56  spin_lock        2   468/netfilter.c     c01e4303   119/softirq.c
    44        BKL        1    59/ioctl.c         c014ea3a   111/ioctl.c
    43        BKL        0  1302/inode.c         c016f2f9  1306/inode.c
    43  spin_lock        1    69/i387.c          c010ca23   227/mmx.c
    42        BKL        1    26/readdir.c       c014ed07    28/readdir.c


Renice -20 both artsd prozesses (the KDE-2.2.1 noatun sound daemon)
help a little bit but there are still some hiccups (1~3 sec)
remaining.

But the system is very responsive (mouse, keyboard).

time ./dbench 16
Throughput 30.8602 MB/sec (NB=38.5752 MB/sec  308.602 MBit/sec)
7.490u 29.350s 1:09.44 53.0%    0+0k 0+0io 511pf+0w

Worst 20 latency times of 5851 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  5518  spin_lock        1  1376/sched.c         c0114db3  1380/sched.c
  2553        BKL        1  1302/inode.c         c016f2f9   697/sched.c
  2284        BKL        0  1302/inode.c         c016f2f9   842/inode.c
  2235   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  2227        BKL        0  1302/inode.c         c016f2f9  1380/sched.c
  2183        BKL        0   927/namei.c         c014b2bf  1306/inode.c
  2055        BKL        1   927/namei.c         c014b2bf   697/sched.c
  2037        BKL        1   452/exit.c          c011af61   697/sched.c
  2032        BKL        0    30/inode.c         c016cdf1   697/sched.c
  2008        BKL        1  1302/inode.c         c016f2f9  1381/sched.c
  1943        BKL        0   927/namei.c         c014b2bf  1439/namei.c
  1926        BKL        1   452/exit.c          c011af61    52/inode.c
  1919  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  1880        BKL        0  1437/namei.c         c014c42f  1381/sched.c
  1865        BKL        0    30/inode.c         c016cdf1  1380/sched.c
  1858  spin_lock        0   547/sched.c         c0112fe4  1380/sched.c
  1849   reacqBKL        0  1375/sched.c         c0114d94  1439/namei.c
  1821   reacqBKL        0  1375/sched.c         c0114d94   697/sched.c
  1774        BKL        1   129/attr.c          c015765d   697/sched.c
  1720        BKL        1  1437/namei.c         c014c42f  1380/sched.c


time ./dbench 48
Throughput 22.85 MB/sec (NB=28.5626 MB/sec  228.5 MBit/sec)
21.840u 98.560s 4:38.30 43.2%   0+0k 0+0io 1311pf+0w

Worst 20 latency times of 8664 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 11179  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
 10943        BKL        1  1302/inode.c         c016f2f9   697/sched.c
 10798  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  9367  spin_lock        1  1376/sched.c         c0114db3  1306/inode.c
  7230  spin_lock        1  1376/sched.c         c0114db3  1381/sched.c
  6870  spin_lock        1   547/sched.c         c0112fe4  1381/sched.c
  5610   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  5356  spin_lock        0   547/sched.c         c0112fe4  1380/sched.c
  4162   reacqBKL        0  1375/sched.c         c0114d94  1306/inode.c
  4068   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  3335        BKL        0  1302/inode.c         c016f2f9  1380/sched.c
  3161  spin_lock        1  1376/sched.c         c0114db3  1380/sched.c
  3030        BKL        1  1437/namei.c         c014c42f   697/sched.c
  2974        BKL        0  1437/namei.c         c014c42f  1380/sched.c
  2832        BKL        0  1302/inode.c         c016f2f9  1381/sched.c
  2817        BKL        0   927/namei.c         c014b2bf  1380/sched.c
  2713  spin_lock        1   483/dcache.c        c0153efa   520/dcache.c
  2522  spin_lock        1   547/sched.c         c0112fe4  1306/inode.c
  2522        BKL        0   533/inode.c         c016d96d  1381/sched.c
  2508        BKL        0   533/inode.c         c016d96d   929/namei.c

Re: [PATCH] Preemption Latency Measurement Tool

[Dieter Nützel]

Am Donnerstag, 20. September 2001 00:44 schrieb Robert Love:
> Available at:
> http://tech9.net/rml/linux/patch-rml-2.4.9-ac12-preempt-stats-1 and
> http://tech9.net/rml/linux/patch-rml-2.4.10-pre12-preempt-stats-1
> for 2.4.9-ac12 and 2.4.10-pre12, respectively.
>
> This patch is provided thanks to MontaVista (http://mvista.com).

Great, thanks.

Here are some results for 2.4.10-pre12 (Andrea's VM :-)

Athlon II 1 GHz (0.18 µm)
MSI MS-6167 Rev 1.0B (Irongate C4)
640 MB PC100-2-2-2 SDRAM
IBM DDYS 18 GB U160 (on AHA-2940UW)
ReiserFS 3.6 on all partitions

Sound driver is the new kernel one for SB Live! (not ALSA).
No swap used during whole test.

2.4.10-pre12 + patch-rml-2.4.10-pre12-preempt-kernel-1 + 
patch-rml-2.4.10-pre12-preempt-stats-1

Hope my numbers help to find the right reason for the hiccups.
ReiserFS seems _NOT_ to be the culprit for this.
Maybe the scheduler it self?

-Dieter

KDE-2.2.1 noatun running MP3/Ogg-Vorbis
+
time ./dbench 16
Throughput 29.3012 MB/sec (NB=36.6265 MB/sec  293.012 MBit/sec)
7.450u 28.830s 1:13.10 49.6%    0+0k 0+0io 511pf+0w
load: 1140

Worst 20 latency times of 5583 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  5664  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  2586        BKL        1  1302/inode.c         c016f2f9  1381/sched.c
  2329        BKL        0  1302/inode.c         c016f2f9   842/inode.c
  2231        BKL        1  1302/inode.c         c016f2f9   697/sched.c
  2088        BKL        1  1437/namei.c         c014c42f   697/sched.c
  1992        BKL        0    30/inode.c         c016cdf1  1381/sched.c
  1953        BKL        1  1302/inode.c         c016f2f9    52/inode.c
  1952        BKL        0  1302/inode.c         c016f2f9  1380/sched.c
  1947        BKL        1    30/inode.c         c016cdf1   697/sched.c
  1923   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
  1908        BKL        0  1302/inode.c         c016f2f9  1306/inode.c
  1904        BKL        1   452/exit.c          c011af61   697/sched.c
  1892        BKL        1   129/attr.c          c015765d   697/sched.c
  1875        BKL        0  1437/namei.c         c014c42f  1381/sched.c
  1823  spin_lock        0   547/sched.c         c0112fe4  1381/sched.c
  1790   reacqBKL        0  1375/sched.c         c0114d94  1439/namei.c
  1779        BKL        1  1366/namei.c         c014c12c  1381/sched.c
  1762  spin_lock        0   547/sched.c         c0112fe4  1380/sched.c
  1756   reacqBKL        1  1375/sched.c         c0114d94    52/inode.c
  1754        BKL        0   927/namei.c         c014b2bf  1381/sched.c


time ./dbench 32
Throughput 28.0138 MB/sec (NB=35.0172 MB/sec  280.138 MBit/sec)
14.570u 61.520s 2:31.80 50.1%   0+0k 0+0io 911pf+0w
load: 2690

Worst 20 latency times of 8091 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  8347        BKL        1   533/inode.c         c016d96d   842/inode.c
  7808  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  6181        BKL        1  1302/inode.c         c016f2f9  1381/sched.c
  3325        BKL        1  1302/inode.c         c016f2f9   842/inode.c
  3314  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
  3014        BKL        1   129/attr.c          c015765d   697/sched.c
  2956        BKL        1  1302/inode.c         c016f2f9  1380/sched.c
  2954   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  2795        BKL        1   927/namei.c         c014b2bf   697/sched.c
  2750        BKL        1  1302/inode.c         c016f2f9   697/sched.c
  2667        BKL        1    30/inode.c         c016cdf1   697/sched.c
  2623  spin_lock        0  1376/sched.c         c0114db3  1380/sched.c
  2613  spin_lock        0  1376/sched.c         c0114db3  1306/inode.c
  2566   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
  2527        BKL        0  1437/namei.c         c014c42f   697/sched.c
  2526        BKL        0  1437/namei.c         c014c42f  1380/sched.c
  2525  spin_lock        1   547/sched.c         c0112fe4  1380/sched.c
  2513        BKL        0   927/namei.c         c014b2bf  1380/sched.c
  2442        BKL        0    30/inode.c         c016cdf1  1381/sched.c
  2353        BKL        0   452/exit.c          c011af61  1380/sched.c


time ./dbench 40
Throughput 24.664 MB/sec (NB=30.83 MB/sec  246.64 MBit/sec)
18.690u 77.980s 3:35.09 44.9%   0+0k 0+0io 1111pf+0w
load: 3734

Worst 20 latency times of 7340 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  9313  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  9040        BKL        1  1302/inode.c         c016f2f9  1306/inode.c
  8530        BKL        1  1302/inode.c         c016f2f9   842/inode.c
  8268   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  5432  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
  3630   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  3519        BKL        1  1437/namei.c         c014c42f  1380/sched.c
  3387        BKL        0  1302/inode.c         c016f2f9   697/sched.c
  3194  spin_lock        0   547/sched.c         c0112fe4  1380/sched.c
  3180  spin_lock        0   547/sched.c         c0112fe4  1381/sched.c
  3015  spin_lock        1   547/sched.c         c0112fe4   842/inode.c
  2894        BKL        0  1302/inode.c         c016f2f9  1381/sched.c
  2778  spin_lock        1  1376/sched.c         c0114db3  1380/sched.c
  2755        BKL        1  1302/inode.c         c016f2f9  1380/sched.c
  2676        BKL        1   452/exit.c          c011af61   697/sched.c
  2354        BKL        1   533/inode.c         c016d96d   697/sched.c
  2237        BKL        0    30/inode.c         c016cdf1   697/sched.c
  2104        BKL        0  1437/namei.c         c014c42f  1381/sched.c
  2097  spin_lock        0  1376/sched.c         c0114db3  1381/sched.c
  2082        BKL        0    30/inode.c         c016cdf1  1380/sched.c


time ./dbench 48
Throughput 24.5409 MB/sec (NB=30.6761 MB/sec  245.409 MBit/sec)
22.080u 97.560s 4:19.19 46.1%   0+0k 0+0io 1311pf+0w
load: 4622

Worst 20 latency times of 10544 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 12831        BKL        1    30/inode.c         c016cdf1    52/inode.c
 10869   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  9303        BKL        1  1302/inode.c         c016f2f9   697/sched.c
  9145        BKL        1  1302/inode.c         c016f2f9  1306/inode.c
  7984  spin_lock        1   547/sched.c         c0112fe4  1380/sched.c
  5983        BKL        1  1302/inode.c         c016f2f9   842/inode.c
  4947   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  4497  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
  4310  spin_lock        1  1376/sched.c         c0114db3  1380/sched.c
  4290   reacqBKL        0  1375/sched.c         c0114d94  1306/inode.c
  4002  spin_lock        1   547/sched.c         c0112fe4  1381/sched.c
  3822  spin_lock        0  1376/sched.c         c0114db3   697/sched.c
  3683        BKL        0  1302/inode.c         c016f2f9  1380/sched.c
  3422  spin_lock        1   547/sched.c         c0112fe4  1306/inode.c
  3193        BKL        0  1437/namei.c         c014c42f  1380/sched.c
  3006        BKL        1    30/inode.c         c016cdf1  1380/sched.c
  2990        BKL        1   129/attr.c          c015765d   697/sched.c
  2971        BKL        1  1437/namei.c         c014c42f  1381/sched.c
  2939        BKL        0   927/namei.c         c014b2bf  1381/sched.c
  2862        BKL        0  1302/inode.c         c016f2f9  1381/sched.c


KDE-2.2.1 noatun running MP3/Ogg-Vorbis

Worst 20 latency times of 2252 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
   237        BKL        0  2763/buffer.c        c01410aa   697/sched.c
   218  spin_lock        0   547/sched.c         c0112fe4  1381/sched.c
   215   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
   215        BKL        0  2763/buffer.c        c01410aa  1381/sched.c
   205        BKL        0   359/buffer.c        c013d1bc  1381/sched.c
   205       eth1        0   585/irq.c           c010886f   647/irq.c
   149  spin_lock        0   547/sched.c         c0112fe4   697/sched.c
   147        BKL        0   359/buffer.c        c013d1bc   697/sched.c
   135  spin_lock        0  1376/sched.c         c0114db3  1380/sched.c
   130   reacqBKL        0  1375/sched.c         c0114d94   697/sched.c
   111        BKL        0   452/exit.c          c011af61   697/sched.c
   105    unknown        1    76/softirq.c       c011c634   119/softirq.c
    86        BKL        4   712/tty_io.c        c018cf6b   714/tty_io.c
    61  spin_lock        0  1715/dev.c           c01dc4b3  1728/dev.c
    58        BKL        0   301/namei.c         c0149db1   303/namei.c
    56  spin_lock        2   468/netfilter.c     c01e4303   119/softirq.c
    44        BKL        1    59/ioctl.c         c014ea3a   111/ioctl.c
    43        BKL        0  1302/inode.c         c016f2f9  1306/inode.c
    43  spin_lock        1    69/i387.c          c010ca23   227/mmx.c
    42        BKL        1    26/readdir.c       c014ed07    28/readdir.c


Renice -20 both artsd prozesses (the KDE-2.2.1 noatun sound daemon)
help a little bit but there are still some hiccups (1~3 sec)
remaining.

But the system is very responsive (mouse, keyboard).

time ./dbench 16
Throughput 30.8602 MB/sec (NB=38.5752 MB/sec  308.602 MBit/sec)
7.490u 29.350s 1:09.44 53.0%    0+0k 0+0io 511pf+0w

Worst 20 latency times of 5851 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  5518  spin_lock        1  1376/sched.c         c0114db3  1380/sched.c
  2553        BKL        1  1302/inode.c         c016f2f9   697/sched.c
  2284        BKL        0  1302/inode.c         c016f2f9   842/inode.c
  2235   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  2227        BKL        0  1302/inode.c         c016f2f9  1380/sched.c
  2183        BKL        0   927/namei.c         c014b2bf  1306/inode.c
  2055        BKL        1   927/namei.c         c014b2bf   697/sched.c
  2037        BKL        1   452/exit.c          c011af61   697/sched.c
  2032        BKL        0    30/inode.c         c016cdf1   697/sched.c
  2008        BKL        1  1302/inode.c         c016f2f9  1381/sched.c
  1943        BKL        0   927/namei.c         c014b2bf  1439/namei.c
  1926        BKL        1   452/exit.c          c011af61    52/inode.c
  1919  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  1880        BKL        0  1437/namei.c         c014c42f  1381/sched.c
  1865        BKL        0    30/inode.c         c016cdf1  1380/sched.c
  1858  spin_lock        0   547/sched.c         c0112fe4  1380/sched.c
  1849   reacqBKL        0  1375/sched.c         c0114d94  1439/namei.c
  1821   reacqBKL        0  1375/sched.c         c0114d94   697/sched.c
  1774        BKL        1   129/attr.c          c015765d   697/sched.c
  1720        BKL        1  1437/namei.c         c014c42f  1380/sched.c


time ./dbench 48
Throughput 22.85 MB/sec (NB=28.5626 MB/sec  228.5 MBit/sec)
21.840u 98.560s 4:38.30 43.2%   0+0k 0+0io 1311pf+0w

Worst 20 latency times of 8664 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 11179  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
 10943        BKL        1  1302/inode.c         c016f2f9   697/sched.c
 10798  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  9367  spin_lock        1  1376/sched.c         c0114db3  1306/inode.c
  7230  spin_lock        1  1376/sched.c         c0114db3  1381/sched.c
  6870  spin_lock        1   547/sched.c         c0112fe4  1381/sched.c
  5610   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  5356  spin_lock        0   547/sched.c         c0112fe4  1380/sched.c
  4162   reacqBKL        0  1375/sched.c         c0114d94  1306/inode.c
  4068   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  3335        BKL        0  1302/inode.c         c016f2f9  1380/sched.c
  3161  spin_lock        1  1376/sched.c         c0114db3  1380/sched.c
  3030        BKL        1  1437/namei.c         c014c42f   697/sched.c
  2974        BKL        0  1437/namei.c         c014c42f  1380/sched.c
  2832        BKL        0  1302/inode.c         c016f2f9  1381/sched.c
  2817        BKL        0   927/namei.c         c014b2bf  1380/sched.c
  2713  spin_lock        1   483/dcache.c        c0153efa   520/dcache.c
  2522  spin_lock        1   547/sched.c         c0112fe4  1306/inode.c
  2522        BKL        0   533/inode.c         c016d96d  1381/sched.c
  2508        BKL        0   533/inode.c         c016d96d   929/namei.c

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Thu, 2001-09-20 at 02:31, Dieter Nützel wrote:
> Here are some results for 2.4.10-pre12 (Andrea's VM :-)
> 
> Athlon II 1 GHz (0.18 µm)
> MSI MS-6167 Rev 1.0B (Irongate C4)
> 640 MB PC100-2-2-2 SDRAM
> IBM DDYS 18 GB U160 (on AHA-2940UW)
> ReiserFS 3.6 on all partitions
> 
> Sound driver is the new kernel one for SB Live! (not ALSA).
> No swap used during whole test.

Good. I use that sound driver too (I was the one who updated it and
caused the commotion back in 2.4.9 :)

I am interested if you see any different times if you switch to ALSA,
though.

> 2.4.10-pre12 + patch-rml-2.4.10-pre12-preempt-kernel-1 + 
> patch-rml-2.4.10-pre12-preempt-stats-1
> 
> Hope my numbers help to find the right reason for the hiccups.
> ReiserFS seems _NOT_ to be the culprit for this.
> Maybe the scheduler it self?

The scheduler does hold some spinlocks.  So does VM.  I am working on
some ideas to tackle the highest of the worst-case spinlocks. Stay
tuned.

> KDE-2.2.1 noatun running MP3/Ogg-Vorbis
>
> time ./dbench 16
> Throughput 29.3012 MB/sec (NB=36.6265 MB/sec  293.012 MBit/sec)
> 7.450u 28.830s 1:13.10 49.6%    0+0k 0+0io 511pf+0w
> load: 1140
> 
> Worst 20 latency times of 5583 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
>   5664  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
> <snip>

5ms is not an issue at all, especially for a worst case spinlock... no
problem here.

> time ./dbench 40
> Throughput 24.664 MB/sec (NB=30.83 MB/sec  246.64 MBit/sec)
> 18.690u 77.980s 3:35.09 44.9%   0+0k 0+0io 1111pf+0w
> load: 3734
> 
> Worst 20 latency times of 7340 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
>   9313  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
> <snip>

We are getting higher, but still not an issue.  I'll theorize below why
I think it is increasing...

> time ./dbench 48
> Throughput 24.5409 MB/sec (NB=30.6761 MB/sec  245.409 MBit/sec)
> 22.080u 97.560s 4:19.19 46.1%   0+0k 0+0io 1311pf+0w
> load: 4622
> 
> Worst 20 latency times of 10544 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
>  12831        BKL        1    30/inode.c         c016cdf1    52/inode.c
>  10869   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
> <snip>

Now we are above what I consider perfect (10ms), but I still am not
concenrned until 15-20ms times.  The list I am compiling is of much
higher problems, so you are fine here too.

The reason I think it jumps during the higher threaded dbenchs is for
the obvious reason - more I/O.  This is causing more seeks and longer
tranversing of the I/O queue.

> KDE-2.2.1 noatun running MP3/Ogg-Vorbis
> 
> Worst 20 latency times of 2252 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
>    237        BKL        0  2763/buffer.c        c01410aa   697/sched.c
> <snip>

0.2ms is ideal for any system :)


> Renice -20 both artsd prozesses (the KDE-2.2.1 noatun sound daemon)
> help a little bit but there are still some hiccups (1~3 sec)
> remaining.

You see 1-3second skips in the audio? With the 0.2ms latencies? Grr,
odd.

> But the system is very responsive (mouse, keyboard).
> 
> time ./dbench 16
> Throughput 30.8602 MB/sec (NB=38.5752 MB/sec  308.602 MBit/sec)
> 7.490u 29.350s 1:09.44 53.0%    0+0k 0+0io 511pf+0w
> 
> Worst 20 latency times of 5851 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
>   5518  spin_lock        1  1376/sched.c         c0114db3  1380/sched.c
> <snip>
>
> time ./dbench 48
> Throughput 22.85 MB/sec (NB=28.5626 MB/sec  228.5 MBit/sec)
> 21.840u 98.560s 4:38.30 43.2%   0+0k 0+0io 1311pf+0w
> 
> Worst 20 latency times of 8664 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
>  11179  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
> <snip>

Still OK.

Thanks for the feedback.

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption patch 2.4.9-ac12

[Robert Love]

On Thu, 2001-09-20 at 17:11, safemode wrote:
> ps.  Rob, i sent a few emails about this and my latencies.  

I just sent you some replies...

I know, and I am working on it.  You are one of the few people reporting
any problems, and the only one with problems like this.  This is not to
say `its you' but just that it is making it hard to figure out, but I am
trying.

I have a boatload of emails to respond to, and most of them were sent
just to me and not CC the list so people just have to wait for me.

I don't get paid to do this, and there are only so many hours until my
girlfriend gets mad :)

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Andrea Arcangeli]

Those inodes lines reminded me one thing, you may want to give it a try:

--- 2.4.10pre12aa1/fs/inode.c.~1~	Thu Sep 20 01:44:07 2001
+++ 2.4.10pre12aa1/fs/inode.c	Thu Sep 20 08:37:33 2001
@@ -295,6 +295,12 @@
 			 * so we have to start looking from the list head.
 			 */
 			tmp = head;
+
+			if (unlikely(current->need_resched)) {
+				spin_unlock(&inode_lock);
+				schedule();
+				spin_lock(&inode_lock);
+			}
 		}
 	}
 
Andrea

Re: [PATCH] Preemption Latency Measurement Tool

[Dieter Nützel]

Am Donnerstag, 20. September 2001 08:41 schrieb Andrea Arcangeli:
> Those inodes lines reminded me one thing, you may want to give it a try:
>
> --- 2.4.10pre12aa1/fs/inode.c.~1~	Thu Sep 20 01:44:07 2001
> +++ 2.4.10pre12aa1/fs/inode.c	Thu Sep 20 08:37:33 2001
> @@ -295,6 +295,12 @@
>  			 * so we have to start looking from the list head.
>  			 */
>  			tmp = head;
> +
> +			if (unlikely(current->need_resched)) {
> +				spin_unlock(&inode_lock);
> +				schedule();
> +				spin_lock(&inode_lock);
> +			}
>  		}
>  	}
>

You've forgotten a one liner.

  #include <linux/locks.h>
+#include <linux/compiler.h>

But this is not enough. Even with reniced artsd (-20).
Some shorter hiccups (0.5~1 sec).

-Dieter

dbench 16 (without renice)
Throughput 31.0483 MB/sec (NB=38.8104 MB/sec  310.483 MBit/sec)
7.270u 29.290s 1:09.03 52.9%    0+0k 0+0io 511pf+0w
load: 1034

Worst 20 latency times of 4261 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  4617   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
  2890  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  2072        BKL        1   533/inode.c         c016d9cd   697/sched.c
  2062        BKL        1  1302/inode.c         c016f359    52/inode.c
  2039        BKL        1  1302/inode.c         c016f359   697/sched.c
  1908        BKL        0  1302/inode.c         c016f359   929/namei.c
  1870        BKL        0  1302/inode.c         c016f359  1381/sched.c
  1859  spin_lock        0   547/sched.c         c0112fe4   697/sched.c
  1834        BKL        0    30/inode.c         c016ce51  1381/sched.c
  1834        BKL        1  1302/inode.c         c016f359  1380/sched.c
  1833        BKL        1  1437/namei.c         c014c42f   697/sched.c
  1831        BKL        1   452/exit.c          c011af61   697/sched.c
  1820        BKL        1  1437/namei.c         c014c42f   842/inode.c
  1797        BKL        0  1302/inode.c         c016f359   842/inode.c
  1741  spin_lock        0   547/sched.c         c0112fe4  1380/sched.c
  1696   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  1690        BKL        1  1437/namei.c         c014c42f  1380/sched.c
  1652        BKL        1   533/inode.c         c016d9cd  1380/sched.c
  1648        BKL        1  1870/namei.c         c014d420  1381/sched.c
  1643        BKL        0   927/namei.c         c014b2bf  1381/sched.c


dbench 16 (artsd renice -20)
Throughput 32.8102 MB/sec (NB=41.0127 MB/sec  328.102 MBit/sec)
7.490u 28.570s 1:05.38 55.1%    0+0k 0+0io 511pf+0w
load: 963

Worst 20 latency times of 4649 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  4828  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  2446  spin_lock        1  1376/sched.c         c0114db3  1380/sched.c
  2237   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  2205   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  2205        BKL        1  1302/inode.c         c016f359  1380/sched.c
  2076        BKL        0  1302/inode.c         c016f359  1381/sched.c
  2065  spin_lock        0   547/sched.c         c0112fe4   697/sched.c
  2048        BKL        0    30/inode.c         c016ce51   697/sched.c
  2040        BKL        1   452/exit.c          c011af61   697/sched.c
  1982        BKL        0  1437/namei.c         c014c42f  1381/sched.c
  1953        BKL        0  1437/namei.c         c014c42f  1380/sched.c
  1942        BKL        1  1302/inode.c         c016f359   697/sched.c
  1847        BKL        0  1302/inode.c         c016f359   842/inode.c
  1761        BKL        0  1437/namei.c         c014c42f   697/sched.c
  1734   reacqBKL        1  1375/sched.c         c0114d94    52/inode.c
  1708        BKL        0    30/inode.c         c016ce51  1306/inode.c
  1705        BKL        0   927/namei.c         c014b2bf  1381/sched.c
  1688        BKL        0  1302/inode.c         c016f359   929/namei.c
  1679        BKL        1  1437/namei.c         c014c42f   842/inode.c
  1648        BKL        1  1302/inode.c         c016f359  1439/namei.c


dbench 48 looks like this (without renice)
Throughput 24.5736 MB/sec (NB=30.717 MB/sec  245.736 MBit/sec)
23.250u 89.760s 4:18.85 43.6%   0+0k 0+0io 1311pf+0w
load: 4429

Worst 20 latency times of 8033 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 10856  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
 10705        BKL        1  1302/inode.c         c016f359   697/sched.c
 10577  spin_lock        1  1376/sched.c         c0114db3   303/namei.c
  9427  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
  8526   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  4492   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  4171        BKL        1  1302/inode.c         c016f359  1381/sched.c
  3902   reacqBKL        0  1375/sched.c         c0114d94  1306/inode.c
  3376  spin_lock        0  1376/sched.c         c0114db3  1380/sched.c
  3132        BKL        0  1302/inode.c         c016f359  1380/sched.c
  3096  spin_lock        1   547/sched.c         c0112fe4  1380/sched.c
  2808        BKL        0    30/inode.c         c016ce51  1381/sched.c
  2807  spin_lock        0   547/sched.c         c0112fe4  1381/sched.c
  2782        BKL        0   452/exit.c          c011af61  1380/sched.c
  2631  spin_lock        0   483/dcache.c        c0153efa   520/dcache.c
  2533        BKL        0   533/inode.c         c016d9cd  1380/sched.c
  2489        BKL        0   927/namei.c         c014b2bf  1380/sched.c
  2389        BKL        1   452/exit.c          c011af61    52/inode.c
  2369        BKL        1  1302/inode.c         c016f359   842/inode.c
  2327        BKL        1    30/inode.c         c016ce51  1380/sched.c

Re: [PATCH] Preemption Latency Measurement Tool

[Andrea Arcangeli]

On Thu, Sep 20, 2001 at 09:57:50AM +0200, Dieter Nützel wrote:
> Am Donnerstag, 20. September 2001 08:41 schrieb Andrea Arcangeli:
> > Those inodes lines reminded me one thing, you may want to give it a try:
> >
> > --- 2.4.10pre12aa1/fs/inode.c.~1~	Thu Sep 20 01:44:07 2001
> > +++ 2.4.10pre12aa1/fs/inode.c	Thu Sep 20 08:37:33 2001
> > @@ -295,6 +295,12 @@
> >  			 * so we have to start looking from the list head.
> >  			 */
> >  			tmp = head;
> > +
> > +			if (unlikely(current->need_resched)) {
> > +				spin_unlock(&inode_lock);
> > +				schedule();
> > +				spin_lock(&inode_lock);
> > +			}
> >  		}
> >  	}
> >
> 
> You've forgotten a one liner.
> 
>   #include <linux/locks.h>
> +#include <linux/compiler.h>

woops, didn't trapped it because of gcc 3.0.2. thanks.

> But this is not enough. Even with reniced artsd (-20).
> Some shorter hiccups (0.5~1 sec).

I'm not familiar with the output of the latency bench, but I actually
read "4617" usec as the worst latency, that means 4msec, not 500/1000
msec.

> Worst 20 latency times of 4261 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
    ^^^^
>   4617   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
    ^^^^
>   2890  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
>   2072        BKL        1   533/inode.c         c016d9cd   697/sched.c
>   2062        BKL        1  1302/inode.c         c016f359    52/inode.c
>   2039        BKL        1  1302/inode.c         c016f359   697/sched.c
>   1908        BKL        0  1302/inode.c         c016f359   929/namei.c
>   1870        BKL        0  1302/inode.c         c016f359  1381/sched.c
>   1859  spin_lock        0   547/sched.c         c0112fe4   697/sched.c
>   1834        BKL        0    30/inode.c         c016ce51  1381/sched.c
>   1834        BKL        1  1302/inode.c         c016f359  1380/sched.c
>   1833        BKL        1  1437/namei.c         c014c42f   697/sched.c
>   1831        BKL        1   452/exit.c          c011af61   697/sched.c
>   1820        BKL        1  1437/namei.c         c014c42f   842/inode.c
>   1797        BKL        0  1302/inode.c         c016f359   842/inode.c
>   1741  spin_lock        0   547/sched.c         c0112fe4  1380/sched.c
>   1696   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
>   1690        BKL        1  1437/namei.c         c014c42f  1380/sched.c
>   1652        BKL        1   533/inode.c         c016d9cd  1380/sched.c
>   1648        BKL        1  1870/namei.c         c014d420  1381/sched.c
>   1643        BKL        0   927/namei.c         c014b2bf  1381/sched.c


those are kernel addresses, can you resolve them via System.map rather
than trying to find their start/end line number?

> Worst 20 latency times of 8033 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
>  10856  spin_lock        1  1376/sched.c         c0114db3   697/sched.c

with dbench 48 we gone to 10msec latency as far I can see (still far
from 0.5~1 sec). dbench 48 is longer so more probability to get the
higher latency, and it does more I/O, probably also seeks more, so thre
are many variables (slower insection in I/O queues first of all, etcll).
However 10msec isn't that bad, it means 100hz, something that the human
eye cannot see. 0.5~1 sec would been horribly bad latency instead.. :)

>  10705        BKL        1  1302/inode.c         c016f359   697/sched.c
>  10577  spin_lock        1  1376/sched.c         c0114db3   303/namei.c
>   9427  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
>   8526   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
>   4492   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
>   4171        BKL        1  1302/inode.c         c016f359  1381/sched.c
>   3902   reacqBKL        0  1375/sched.c         c0114d94  1306/inode.c
>   3376  spin_lock        0  1376/sched.c         c0114db3  1380/sched.c
>   3132        BKL        0  1302/inode.c         c016f359  1380/sched.c
>   3096  spin_lock        1   547/sched.c         c0112fe4  1380/sched.c
>   2808        BKL        0    30/inode.c         c016ce51  1381/sched.c
>   2807  spin_lock        0   547/sched.c         c0112fe4  1381/sched.c
>   2782        BKL        0   452/exit.c          c011af61  1380/sched.c
>   2631  spin_lock        0   483/dcache.c        c0153efa   520/dcache.c
>   2533        BKL        0   533/inode.c         c016d9cd  1380/sched.c
>   2489        BKL        0   927/namei.c         c014b2bf  1380/sched.c
>   2389        BKL        1   452/exit.c          c011af61    52/inode.c
>   2369        BKL        1  1302/inode.c         c016f359   842/inode.c
>   2327        BKL        1    30/inode.c         c016ce51  1380/sched.c


Andrea

Re: [PATCH] Preemption Latency Measurement Tool

[george anzinger]

Andrea Arcangeli wrote:
> 
> On Thu, Sep 20, 2001 at 09:57:50AM +0200, Dieter Nützel wrote:
> > Am Donnerstag, 20. September 2001 08:41 schrieb Andrea Arcangeli:
> > > Those inodes lines reminded me one thing, you may want to give it a try:
> > >
> > > --- 2.4.10pre12aa1/fs/inode.c.~1~   Thu Sep 20 01:44:07 2001
> > > +++ 2.4.10pre12aa1/fs/inode.c       Thu Sep 20 08:37:33 2001
> > > @@ -295,6 +295,12 @@
> > >                      * so we have to start looking from the list head.
> > >                      */
> > >                     tmp = head;
> > > +
> > > +                   if (unlikely(current->need_resched)) {
> > > +                           spin_unlock(&inode_lock);
> > > +                           schedule();
> > > +                           spin_lock(&inode_lock);
> > > +                   }
> > >             }
> > >     }
> > >
Be warned, while the above will improve latency, it will not improve the
numbers reported by the tool.  The reason is that the tool looks at
actual preemption disable times, so it does not care if "need_resched"
is set or not.  This means that, in the case where need_resched is not
set, the tool would report a long latency as if the conditional lock
break code was not present.  To get the above code into the tools
purview, you could either code it without the conditional or, better,
put the whole thing into a macro ( I think Ingo called it
"conditional_schedule()") and put the instrumentation stuff in the
macro.  Also, in the case of a system with the preemption patch, the
schedule is not needed unless the BKL is also held.

> >
> > You've forgotten a one liner.
> >
> >   #include <linux/locks.h>
> > +#include <linux/compiler.h>
> 
> woops, didn't trapped it because of gcc 3.0.2. thanks.
> 
> > But this is not enough. Even with reniced artsd (-20).
> > Some shorter hiccups (0.5~1 sec).
> 
> I'm not familiar with the output of the latency bench, but I actually
> read "4617" usec as the worst latency, that means 4msec, not 500/1000
> msec.
> 
> > Worst 20 latency times of 4261 measured in this period.
> >   usec      cause     mask   start line/file      address   end line/file
>     ^^^^
> >   4617   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
>     ^^^^
~snip
> 
> those are kernel addresses, can you resolve them via System.map rather
> than trying to find their start/end line number?

Uh, trying to find???  These are the names and line numbers provided by
the PPC macros.  The only time the address is helpful is when the bad
guy is hiding in an "inline" in a header file.  Still, is there a simple
script to get the function/offset from the System.map?  We could then
post process with a simple bash/sed script.

> 
> > Worst 20 latency times of 8033 measured in this period.
> >   usec      cause     mask   start line/file      address   end line/file
> >  10856  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
> 
> with dbench 48 we gone to 10msec latency as far I can see (still far
> from 0.5~1 sec). dbench 48 is longer so more probability to get the
> higher latency, and it does more I/O, probably also seeks more, so thre
> are many variables (slower insection in I/O queues first of all, etcll).
> However 10msec isn't that bad, it means 100hz, something that the human
> eye cannot see. 0.5~1 sec would been horribly bad latency instead.. :)

Ah, but we would REALLY like to see it below 1msec.
~snip
 
George

Re: [PATCH] Preemption Latency Measurement Tool

[Randy.Dunlap]

george anzinger wrote:
> 
> Andrea Arcangeli wrote:
> >
> > those are kernel addresses, can you resolve them via System.map rather
> > than trying to find their start/end line number?
> 
> Uh, trying to find???  These are the names and line numbers provided by
> the PPC macros.  The only time the address is helpful is when the bad
> guy is hiding in an "inline" in a header file.  Still, is there a simple
> script to get the function/offset from the System.map?  We could then
> post process with a simple bash/sed script.

I posted one earlier today (Perl).  It's at
http://www.osdlab.org/sw_resources/scripts/ksysmap .

~Randy

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Thu, 2001-09-20 at 04:21, Andrea Arcangeli wrote:
> > You've forgotten a one liner.
> > 
> >   #include <linux/locks.h>
> > +#include <linux/compiler.h>
> 
> woops, didn't trapped it because of gcc 3.0.2. thanks.
> 
> > But this is not enough. Even with reniced artsd (-20).
> > Some shorter hiccups (0.5~1 sec).
> 
> I'm not familiar with the output of the latency bench, but I actually
> read "4617" usec as the worst latency, that means 4msec, not 500/1000
> msec.

Right, the patch is returning the length preemption was unavailable
(which is when a lock is held) in us. So it is indded 4ms.

But, I think Dieter is saying he _sees_ 0.5~1s latencies (in the form of
audio skips).  This is despite the 4ms locks being held.

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Dieter Nützel]

Am Donnerstag, 20. September 2001 23:10 schrieb Robert Love:
> On Thu, 2001-09-20 at 04:21, Andrea Arcangeli wrote:
> > > You've forgotten a one liner.
> > >
> > >   #include <linux/locks.h>
> > > +#include <linux/compiler.h>
> >
> > woops, didn't trapped it because of gcc 3.0.2. thanks.
> >
> > > But this is not enough. Even with reniced artsd (-20).
> > > Some shorter hiccups (0.5~1 sec).
> >
> > I'm not familiar with the output of the latency bench, but I actually
> > read "4617" usec as the worst latency, that means 4msec, not 500/1000
> > msec.
>
> Right, the patch is returning the length preemption was unavailable
> (which is when a lock is held) in us. So it is indded 4ms.
>
> But, I think Dieter is saying he _sees_ 0.5~1s latencies (in the form of
> audio skips).  This is despite the 4ms locks being held.

Yes, that's the case. During dbench 16,32,40,48, etc...

-Dieter

Re: [PATCH] Preemption Latency Measurement Tool

[Oliver Xymoron]

On Thu, 20 Sep 2001, Dieter Nützel wrote:

> Am Donnerstag, 20. September 2001 23:10 schrieb Robert Love:
> > On Thu, 2001-09-20 at 04:21, Andrea Arcangeli wrote:
> > > > You've forgotten a one liner.
> > > >
> > > >   #include <linux/locks.h>
> > > > +#include <linux/compiler.h>
> > >
> > > woops, didn't trapped it because of gcc 3.0.2. thanks.
> > >
> > > > But this is not enough. Even with reniced artsd (-20).
> > > > Some shorter hiccups (0.5~1 sec).
> > >
> > > I'm not familiar with the output of the latency bench, but I actually
> > > read "4617" usec as the worst latency, that means 4msec, not 500/1000
> > > msec.
> >
> > Right, the patch is returning the length preemption was unavailable
> > (which is when a lock is held) in us. So it is indded 4ms.
> >
> > But, I think Dieter is saying he _sees_ 0.5~1s latencies (in the form of
> > audio skips).  This is despite the 4ms locks being held.
>
> Yes, that's the case. During dbench 16,32,40,48, etc...

You might actually be waiting on disk I/O and not blocked.

Does your audio source depend on any files (eg mp3s) and if so, could they
be moved to a ramfs? Do the skips go away then?

--
 "Love the dolphins," she advised him. "Write by W.A.S.T.E.."

Re: [PATCH] Preemption Latency Measurement Tool

[Dieter Nützel]

Am Freitag, 21. September 2001 00:03 schrieb Oliver Xymoron:
> On Thu, 20 Sep 2001, Dieter Nützel wrote:
> > Am Donnerstag, 20. September 2001 23:10 schrieb Robert Love:
> > > On Thu, 2001-09-20 at 04:21, Andrea Arcangeli wrote:
> > > > > You've forgotten a one liner.
> > > > >
> > > > >   #include <linux/locks.h>
> > > > > +#include <linux/compiler.h>
> > > >
> > > > woops, didn't trapped it because of gcc 3.0.2. thanks.
> > > >
> > > > > But this is not enough. Even with reniced artsd (-20).
> > > > > Some shorter hiccups (0.5~1 sec).
> > > >
> > > > I'm not familiar with the output of the latency bench, but I actually
> > > > read "4617" usec as the worst latency, that means 4msec, not 500/1000
> > > > msec.
> > >
> > > Right, the patch is returning the length preemption was unavailable
> > > (which is when a lock is held) in us. So it is indded 4ms.
> > >
> > > But, I think Dieter is saying he _sees_ 0.5~1s latencies (in the form
> > > of audio skips).  This is despite the 4ms locks being held.
> >
> > Yes, that's the case. During dbench 16,32,40,48, etc...
>
> You might actually be waiting on disk I/O and not blocked.
>
> Does your audio source depend on any files (eg mp3s) and if so, could they
> be moved to a ramfs? Do the skips go away then?

Good point.

I've copied one video (MP2) and one Ogg-Vorbis file into /dev/shm.
Little bit better but hiccup still there :-(

dbench 16
Throughput 25.7613 MB/sec (NB=32.2016 MB/sec  257.613 MBit/sec)
7.500u 29.870s 1:22.99 45.0%    0+0k 0+0io 511pf+0w

Worst 20 latency times of 3298 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 11549  spin_lock        1   678/inode.c         c01566d7   704/inode.c

c01566a0 T prune_icache
c01566d7 ..... <<<<<
c0156800 T shrink_icache_memory

  7395  spin_lock        1   291/buffer.c        c014151c   285/buffer.c

c0141400 T kupdate
c014151c ..... <<<<<
c0141610 T set_buffer_async_io

  7372  spin_lock        1   291/buffer.c        c01413e3   280/buffer.c

c0141290 T bdflush
c01413e3 ..... <<<<<
c0141400 T kupdate

  5702   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c

c0114d60 T preempt_schedule
c0114d94 ..... <<<<<
c0114e10 T wake_up_process

  4744        BKL        0  2763/buffer.c        c01410aa   697/sched.c

c0141080 t sync_old_buffers
c01410aa ..... <<<<<
c01411b0 T block_sync_page

  4695  spin_lock        1   291/buffer.c        c014151c   280/buffer.c
  4551  spin_lock        1  1376/sched.c         c0114db3  1380/sched.c
  4466  spin_lock        1   547/sched.c         c0112fe4  1306/inode.c
  4464  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  4146   reacqBKL        1  1375/sched.c         c0114d94   842/inode.c
  4131  spin_lock        0   547/sched.c         c0112fe4   697/sched.c
  3900   reacqBKL        1  1375/sched.c         c0114d94   929/namei.c
  3390  spin_lock        1   547/sched.c         c0112fe4  1439/namei.c
  3191        BKL        0  1302/inode.c         c016f359   842/inode.c
  2866        BKL        0  1302/inode.c         c016f359  1381/sched.c
  2803   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
  2762        BKL        0    30/inode.c         c016ce51    52/inode.c
  2633        BKL        0  2763/buffer.c        c01410aa  1380/sched.c
  2629        BKL        0  2763/buffer.c        c01410aa  1381/sched.c
  2466  spin_lock        1   468/vmscan.c        c0133c35   415/vmscan.c

*******************************************************

dbench 16 + renice artsd -20 works
GREAT!

*******************************************************

dbench 32 and above + renice artsd -20 fail

Writing this during dbench 32 ...:-)))

dbench 32 + renice artsd -20
Throughput 18.5102 MB/sec (NB=23.1378 MB/sec  185.102 MBit/sec)
15.240u 63.070s 3:49.21 34.1%   0+0k 0+0io 911pf+0w

Worst 20 latency times of 3679 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 17625  spin_lock        1   678/inode.c         c01566d7   704/inode.c

c01566a0 T prune_icache
c01566d7 ..... <<<<<
c0156800 T shrink_icache_memory

  9829  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
  9186  spin_lock        1   547/sched.c         c0112fe4  1306/inode.c
  7447   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  7097        BKL        1  1302/inode.c         c016f359   697/sched.c
  5974  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  5231        BKL        1  1437/namei.c         c014c42f   697/sched.c
  5192  spin_lock        0  1376/sched.c         c0114db3  1380/sched.c
  4992   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  4875  spin_lock        1   305/dcache.c        c0153acd    80/dcache.c
  4390        BKL        1   927/namei.c         c014b2bf   929/namei.c
  3616   reacqBKL        0  1375/sched.c         c0114d94  1306/inode.c
  3498  spin_lock        1   547/sched.c         c0112fe4   929/namei.c
  3427  spin_lock        1   547/sched.c         c0112fe4   842/inode.c
  3323        BKL        1  1302/inode.c         c016f359  1306/inode.c
  3165        BKL        1   452/exit.c          c011af61   697/sched.c
  3059  spin_lock        1   305/dcache.c        c0153acd    86/dcache.c
  3016        BKL        1   533/inode.c         c016d9cd  1306/inode.c
  2943        BKL        1  1302/inode.c         c016f359    52/inode.c
  2904  spin_lock        1   547/sched.c         c0112fe4  1439/namei.c

Thanks,
	Dieter

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Thu, 2001-09-20 at 18:51, Dieter Nützel wrote:
> > Does your audio source depend on any files (eg mp3s) and if so, could they
> > be moved to a ramfs? Do the skips go away then?
> 
> Good point.
> 
> I've copied one video (MP2) and one Ogg-Vorbis file into /dev/shm.
> Little bit better but hiccup still there :-(

As I've been saying, the problem really shouldn't be disk I/O.  I would
think (and really hope) the readahead code can fit a little mp3 in
memory.  Even if not, its a quick read to load it.  The continued blips
you see are caused by something, well, continual :)

> dbench 16
> Throughput 25.7613 MB/sec (NB=32.2016 MB/sec  257.613 MBit/sec)
> 7.500u 29.870s 1:22.99 45.0%    0+0k 0+0io 511pf+0w
> 
> Worst 20 latency times of 3298 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
>  11549  spin_lock        1   678/inode.c         c01566d7   704/inode.c

A single 11ms latency is not bad.  Again, this looks OK.

> *******************************************************
> 
> dbench 16 + renice artsd -20 works
> GREAT!
> 
> *******************************************************

Great :)

> dbench 32 and above + renice artsd -20 fail
> 
> Writing this during dbench 32 ...:-)))
> 
> dbench 32 + renice artsd -20
> Throughput 18.5102 MB/sec (NB=23.1378 MB/sec  185.102 MBit/sec)
> 15.240u 63.070s 3:49.21 34.1%   0+0k 0+0io 911pf+0w
> 
> Worst 20 latency times of 3679 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
>  17625  spin_lock        1   678/inode.c         c01566d7   704/inode.c

What do you mean failed?

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[george anzinger]

[-- Attachment #1: Type: text/plain, Size: 2786 bytes --]

Robert Love wrote:
> 
> On Thu, 2001-09-20 at 18:51, Dieter Nützel wrote:
> > > Does your audio source depend on any files (eg mp3s) and if so, could they
> > > be moved to a ramfs? Do the skips go away then?
> >
> > Good point.
> >
> > I've copied one video (MP2) and one Ogg-Vorbis file into /dev/shm.
> > Little bit better but hiccup still there :-(
> 
> As I've been saying, the problem really shouldn't be disk I/O.  I would
> think (and really hope) the readahead code can fit a little mp3 in
> memory.  Even if not, its a quick read to load it.  The continued blips
> you see are caused by something, well, continual :)
> 
Are you running your application at some real time priority?  I suspect
that, when dbench starts, it floods the system with a lot of new tasks
and the system must visit each one until it gets back to your ap.  Nice
will only do so much here.  Real time priority is the way to go. 
Attached are a couple of small programs to help here.  "rt" runs a given
ap at a given priority.  I.e. > rt 10 foo, runs foo at priority 10. 
(There are more options, try rt -h.)  getrt reports the priority of a
task.  If you do something like > rt 10 bash   everything you run from
the new bash prompt will be at priority 10.  You must be root to run rt
:(

George

> > dbench 16
> > Throughput 25.7613 MB/sec (NB=32.2016 MB/sec  257.613 MBit/sec)
> > 7.500u 29.870s 1:22.99 45.0%    0+0k 0+0io 511pf+0w
> >
> > Worst 20 latency times of 3298 measured in this period.
> >   usec      cause     mask   start line/file      address   end line/file
> >  11549  spin_lock        1   678/inode.c         c01566d7   704/inode.c
> 
> A single 11ms latency is not bad.  Again, this looks OK.
> 
> > *******************************************************
> >
> > dbench 16 + renice artsd -20 works
> > GREAT!
> >
> > *******************************************************
> 
> Great :)
> 
> > dbench 32 and above + renice artsd -20 fail
> >
> > Writing this during dbench 32 ...:-)))
> >
> > dbench 32 + renice artsd -20
> > Throughput 18.5102 MB/sec (NB=23.1378 MB/sec  185.102 MBit/sec)
> > 15.240u 63.070s 3:49.21 34.1%   0+0k 0+0io 911pf+0w
> >
> > Worst 20 latency times of 3679 measured in this period.
> >   usec      cause     mask   start line/file      address   end line/file
> >  17625  spin_lock        1   678/inode.c         c01566d7   704/inode.c
> 
> What do you mean failed?
> 
> --
> Robert M. Love
> rml at ufl.edu
> rml at tech9.net
> 
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/

[-- Attachment #2: rt.c --]
[-- Type: text/plain, Size: 3205 bytes --]



/*
   rt - a utility to set the realtime priority and scheduling policy
*/

/* includes */
#include <stdio.h>
#include <stdlib.h>
#include <sched.h>
#include <unistd.h>
#define _GNU_LIBRARY__
#include <getopt.h>

/* defines */

#define RUNSTRING "usage:  rt [-f] [-v] prio [--] runstring  \n \
 or:   rt [-f] [-v] -p PID prio\\ \n\n \
where: prio specifies the realtime priority  \n \
       -f set scheduling policy to SCHED_FIFO \n \
       -v turns on verbose mode. \n \
       -p PID specifies an existing process to modify \n \
       runstring is a process and parameters \n \
       (use '--' if runstring contains options). \n"

#define POLICY(x)  x ? x-1 ? "SCHED_RR" : "SCHED_FIFO" : "SCHED_OTHER"

/* prototypes */
void print_usage(char *[]);

/* globals */
int verbose=0;  /* 0=none, !0=verbose */


main(int argc, char *argv[])
{
        struct sched_param prio_struct;
        int policy = -1;
        int pid = 0;
        int pidopt = 0;
        int optprobs = 0; /* problems parsing? */
        
        int  c;         /* generic single character */

        /* "standard" option parsing... */
        while ( (c=getopt(argc, argv, "+fp:v?")) != EOF)
        {
        switch (c) {
                case 'f':       /* set FIFO mode */
                        policy = SCHED_FIFO;
                        break;
                case 'p':       /* read PID */  
                        sscanf(optarg,"%d",&pid); 
                        pidopt=1;
                        break;
                case 'v':
                        verbose=1;      /* verbosity */
                        break;
                case '?':       /* help? */
                        printf("%s",RUNSTRING);
                        exit(0);
                default:        /* something went wrong */
                        optprobs=1;     /* we'll deal with this problem later */
                        break;
                }
        }

        if (optprobs) {
                fprintf(stderr,RUNSTRING);
                exit(1);
        }


        if((argc - optind) < 2-pidopt) {
                print_usage(argv);
        }

        sscanf(argv[optind], "%d", &(prio_struct.sched_priority));

        /* sanity checking... */
        if ( (prio_struct.sched_priority != 0) && (policy < 0 ) ) {
                policy=SCHED_RR;
                if (verbose)
                  printf("Defaulting sched policy to %s.\n", POLICY(policy));
        }

        if ( (prio_struct.sched_priority == 0 ) && (policy != SCHED_OTHER) ) {
                policy=SCHED_OTHER;
                fprintf(stderr,"Priority of %d implies sched policy of %s.\n",
                        prio_struct.sched_priority,  POLICY(policy)); 
        }


        policy = (prio_struct.sched_priority)? policy : SCHED_OTHER;
        if( sched_setscheduler(pid,policy,&prio_struct)){
                perror("Priority out of range");
                print_usage(argv);
        }
        if ( pid ) exit(0);
        argv+=optind;   /* adjust argv to point to the runstring */
        argv++;
        execvp(argv[0],argv);
        perror("exec failed..");
}

void print_usage(char * who[])
{
        printf("%s",RUNSTRING);
        exit (1);
}


[-- Attachment #3: getrt.c --]
[-- Type: text/plain, Size: 1336 bytes --]

#include <sched.h>
#include <stdlib.h>

main(int args,char* argc[])
{
        struct sched_param p;
        pid_t pid;

        int policy;
        int prio,max_prio,max_rt_prio;
        char * cpolicy;

        if (args < 2) {
                pid = 0;
        }else{
                pid = atoi(argc[1]);
        }
        policy = sched_getscheduler(pid);
        sched_getparam(pid,&p);
        prio = p.sched_priority;
        max_prio = sched_get_priority_max(policy);
        max_rt_prio = sched_get_priority_max(SCHED_FIFO);

        switch(policy){
        case SCHED_OTHER:
                cpolicy = "SCHED_OTHER";
                break;
        case SCHED_RR:
                cpolicy = "SCHED_RR";
                break;
        case SCHED_FIFO:
                cpolicy = "SCHED_FIFO";
                break;
        default:
                perror("sched_getscheduler");
                exit(1);
        }
                
        if (policy == SCHED_OTHER){
                printf("%s at priority %d (MAX_PRIO(%s) = %d, MAX_PRIO(SCHED_FIFO) = %d)\n",
                       cpolicy,      prio,       cpolicy,max_prio,               max_rt_prio);
        }else{
                printf("%s at priority %d (MAX_PRIO(%s) = %d)\n",
                       cpolicy,       prio,      cpolicy, max_prio);
        }
        exit(0);
}

Re: [PATCH] Preemption Latency Measurement Tool

[Dieter Nützel]

Am Freitag, 21. September 2001 17:48 schrieb george anzinger:
> Robert Love wrote:
> > On Thu, 2001-09-20 at 18:51, Dieter Nützel wrote:
> > > > Does your audio source depend on any files (eg mp3s) and if so, could
> > > > they be moved to a ramfs? Do the skips go away then?
> > >
> > > Good point.
> > >
> > > I've copied one video (MP2) and one Ogg-Vorbis file into /dev/shm.
> > > Little bit better but hiccup still there :-(
> >
> > As I've been saying, the problem really shouldn't be disk I/O.  I would
> > think (and really hope) the readahead code can fit a little mp3 in
> > memory.  Even if not, its a quick read to load it.  The continued blips
> > you see are caused by something, well, continual :)
>
> Are you running your application at some real time priority?  I suspect
> that, when dbench starts, it floods the system with a lot of new tasks
> and the system must visit each one until it gets back to your ap.  Nice
> will only do so much here.  Real time priority is the way to go.
> Attached are a couple of small programs to help here.  "rt" runs a given
> ap at a given priority.  I.e. > rt 10 foo, runs foo at priority 10.
> (There are more options, try rt -h.)  getrt reports the priority of a
> task.  If you do something like > rt 10 bash   everything you run from
> the new bash prompt will be at priority 10.  You must be root to run rt

Yes, I do like I've posted in all the related threads.

Here is some more input for you. I hope it could help nail it down.

Regards,
	Dieter

BTW I'll now switching to 2.4.10-pre14

SunWave1#time tar xIf /Pakete/Linux/linux-2.4.9.tar.bz2
34.570u 5.350s 0:47.84 83.4%    0+0k 0+0io 295pf+0w

I "hear" some have disk activities (disk trashing).

SunWave1#sync

Runs for ages!!!

User	 CPU  0%
System	 CPU  0%
Idle	 CPU 99%

So where did it wait???

Here comes what latencytimes show:

Worst 20 latency times of 5061 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
322263   reacqBKL        1  1375/sched.c         c01138b4   697/sched.c
216174        BKL        1    30/inode.c         c016b971    52/inode.c
158328        BKL        9   742/block_dev.c     c0144d51   697/sched.c
 66975        BKL        1  1101/super.c         c014250d   697/sched.c
 53560        BKL        1  1101/super.c         c014250d  1130/super.c
 37742  spin_lock        1   547/sched.c         c0111b04   795/block_dev.c
 24822  spin_lock        1   678/inode.c         c01551f7   704/inode.c
 24739  spin_lock        1   291/buffer.c        c014003c   285/buffer.c
 19330  spin_lock        1   547/sched.c         c0111b04   697/sched.c
 16566        BKL        1    30/inode.c         c016b971   697/sched.c
 14049  spin_lock        1  2043/tcp_ipv6.c      e9078837   119/softirq.c
 11993  spin_lock        1  2111/tcp_ipv4.c      c0220517   119/softirq.c
 11704        BKL        1   706/block_dev.c     c0144bd7  1381/sched.c
 11405  spin_lock        1   291/buffer.c        c014003c   280/buffer.c
 11288        BKL        1   706/block_dev.c     c0144bd7   697/sched.c
 11213   reacqBKL        9  1375/sched.c         c01138b4   696/block_dev.c
 11212  spin_lock        1   547/sched.c         c0111b04   696/block_dev.c
  7552  spin_lock        1   298/buffer.c        c013bb1c   285/buffer.c
  5013        BKL        0  2763/buffer.c        c013fbca   697/sched.c
  4641        BKL        1  1302/inode.c         c016de79   697/sched.c

SunWave1#ksymoops -m /boot/System.map -A " c01138b4 c016b971 c0144d51 
c014250d c014250d c0111b04 c01551f7 c014003c c0111b04 c016b971 e9078837 
c0220517 c0144bd7 c014003c c0144bd7 c01138b4 c0111b04 c013bb1c c013fbca 
c016de79"
ksymoops 2.4.3 on i686 2.4.10-pre12-preempt.  Options used
     -V (default)
     -k /proc/ksyms (default)
     -l /proc/modules (default)
     -o /lib/modules/2.4.10-pre12-preempt/ (default)
     -m /boot/System.map (specified)


Adhoc c01138b4 <preempt_schedule+34/b0>
Adhoc c016b970 <reiserfs_delete_inode+30/110>
Adhoc c0144d50 <blkdev_close+60/1b0>
Adhoc c014250c <kill_super+ac/280>
Adhoc c014250c <kill_super+ac/280>
Adhoc c0111b04 <schedule+34/550>
Adhoc c01551f6 <prune_icache+36/160>
Adhoc c014003c <kupdate+11c/210>
Adhoc c0111b04 <schedule+34/550>
Adhoc c016b970 <reiserfs_delete_inode+30/110>
Adhoc e9078836 <[ipv6]tcp6_get_info+4a6/770>
Adhoc c0220516 <tcp_get_info+4b6/7a0>
Adhoc c0144bd6 <blkdev_put+46/160>
Adhoc c014003c <kupdate+11c/210>
Adhoc c0144bd6 <blkdev_put+46/160>
Adhoc c01138b4 <preempt_schedule+34/b0>
Adhoc c0111b04 <schedule+34/550>
Adhoc c013bb1c <wait_for_locked_buffers+3c/60>
Adhoc c013fbca <sync_old_buffers+2a/130>
Adhoc c016de78 <reiserfs_dirty_inode+58/f0>

Re: [PATCH] Preemption Latency Measurement Tool

[safemode]

ok. The preemption patch helps realtime applications in linux be a little 
more close to realtime.  I understand that.  But your mp3 player shouldn't 
need root permission or renicing or realtime priority flags to play mp3s.  To 
test how well the latency patches are working you should be running things 
all at the same priority.  The main issue people are having with skipping 
mp3s is not in the decoding of the mp3 or in the retrieving of the file, it's 
in the playing in the soundcard.  That's being affected by dbench flooding 
the system with irq requests.  I'm inclined to believe it's irq requests 
because the _only_ time i have problems with mp3s (and i dont change priority 
levels) is when A. i do a cdparanoia -Z -B "1-"    or dbench 32.   I bet if 
someone did these tests on scsi hardware with the latency patch, they'd find 
much better results than us users of ide devices.  

even i dont get any skips when i run the player at nice -n -20.   That 
doesn't tell you much about the preemption patch though.  And it doesn't tell 
you about performance when you dont give linux the chance to do what it does, 
 multitask.  That's where the latency patch is directed at improving, i 
think.  




On Saturday 22 September 2001 17:09, Dieter Nützel wrote:
> Am Freitag, 21. September 2001 17:48 schrieb george anzinger:
> > Robert Love wrote:
> > > On Thu, 2001-09-20 at 18:51, Dieter Nützel wrote:
> > > > > Does your audio source depend on any files (eg mp3s) and if so,
> > > > > could they be moved to a ramfs? Do the skips go away then?
> > > >
> > > > Good point.
> > > >
> > > > I've copied one video (MP2) and one Ogg-Vorbis file into /dev/shm.
> > > > Little bit better but hiccup still there :-(
> > >
> > > As I've been saying, the problem really shouldn't be disk I/O.  I would
> > > think (and really hope) the readahead code can fit a little mp3 in
> > > memory.  Even if not, its a quick read to load it.  The continued blips
> > > you see are caused by something, well, continual :)
> >
> > Are you running your application at some real time priority?  I suspect
> > that, when dbench starts, it floods the system with a lot of new tasks
> > and the system must visit each one until it gets back to your ap.  Nice
> > will only do so much here.  Real time priority is the way to go.
> > Attached are a couple of small programs to help here.  "rt" runs a given
> > ap at a given priority.  I.e. > rt 10 foo, runs foo at priority 10.
> > (There are more options, try rt -h.)  getrt reports the priority of a
> > task.  If you do something like > rt 10 bash   everything you run from
> > the new bash prompt will be at priority 10.  You must be root to run rt
>
> Yes, I do like I've posted in all the related threads.
>
> Here is some more input for you. I hope it could help nail it down.
>
> Regards,
> 	Dieter
>
> BTW I'll now switching to 2.4.10-pre14
>
> SunWave1#time tar xIf /Pakete/Linux/linux-2.4.9.tar.bz2
> 34.570u 5.350s 0:47.84 83.4%    0+0k 0+0io 295pf+0w
>
> I "hear" some have disk activities (disk trashing).
>
> SunWave1#sync
>
> Runs for ages!!!
>
> User	 CPU  0%
> System	 CPU  0%
> Idle	 CPU 99%
>
> So where did it wait???
>
> Here comes what latencytimes show:
>
> Worst 20 latency times of 5061 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
> 322263   reacqBKL        1  1375/sched.c         c01138b4   697/sched.c
> 216174        BKL        1    30/inode.c         c016b971    52/inode.c
> 158328        BKL        9   742/block_dev.c     c0144d51   697/sched.c
>  66975        BKL        1  1101/super.c         c014250d   697/sched.c
>  53560        BKL        1  1101/super.c         c014250d  1130/super.c
>  37742  spin_lock        1   547/sched.c         c0111b04   795/block_dev.c
>  24822  spin_lock        1   678/inode.c         c01551f7   704/inode.c
>  24739  spin_lock        1   291/buffer.c        c014003c   285/buffer.c
>  19330  spin_lock        1   547/sched.c         c0111b04   697/sched.c
>  16566        BKL        1    30/inode.c         c016b971   697/sched.c
>  14049  spin_lock        1  2043/tcp_ipv6.c      e9078837   119/softirq.c
>  11993  spin_lock        1  2111/tcp_ipv4.c      c0220517   119/softirq.c
>  11704        BKL        1   706/block_dev.c     c0144bd7  1381/sched.c
>  11405  spin_lock        1   291/buffer.c        c014003c   280/buffer.c
>  11288        BKL        1   706/block_dev.c     c0144bd7   697/sched.c
>  11213   reacqBKL        9  1375/sched.c         c01138b4   696/block_dev.c
>  11212  spin_lock        1   547/sched.c         c0111b04   696/block_dev.c
>   7552  spin_lock        1   298/buffer.c        c013bb1c   285/buffer.c
>   5013        BKL        0  2763/buffer.c        c013fbca   697/sched.c
>   4641        BKL        1  1302/inode.c         c016de79   697/sched.c
>
> SunWave1#ksymoops -m /boot/System.map -A " c01138b4 c016b971 c0144d51
> c014250d c014250d c0111b04 c01551f7 c014003c c0111b04 c016b971 e9078837
> c0220517 c0144bd7 c014003c c0144bd7 c01138b4 c0111b04 c013bb1c c013fbca
> c016de79"
> ksymoops 2.4.3 on i686 2.4.10-pre12-preempt.  Options used
>      -V (default)
>      -k /proc/ksyms (default)
>      -l /proc/modules (default)
>      -o /lib/modules/2.4.10-pre12-preempt/ (default)
>      -m /boot/System.map (specified)
>
>
> Adhoc c01138b4 <preempt_schedule+34/b0>
> Adhoc c016b970 <reiserfs_delete_inode+30/110>
> Adhoc c0144d50 <blkdev_close+60/1b0>
> Adhoc c014250c <kill_super+ac/280>
> Adhoc c014250c <kill_super+ac/280>
> Adhoc c0111b04 <schedule+34/550>
> Adhoc c01551f6 <prune_icache+36/160>
> Adhoc c014003c <kupdate+11c/210>
> Adhoc c0111b04 <schedule+34/550>
> Adhoc c016b970 <reiserfs_delete_inode+30/110>
> Adhoc e9078836 <[ipv6]tcp6_get_info+4a6/770>
> Adhoc c0220516 <tcp_get_info+4b6/7a0>
> Adhoc c0144bd6 <blkdev_put+46/160>
> Adhoc c014003c <kupdate+11c/210>
> Adhoc c0144bd6 <blkdev_put+46/160>
> Adhoc c01138b4 <preempt_schedule+34/b0>
> Adhoc c0111b04 <schedule+34/550>
> Adhoc c013bb1c <wait_for_locked_buffers+3c/60>
> Adhoc c013fbca <sync_old_buffers+2a/130>
> Adhoc c016de78 <reiserfs_dirty_inode+58/f0>
>
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/

Re: [PATCH] Preemption Latency Measurement Tool

[Dieter Nützel]

Am Sonntag, 23. September 2001 01:40 schrieb safemode:
> ok. The preemption patch helps realtime applications in linux be a little
> more close to realtime.  I understand that.  But your mp3 player shouldn't
> need root permission or renicing or realtime priority flags to play mp3s. 
> To test how well the latency patches are working you should be running
> things all at the same priority.  The main issue people are having with
> skipping mp3s is not in the decoding of the mp3 or in the retrieving of the
> file, it's in the playing in the soundcard.  That's being affected by
> dbench flooding the system with irq requests.  I'm inclined to believe it's
> irq requests because the _only_ time i have problems with mp3s (and i dont
> change priority levels) is when A. i do a cdparanoia -Z -B "1-"    or
> dbench 32.   I bet if someone did these tests on scsi hardware with the
> latency patch, they'd find much better results than us users of ide
> devices.

Nope.
If you would have read (all) posts about this and related threads you should 
have noticed that I am and others running SCSI systems...

>
> even i dont get any skips when i run the player at nice -n -20. 

During dbench 16/32 and higher? Are you sure?

-Dieter

Re: [PATCH] Preemption Latency Measurement Tool

[safemode]

On Saturday 22 September 2001 19:46, Dieter Nützel wrote:
> Am Sonntag, 23. September 2001 01:40 schrieb safemode:
> > ok. The preemption patch helps realtime applications in linux be a little
> > more close to realtime.  I understand that.  But your mp3 player
> > shouldn't need root permission or renicing or realtime priority flags to
> > play mp3s. To test how well the latency patches are working you should be
> > running things all at the same priority.  The main issue people are
> > having with skipping mp3s is not in the decoding of the mp3 or in the
> > retrieving of the file, it's in the playing in the soundcard.  That's
> > being affected by dbench flooding the system with irq requests.  I'm
> > inclined to believe it's irq requests because the _only_ time i have
> > problems with mp3s (and i dont change priority levels) is when A. i do a
> > cdparanoia -Z -B "1-"    or dbench 32.   I bet if someone did these tests
> > on scsi hardware with the latency patch, they'd find much better results
> > than us users of ide devices.
>
> Nope.
> If you would have read (all) posts about this and related threads you
> should have noticed that I am and others running SCSI systems...

hrmm  strange because the only thing that could be causing the soundcard to 
skip would be irq requests still stuck in the cpu as far as i know.  I only 
get that with massive ide access and that's it.  Also that is when linux is 
juggling them all equally. 

> > even i dont get any skips when i run the player at nice -n -20.
>
> During dbench 16/32 and higher? Are you sure?

I ran it myself and i dont drink alcohol or take drugs.  so yea, i'm sure :)  
If i went high enough i suppose the same problem would occur.  it's probably 
in an area of the kernel where the preempt patch doesn't work (yet).    It 
does happen on cdparanoia -Z -B "1"    I dont think anything ide is safe from 
that.    

> -Dieter

Re: [PATCH] Preemption Latency Measurement Tool

[Roger Larsson]

On Sunday 23 September 2001 01.40, safemode wrote:
> ok. The preemption patch helps realtime applications in linux be a little
> more close to realtime.  I understand that.  But your mp3 player shouldn't
> need root permission or renicing or realtime priority flags to play mp3s. 
> To test how well the latency patches are working you should be running
> things all at the same priority.  The main issue people are having with
> skipping mp3s is not in the decoding of the mp3 or in the retrieving of the
> file, it's in the playing in the soundcard.  That's being affected by
> dbench flooding the system with irq requests.  I'm inclined to believe it's
> irq requests because the _only_ time i have problems with mp3s (and i dont
> change priority levels) is when A. i do a cdparanoia -Z -B "1-"    or
> dbench 32.   I bet if someone did these tests on scsi hardware with the
> latency patch, they'd find much better results than us users of ide
> devices.

No, irq might have something to do with it but it is unlikely since the
stops are too long.

Much more likely is:
a) when running without priority altered:
MP3 playing requires processing, this will lower the process priority
relative processes that does little processing - like dbench processes.
Running with negative nice will help this, but is no guarantee. Running
with RT priority is.
[this is where the various low latency patches helps]

b) several processes are doing disk operations simultaneously.
This will put preassure on the VM to free pages fast enough. It will
also put preassure on the disk IO to read from disk fast enough -
these requests are not prioritized with the process priority in mind.
If there are no pages free we have to wait...
[if you run the latencytest program with no audiofile, to use a sine,
 you will not hear dropouts... it runs with RT prio with resident memory]

This second problem is MUCH harder to solve.
Multimedia applications could reserve memory - for their critical code
including buffers... (but this will require suid helpers...)
SGIs filesystem XFS is said to be able to guarantee bandwith to an
application.

Riels schedule in __alloc_pages probably helps the case with competing
regular processes a lot. Not allowing memory allocators to run their
whole time slot. The result should be a way to prioritize memory allocs
relative your priority. (yield part might be possible/good to remove)

/RogerL

-- 
Roger Larsson
Skellefteå
Sweden

Re: [PATCH] Preemption Latency Measurement Tool

[safemode]

On Saturday 22 September 2001 20:38, Roger Larsson wrote:
> On Sunday 23 September 2001 01.40, safemode wrote:
> > ok. The preemption patch helps realtime applications in linux be a little
> > more close to realtime.  I understand that.  But your mp3 player
> > shouldn't need root permission or renicing or realtime priority flags to
> > play mp3s. To test how well the latency patches are working you should be
> > running things all at the same priority.  The main issue people are
> > having with skipping mp3s is not in the decoding of the mp3 or in the
> > retrieving of the file, it's in the playing in the soundcard.  That's
> > being affected by dbench flooding the system with irq requests.  I'm
> > inclined to believe it's irq requests because the _only_ time i have
> > problems with mp3s (and i dont change priority levels) is when A. i do a
> > cdparanoia -Z -B "1-"    or dbench 32.   I bet if someone did these tests
> > on scsi hardware with the latency patch, they'd find much better results
> > than us users of ide devices.
>
> No, irq might have something to do with it but it is unlikely since the
> stops are too long.
>
> Much more likely is:
> a) when running without priority altered:
> MP3 playing requires processing, this will lower the process priority
> relative processes that does little processing - like dbench processes.
> Running with negative nice will help this, but is no guarantee. Running
> with RT priority is.
> [this is where the various low latency patches helps]

I dont think mp3 playing should require realtime priority.  if the problem is 
not getting enough cpu time or attention from the kernel then it's a kernel 
scheduling problem.  You shouldn't have to "cheat" and bypass all that.  in 
an ideal situation the kernel should be able to see that the mp3 proccess is 
running and is thus more important than stuff like dbench proccesses.  
Although this problem we're having with mp3 skippage is not a cpu bound 
problem.  We're dealing with another resource here that's not so predictable 
because the kernel scheduling handles cpu time slices very nicely.  


> b) several processes are doing disk operations simultaneously.
> This will put preassure on the VM to free pages fast enough. It will
> also put preassure on the disk IO to read from disk fast enough -
> these requests are not prioritized with the process priority in mind.
> If there are no pages free we have to wait...
> [if you run the latencytest program with no audiofile, to use a sine,
>  you will not hear dropouts... it runs with RT prio with resident memory]

this may be the reason.  Although i dont think RT prio has anything to do 
with it.  If RT prio doesn't effect this VM portion of the kernel then wether 
we use RT or not for something as tiny as mp3 playing would hardly matter.  
Our sound drivers may not be able to play nicely with the VM under heavy disk 
access like cdparanoia -Z or dbench 32 and above.  


> This second problem is MUCH harder to solve.
> Multimedia applications could reserve memory - for their critical code
> including buffers... (but this will require suid helpers...)
> SGIs filesystem XFS is said to be able to guarantee bandwith to an
> application.
>
> Riels schedule in __alloc_pages probably helps the case with competing
> regular processes a lot. Not allowing memory allocators to run their
> whole time slot. The result should be a way to prioritize memory allocs
> relative your priority. (yield part might be possible/good to remove)

Sounds interesting. 
> /RogerL

Setting to RT should guarantee that your process gets executed when it wants 
to and processed by the kernel, which should help when dealing with something 
that holds on to a part of the kernel for an unpredictable amount of time or 
perhaps just a length of time that's too long.  But this vm scheduling thing 
that can break up those requests should allow the kernel to organize more of 
it's processes to be able to run smoothly at the same time without the need 
to give one higher priority than the other. Perhaps making a default alloc 
time slot that's small so no processes get accidentally starved and if you 
want a program that hogs memory time to run at full performance and not be 
hampered by multitasking, running at a higher priority would increase it's 
mem alloc time.   mp3 playing requires a very minimal amount of resources 
from anything.  it should be made that these minimal programs can run 
smoothly without resource hogging programs starving them unless you 
specificaly want them to (ie. increase priority).  

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Sat, 2001-09-22 at 20:38, Roger Larsson wrote:
> Riels schedule in __alloc_pages probably helps the case with competing
> regular processes a lot. Not allowing memory allocators to run their
> whole time slot. The result should be a way to prioritize memory allocs
> relative your priority. (yield part might be possible/good to remove)

When did this go in?  I assume its in the 2.4.9-ac series and not
2.4.10?

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Roger Larsson]

On Sunday 23 September 2001 05.02, Robert Love wrote:
> On Sat, 2001-09-22 at 20:38, Roger Larsson wrote:
> > Riels schedule in __alloc_pages probably helps the case with competing
> > regular processes a lot. Not allowing memory allocators to run their
> > whole time slot. The result should be a way to prioritize memory allocs
> > relative your priority. (yield part might be possible/good to remove)
>
> When did this go in?  I assume its in the 2.4.9-ac series and not
> 2.4.10?

2.4.0-test something...
It was removed when introducing Andreas VM

/RogerL

-- 
Roger Larsson
Skellefteå
Sweden

Re: [PATCH] Preemption Latency Measurement Tool

[Dieter Nützel]

Am Sonntag, 23. September 2001 02:15 schrieb safemode:
> On Saturday 22 September 2001 19:46, Dieter Nützel wrote:
> > Am Sonntag, 23. September 2001 01:40 schrieb safemode:
> > > ok. The preemption patch helps realtime applications in linux be a
> > > little more close to realtime.  I understand that.  But your mp3 player
> > > shouldn't need root permission or renicing or realtime priority flags
> > > to play mp3s. To test how well the latency patches are working you
> > > should be running things all at the same priority.  The main issue
> > > people are having with skipping mp3s is not in the decoding of the mp3
> > > or in the retrieving of the file, it's in the playing in the soundcard.
> > >  That's being affected by dbench flooding the system with irq requests.
> > >  I'm inclined to believe it's irq requests because the _only_ time i
> > > have problems with mp3s (and i dont change priority levels) is when A.
> > > i do a cdparanoia -Z -B "1-"    or dbench 32.   I bet if someone did
> > > these tests on scsi hardware with the latency patch, they'd find much
> > > better results than us users of ide devices.
> >
> > Nope.
> > If you would have read (all) posts about this and related threads you
> > should have noticed that I am and others running SCSI systems...
>
> hrmm  strange because the only thing that could be causing the soundcard to
> skip would be irq requests still stuck in the cpu as far as i know.  I only
> get that with massive ide access and that's it.  Also that is when linux is
> juggling them all equally.
>
> > > even i dont get any skips when i run the player at nice -n -20.
> >
> > During dbench 16/32 and higher? Are you sure?
>
> I ran it myself and i dont drink alcohol or take drugs.  so yea, i'm sure
> :)

:-)))

I would only to be sure. 'cause I get this regularly.

> If i went high enough i suppose the same problem would occur.  it's
> probably in an area of the kernel where the preempt patch doesn't work
> (yet).    It does happen on cdparanoia -Z -B "1"

I am under the impression that we didn't found the cause of it, yet.

>    I dont think anything ide is safe from that.

No comment on this...:-)

So, do you running ReiserFS or what?

Thanks,
	Dieter

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Sat, 2001-09-22 at 19:40, safemode wrote:
> ok. The preemption patch helps realtime applications in linux be a little 
> more close to realtime.  I understand that.  But your mp3 player shouldn't 
> need root permission or renicing or realtime priority flags to play mp3s.

It doesn't, it needs them to play with a dbench 32 running in the
background.  This isn't nessecarily acceptable, either, but it is a
difference.

Note one thing the preemption patch does is really make `realtime' apps
accel.  Without it, regardless of the priority of the application, the
app can be starved due to something in kernel mode.  Now it can't, and
since said application is high priority, it will get the CPU when it
wants it.

This is not to say the preemption patch is no good if you don't run
stuff at realtime --  I don't (who uses nice, anyhow? :>), and I notice
a difference.

> To 
> test how well the latency patches are working you should be running things 
> all at the same priority.  The main issue people are having with skipping 
> mp3s is not in the decoding of the mp3 or in the retrieving of the file, it's 
> in the playing in the soundcard.  That's being affected by dbench flooding 
> the system with irq requests.  I'm inclined to believe it's irq requests 
> because the _only_ time i have problems with mp3s (and i dont change priority 
> levels) is when A. i do a cdparanoia -Z -B "1-"    or dbench 32.   I bet if 
> someone did these tests on scsi hardware with the latency patch, they'd find 
> much better results than us users of ide devices.  

The skips are really big to be irq requests, although perhaps you are
right in that the handling of the irq (we disable preemption during
irq_off, of course, but also during bottom half execution) is the
problem.

However, I am more inclined to believe it is something else.  All these
long held locks can indeed be the problem.

I am on an all UW2 SCSI system, and I have no major blips playing during
a `dbench 16' (never ran 32).  However, many other users (Dieter, I
believe) are on a SCSI system too.

> even i dont get any skips when i run the player at nice -n -20.   That 
> doesn't tell you much about the preemption patch though.  And it doesn't tell 
> you about performance when you dont give linux the chance to do what it does, 
>  multitask.  That's where the latency patch is directed at improving, i 
> think.  

Agreed.

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[george anzinger]

Robert Love wrote:
> 
> On Sat, 2001-09-22 at 19:40, safemode wrote:
> > ok. The preemption patch helps realtime applications in linux be a little
> > more close to realtime.  I understand that.  But your mp3 player shouldn't
> > need root permission or renicing or realtime priority flags to play mp3s.
> 
> It doesn't, it needs them to play with a dbench 32 running in the
> background.  This isn't nessecarily acceptable, either, but it is a
> difference.
> 
> Note one thing the preemption patch does is really make `realtime' apps
> accel.  Without it, regardless of the priority of the application, the
> app can be starved due to something in kernel mode.  Now it can't, and
> since said application is high priority, it will get the CPU when it
> wants it.
> 
> This is not to say the preemption patch is no good if you don't run
> stuff at realtime --  I don't (who uses nice, anyhow? :>), and I notice
> a difference.
> 
> > To
> > test how well the latency patches are working you should be running things
> > all at the same priority.  The main issue people are having with skipping
> > mp3s is not in the decoding of the mp3 or in the retrieving of the file, it's
> > in the playing in the soundcard.  That's being affected by dbench flooding
> > the system with irq requests.  I'm inclined to believe it's irq requests
> > because the _only_ time i have problems with mp3s (and i dont change priority
> > levels) is when A. i do a cdparanoia -Z -B "1-"    or dbench 32.   I bet if
> > someone did these tests on scsi hardware with the latency patch, they'd find
> > much better results than us users of ide devices.
> 
> The skips are really big to be irq requests, although perhaps you are
> right in that the handling of the irq (we disable preemption during
> irq_off, of course, but also during bottom half execution) is the
> problem.
> 
> However, I am more inclined to believe it is something else.  All these
> long held locks can indeed be the problem.
> 
> I am on an all UW2 SCSI system, and I have no major blips playing during
> a `dbench 16' (never ran 32).  However, many other users (Dieter, I
> believe) are on a SCSI system too.

Dieter, could you post your .config file?  It might have a clue or two.

George

> 
> > even i dont get any skips when i run the player at nice -n -20.   That
> > doesn't tell you much about the preemption patch though.  And it doesn't tell
> > you about performance when you dont give linux the chance to do what it does,
> >  multitask.  That's where the latency patch is directed at improving, i
> > think.
> 
> Agreed.
> 
> --
> Robert M. Love
> rml at ufl.edu
> rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Dieter Nützel]

[-- Attachment #1: Type: text/plain, Size: 2530 bytes --]

Am Sonntag, 23. September 2001 05:14 schrieb george anzinger:
> Robert Love wrote:
> > On Sat, 2001-09-22 at 19:40, safemode wrote:
> > > ok. The preemption patch helps realtime applications in linux be a
> > > little more close to realtime.  I understand that.  But your mp3 player
> > > shouldn't need root permission or renicing or realtime priority flags
> > > to play mp3s.
> >
> > It doesn't, it needs them to play with a dbench 32 running in the
> > background.  This isn't nessecarily acceptable, either, but it is a
> > difference.
> >
> > Note one thing the preemption patch does is really make `realtime' apps
> > accel.  Without it, regardless of the priority of the application, the
> > app can be starved due to something in kernel mode.  Now it can't, and
> > since said application is high priority, it will get the CPU when it
> > wants it.
> >
> > This is not to say the preemption patch is no good if you don't run
> > stuff at realtime --  I don't (who uses nice, anyhow? :>), and I notice
> > a difference.
> >
> > > To
> > > test how well the latency patches are working you should be running
> > > things all at the same priority.  The main issue people are having with
> > > skipping mp3s is not in the decoding of the mp3 or in the retrieving of
> > > the file, it's in the playing in the soundcard.  That's being affected
> > > by dbench flooding the system with irq requests.  I'm inclined to
> > > believe it's irq requests because the _only_ time i have problems with
> > > mp3s (and i dont change priority levels) is when A. i do a cdparanoia
> > > -Z -B "1-"    or dbench 32.   I bet if someone did these tests on scsi
> > > hardware with the latency patch, they'd find much better results than
> > > us users of ide devices.
> >
> > The skips are really big to be irq requests, although perhaps you are
> > right in that the handling of the irq (we disable preemption during
> > irq_off, of course, but also during bottom half execution) is the
> > problem.
> >
> > However, I am more inclined to believe it is something else.  All these
> > long held locks can indeed be the problem.
> >
> > I am on an all UW2 SCSI system, and I have no major blips playing during
> > a `dbench 16' (never ran 32).  However, many other users (Dieter, I
> > believe) are on a SCSI system too.
>
> Dieter, could you post your .config file?  It might have a clue or two.

Here it comes.

Good night ;-)

-Dieter

BTW I have very good results (not the hiccup) for 2.4.10-pre14 + ReiserFS 
journal.c-2-patch from Chris

[-- Attachment #2: config.bz2 --]
[-- Type: application/x-bzip2, Size: 4370 bytes --]

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Sat, 2001-09-22 at 19:46, Dieter Nützel wrote:
> Nope.
> If you would have read (all) posts about this and related threads you should 
> have noticed that I am and others running SCSI systems...
> 
> >
> > even i dont get any skips when i run the player at nice -n -20. 
> 
> During dbench 16/32 and higher? Are you sure?

I can't speak for safemode, but doing something like:

[22:43:47]rml@phantasy:~$ mpg321 /home/mp3/Get_Up_Kids-Woodson.mp3 &
[22:52:03]rml@phantasy:~$ dbench 16

I don't get any blips (nothing over 0.5s, anyhow, I would wager).

This is a P3-733, i815 board, 384MB PC133, AHA-2940U2W, U2W IBM 9GB system.

Linux 2.4.9-ac14 + preempt + and more

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [reiserfs-list] Re: [PATCH] Preemption Latency Measurement Tool

[Dieter Nützel]

Hello Robert, all the others,

here are my latest results.
I've tried 2.4.10+preempt with some additional patches.
Latest that I have applied was softirq-2.4.10-A7. But it all didn't fix my 
reported MP3 playback hiccup during dbench 16/32.

See the numbers below.

Regards,
	Dieter

2.4.10+
patch-rml-2.4.10-preempt-kernel-1+
patch-rml-2.4.10-preempt-ptrace-and-jobs-fix+
patch-rml-2.4.10-preempt-stats-1+
inode.c-schedule.patch+
journal.c-1-patch

32 clients started
.....................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................++............................................+.......+++..+....+++..+...+.....+.++...+.++++.+++.++++++.+++********************************
Throughput 38.6878 MB/sec (NB=48.3597 MB/sec  386.878 MBit/sec)
14.200u 54.940s 1:50.21 62.7%   0+0k 0+0io 911pf+0w
max load: 1777

Version 1.92a       ------Sequential Output------ --Sequential Input- 
--Random-
                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- 
--Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec 
%CP
SunWave1      1248M    79  97 16034  21  5719   6   147  98 22904  16 269.0   
4
Latency               138ms    2546ms     201ms   97838us   58940us    3207ms
Version 1.92a       ------Sequential Create------ --------Random 
Create--------
SunWave1            -Create-- --Read--- -Delete-- -Create-- --Read--- 
-Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec 
%CP
                 16  6121  75 +++++ +++ 12753  95  8422  80 +++++ +++ 11152  
95
Latency             26126us   11425us   11879us    5325us   12082us   13025us
1.92a,1.92a,SunWave1,1001286857,1248M,79,97,16034,21,5719,6,147,98,22904,16,269.0,4,16,,,,,6121,75,+++++,+++,12753,95,8422,80,+++++,+++,11152,95,138ms,2546ms,201ms,97838us,58940us,3207ms,26126us,11425us,11879us,5325us,12082us,13025us

After running VTK (VIS app) I get this:

Worst 20 latency times of 1648 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  7239  spin_lock        1   381/memory.c        c012808f   402/memory.c
   321        BKL        0  2754/buffer.c        c01415ba   697/sched.c
   312        BKL        0   359/buffer.c        c013d6dc  1381/sched.c
   280        BKL        0   359/buffer.c        c013d6dc  1380/sched.c
   252   reacqBKL        0  1375/sched.c         c0115334  1381/sched.c
   232  spin_lock        0   547/sched.c         c0113574   697/sched.c
   215       eth1        0   585/irq.c           c01089af   647/irq.c
   164        BKL        0   452/exit.c          c011b4d1   681/tty_io.c
   119        BKL        0  1437/namei.c         c014cabf   697/sched.c
   105        BKL        0   452/exit.c          c011b4d1   697/sched.c
   101        BKL        5   712/tty_io.c        c01a6edb   714/tty_io.c
   100        BKL        0   452/exit.c          c011b4d1  1380/sched.c
    99    unknown        1    76/softirq.c       c011cba4   119/softirq.c
    92  spin_lock        4   468/netfilter.c     c01fe263   119/softirq.c
    79        BKL        0    42/file.c          c01714b0    63/file.c
    72        BKL        0   752/namei.c         c014b73f   697/sched.c
    71        BKL        0   533/inode.c         c016e0ad  1381/sched.c
    71        BKL        0    30/inode.c         c016d531    52/inode.c
    68        BKL        0   452/exit.c          c011b4d1  1381/sched.c
    66        BKL        0   927/namei.c         c014b94f   929/namei.c

Adhoc c012808e <zap_page_range+5e/260>

Do we need Rik's patch?

****************************************************************************

2.4.10+
patch-rml-2.4.10-preempt-kernel-1+
patch-rml-2.4.10-preempt-ptrace-and-jobs-fix+
patch-rml-2.4.10-preempt-stats-1+
inode.c-schedule.patch+
journal.c-1-patch+
kupdated-patch

32 clients started
...............................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................+..........................................+.................+...........++.....................++.....++......+......+++++...++++++++.+++++++.++********************************
Throughput 38.9015 MB/sec (NB=48.6269 MB/sec  389.015 MBit/sec)
15.140u 60.640s 1:49.66 69.1%   0+0k 0+0io 911pf+0w
max load: 1654

Version 1.92a       ------Sequential Output------ --Sequential Input- 
--Random-
                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- 
--Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec 
%CP
SunWave1      1248M    84  99 16348  21  5746   6   142  99 23411  17 265.9   
4
Latency               130ms    1868ms     192ms   88459us   54625us    3367ms
Version 1.92a       ------Sequential Create------ --------Random 
Create--------
SunWave1            -Create-- --Read--- -Delete-- -Create-- --Read--- 
-Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec 
%CP
                 16  4941  65 +++++ +++ 12916  96  6847  76 +++++ +++ 10785  
94
Latency              8468us   11334us   11736us    8520us   12205us   12856us
1.92a,1.92a,SunWave1,1001358471,1248M,84,99,16348,21,5746,6,142,99,23411,17,265.9,4,16,,,,,4941,65,+++++,+++,12916,96,6847,76,+++++,+++,10785,94,130ms,1868ms,192ms,88459us,54625us,3367ms,8468us,11334us,11736us,8520us,12205us,12856us

Dbench run during MP3 playback:
32 clients started
.................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................+.........+.........................................+.+.....+...............+...........................................................................+...................++...........+.+.......+..++++.++.+.++.++++++.+++++********************************
Throughput 34.7025 MB/sec (NB=43.3782 MB/sec  347.025 MBit/sec)
15.290u 63.820s 2:02.74 64.4%   0+0k 0+0io 911pf+0w

Worst 20 latency times of 16578 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 26795  spin_lock        1   291/buffer.c        c0141a2c   280/buffer.c
 17330  spin_lock        1   341/vmscan.c        c0133f0a   402/vmscan.c
 12925  spin_lock        1   439/vmscan.c        c0133ea5   338/vmscan.c
 11923  spin_lock        1   291/buffer.c        c0141a2c   285/buffer.c
  7253        BKL        0  1302/inode.c         c016faa9  1381/sched.c
  7117        BKL        1  1302/inode.c         c016faa9   697/sched.c
  6097        BKL        0  1302/inode.c         c016faa9  1380/sched.c
  6000        BKL        1   533/inode.c         c016e11d   697/sched.c
  4870   reacqBKL        1  1375/sched.c         c0115334   929/namei.c
  4015  spin_lock        0   439/vmscan.c        c0133ea5   402/vmscan.c
  2075        BKL        1   452/exit.c          c011b4d1   697/sched.c
  2029  spin_lock        1   547/sched.c         c0113574   697/sched.c
  2010        BKL        0  1302/inode.c         c016faa9   842/inode.c
  1730        BKL        0  2754/buffer.c        c01415ba  2757/buffer.c
  1668        BKL        1  2754/buffer.c        c01415ba   697/sched.c
  1574  spin_lock        0   483/dcache.c        c01545da   520/dcache.c
  1416  spin_lock        0  1376/sched.c         c0115353  1380/sched.c
  1396  spin_lock        1  1376/sched.c         c0115353   697/sched.c
  1387    aic7xxx        1    76/softirq.c       c011cba4   119/softirq.c
  1341        BKL        1   533/inode.c         c016e11d   842/inode.c

Adhoc c0141a2c <kupdate+11c/210>
Adhoc c0133f0a <shrink_cache+37a/5b0>
Adhoc c0133ea4 <shrink_cache+314/5b0>
Adhoc c0141a2c <kupdate+11c/210>
Adhoc c016faa8 <reiserfs_dirty_inode+58/f0>
Adhoc c016faa8 <reiserfs_dirty_inode+58/f0>
Adhoc c016faa8 <reiserfs_dirty_inode+58/f0>
Adhoc c016e11c <reiserfs_get_block+9c/f30>
Adhoc c0115334 <preempt_schedule+34/b0>
Adhoc c0133ea4 <shrink_cache+314/5b0>
Adhoc c011b4d0 <do_exit+130/360>
Adhoc c0113574 <schedule+34/550>
Adhoc c016faa8 <reiserfs_dirty_inode+58/f0>
Adhoc c01415ba <sync_old_buffers+2a/130>
Adhoc c01415ba <sync_old_buffers+2a/130>
Adhoc c01545da <select_parent+3a/100>
Adhoc c0115352 <preempt_schedule+52/b0>
Adhoc c0115352 <preempt_schedule+52/b0>
Adhoc c011cba4 <do_softirq+34/150>
Adhoc c016e11c <reiserfs_get_block+9c/f30>

Redo after some seconds:

Worst 20 latency times of 1944 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  2028        BKL        1  1302/inode.c         c016faa9   697/sched.c
   584        BKL        0  1302/inode.c         c016faa9  1306/inode.c
   572  spin_lock        0  1376/sched.c         c0115353  1380/sched.c
   415        BKL        0  1302/inode.c         c016faa9  1381/sched.c
   356        BKL        0  2754/buffer.c        c01415ba  2757/buffer.c
   353        BKL        0  2754/buffer.c        c01415ba   697/sched.c
   328        BKL        0  2754/buffer.c        c01415ba  1381/sched.c
   278  spin_lock        0   381/memory.c        c012808f   402/memory.c
   274   reacqBKL        0  1375/sched.c         c0115334  1381/sched.c
   245  spin_lock        0   547/sched.c         c0113574   697/sched.c
   208       eth1        0   585/irq.c           c01089af   647/irq.c
   188        BKL        1   301/namei.c         c014a4b1   697/sched.c
   176        BKL        1   927/namei.c         c014b9bf   929/namei.c
   161        BKL        0   301/namei.c         c014a4b1  1380/sched.c
   154        BKL        0   533/inode.c         c016e11d   842/inode.c
   147        BKL        6   712/tty_io.c        c01a6f6b   714/tty_io.c
   141        BKL        0   301/namei.c         c014a4b1  1381/sched.c
   141        BKL        0    30/inode.c         c016d5a1    52/inode.c
   126   reacqBKL        0  1375/sched.c         c0115334  2757/buffer.c
   121   reacqBKL        0  1375/sched.c         c0115334   929/namei.c

Adhoc c016faa8 <reiserfs_dirty_inode+58/f0>
Adhoc c016faa8 <reiserfs_dirty_inode+58/f0>
Adhoc c0115352 <preempt_schedule+52/b0>
Adhoc c016faa8 <reiserfs_dirty_inode+58/f0>
Adhoc c01415ba <sync_old_buffers+2a/130>
Adhoc c01415ba <sync_old_buffers+2a/130>
Adhoc c01415ba <sync_old_buffers+2a/130>
Adhoc c012808e <zap_page_range+5e/260>
Adhoc c0115334 <preempt_schedule+34/b0>
Adhoc c0113574 <schedule+34/550>
Adhoc c01089ae <do_IRQ+3e/1d0>
Adhoc c014a4b0 <real_lookup+70/150>
Adhoc c014b9be <vfs_create+ae/150>
Adhoc c014a4b0 <real_lookup+70/150>
Adhoc c016e11c <reiserfs_get_block+9c/f30>
Adhoc c01a6f6a <tty_write+21a/2f0>
Adhoc c014a4b0 <real_lookup+70/150>
Adhoc c016d5a0 <reiserfs_delete_inode+30/110>
Adhoc c0115334 <preempt_schedule+34/b0>
Adhoc c0115334 <preempt_schedule+34/b0>

****************************************************************************

2.4.10+
patch-rml-2.4.10-preempt-kernel-1+
patch-rml-2.4.10-preempt-ptrace-and-jobs-fix+
patch-rml-2.4.10-preempt-stats-1+
inode.c-schedule.patch+
journal.c-1-patch+
kupdated-patch+
00_vm-tweaks-1

32 clients started
............................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................+......................................+..+...+...+...............+...+...................+.....+++...+.++.+.+..+++++.+...++++++++++********************************
Throughput 37.9905 MB/sec (NB=47.4881 MB/sec  379.905 MBit/sec)
14.810u 62.280s 1:52.26 68.6%   0+0k 0+0io 911pf+0w
max load: 1764

Version 1.92a       ------Sequential Output------ --Sequential Input- 
--Random-
                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- 
--Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec 
%CP
SunWave1      1248M    87  98 16359  21  5839   6   155  99 23709  16 275.7   
4
Latency               247ms    2351ms     191ms   84684us   67700us    3791ms
Version 1.92a       ------Sequential Create------ --------Random 
Create--------
SunWave1            -Create-- --Read--- -Delete-- -Create-- --Read--- 
-Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec 
%CP
                 16  5545  52 +++++ +++ 13434  95  5138  67 +++++ +++ 11297  
95
Latency              4894us   11251us   11868us    4922us   12265us   12863us
1.92a,1.92a,SunWave1,1001467140,1248M,87,98,16359,21,5839,6,155,99,23709,16,275.7,4,16,,,,,5545,52,+++++,+++,13434,95,5138,67,+++++,+++,11297,95,247ms,2351ms,191ms,84684us,67700us,3791ms,4894us,11251us,11868us,4922us,12265us,12863us

Dbench run during MP3 playback:
32 clients started
.................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................++..........+.+..+..............................................+...................................................+.....+..........+.....+.+..++++.+..+....+++++++.+.++++.+++********************************
Throughput 36.1736 MB/sec (NB=45.217 MB/sec  361.736 MBit/sec)
14.920u 61.240s 1:57.82 64.6%   0+0k 0+0io 911pf+0w

Worst 20 latency times of 19595 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 40920  spin_lock        1   291/buffer.c        c0141a5c   280/buffer.c
 16812  spin_lock        1   443/vmscan.c        c0133eb5   340/vmscan.c
  8114        BKL        1   533/inode.c         c016e14d   697/sched.c
  7932  spin_lock        1   443/vmscan.c        c0133eb5   406/vmscan.c
  6886        BKL        1  1302/inode.c         c016fad9   697/sched.c
  6660        BKL        0  1302/inode.c         c016fad9  1306/inode.c
  6260  spin_lock        1   343/vmscan.c        c0133f1a   406/vmscan.c
  4273        BKL        1  1302/inode.c         c016fad9   842/inode.c
  2410   reacqBKL        1  1375/sched.c         c0115334   697/sched.c
  2153   reacqBKL        0  1375/sched.c         c0115334  1381/sched.c
  1876        BKL        0   452/exit.c          c011b4d1   697/sched.c
  1609  spin_lock        1   483/dcache.c        c015460a   520/dcache.c
  1536        BKL        0  2754/buffer.c        c01415ea  2757/buffer.c
  1533  spin_lock        0   291/buffer.c        c0141a5c   285/buffer.c
  1311        BKL        0  2754/buffer.c        c01415ea  1380/sched.c
  1308  spin_lock        0   547/sched.c         c0113574   697/sched.c
  1286        BKL        1   533/inode.c         c016e14d   842/inode.c
  1222        BKL        0    30/inode.c         c016d5d1    52/inode.c
  1110        BKL        0  2754/buffer.c        c01415ea  1381/sched.c
   850  spin_lock        1  1376/sched.c         c0115353  1380/sched.c

Adhoc c0141a5c <kupdate+11c/210>
Adhoc c0133eb4 <shrink_cache+2f4/590>
Adhoc c016e14c <reiserfs_get_block+9c/f30>
Adhoc c0133eb4 <shrink_cache+2f4/590>
Adhoc c016fad8 <reiserfs_dirty_inode+58/f0>
Adhoc c016fad8 <reiserfs_dirty_inode+58/f0>
Adhoc c0133f1a <shrink_cache+35a/590>
Adhoc c016fad8 <reiserfs_dirty_inode+58/f0>
Adhoc c0115334c0115334 <END_OF_CODE+c0115333d122a04e/????>
Adhoc c011b4d0 <do_exit+130/360>
Adhoc c015460a <select_parent+3a/100>
Adhoc c01415ea <sync_old_buffers+2a/130>
Adhoc c0141a5c <kupdate+11c/210>
Adhoc c01415ea <sync_old_buffers+2a/130>
Adhoc c0113574 <schedule+34/550>
Adhoc c016e14c <reiserfs_get_block+9c/f30>
Adhoc c016d5d0 <reiserfs_delete_inode+30/110>
Adhoc c01415ea <sync_old_buffers+2a/130>
Adhoc c0115352 <preempt_schedule+52/b0>

SunWave1#free -t
             total       used       free     shared    buffers     cached
Mem:        642824     168212     474612          0      11404      47612
-/+ buffers/cache:     109196     533628
Swap:            0          0          0
Total:      642824     168212     474612

SunWave1#cat /proc/meminfo
        total:    used:    free:  shared: buffers:  cached:
Mem:  658251776 172527616 485724160        0 11677696 49016832
Swap:        0        0        0
MemTotal:       642824 kB
MemFree:        474340 kB
MemShared:           0 kB
Buffers:         11404 kB
Cached:          47868 kB
SwapCached:          0 kB
Active:          37356 kB
Inactive:        21916 kB
HighTotal:           0 kB
HighFree:            0 kB
LowTotal:       642824 kB
LowFree:        474340 kB
SwapTotal:           0 kB
SwapFree:            0 kB

****************************************************************************

2.4.10+
patch-rml-2.4.10-preempt-kernel-1+
patch-rml-2.4.10-preempt-ptrace-and-jobs-fix+
patch-rml-2.4.10-preempt-stats-1+
inode.c-schedule.patch+
journal.c-1-patch+
kupdated-patch+
00_vm-tweaks-2+
softirq-2.4.10-A7

32 clients started
....................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................+............+.....................................+...+................................+.....................+........+..+++..+++...+++++++..+++++.++++.+++********************************
Throughput 38.061 MB/sec (NB=47.5762 MB/sec  380.61 MBit/sec)
14.850u 60.210s 1:52.00 67.0%   0+0k 0+0io 911pf+0w
max load: 1872

Version 1.92a       ------Sequential Output------ --Sequential Input- 
--Random-
                    -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- 
--Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec 
%CP
SunWave1      1248M    86  99 16238  21  5950   6   160  99 23612  16 270.9   
4
Latency               186ms    1905ms     170ms   81429us   58393us    2869ms
Version 1.92a       ------Sequential Create------ --------Random 
Create--------
SunWave1            -Create-- --Read--- -Delete-- -Create-- --Read--- 
-Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec 
%CP
                 16  5351  51 +++++ +++ 13298  94  8670  82 +++++ +++ 11260  
95
Latency              7799us   11631us   11649us    4801us   12097us   12804us
1.92a,1.92a,SunWave1,1001546561,1248M,86,99,16238,21,5950,6,160,99,23612,16,270.9,4,16,,,,,5351,51,+++++,+++,13298,94,8670,82,+++++,+++,11260,95,186ms,1905ms,170ms,81429us,58393us,2869ms,7799us,11631us,11649us,4801us,12097us,12804us

Dbench run during MP3 playback:
SunWave1>time ./dbench 32
32 clients started
........................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................+.+.+................++.....+........+......................+...................+++.+...........+........+.......++..+++.+..++.+.++...++++.+.+.........+********************************
Throughput 37.9649 MB/sec (NB=47.4562 MB/sec  379.649 MBit/sec)
14.900u 61.430s 1:52.34 67.9%   0+0k 0+0io 911pf+0w

Worst 20 latency times of 13895 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 32066  spin_lock        1   291/buffer.c        c0141aac   285/buffer.c
 13058  spin_lock        1   443/vmscan.c        c0133f05   340/vmscan.c
 10875  spin_lock        1   343/vmscan.c        c0133f6a   340/vmscan.c
  9627  spin_lock        1   291/buffer.c        c0141aac   280/buffer.c
  7310  spin_lock        0   343/vmscan.c        c0133f6a   406/vmscan.c
  7003        BKL        1  1302/inode.c         c016fb29  1402/sched.c
  6906        BKL        0  1302/inode.c         c016fb29   719/sched.c
  6723        BKL        0  1302/inode.c         c016fb29  1306/inode.c
  4036        BKL        1  1302/inode.c         c016fb29   842/inode.c
  3978        BKL        1   533/inode.c         c016e19d   842/inode.c
  3636        BKL        1    30/inode.c         c016d621    52/inode.c
  3359   reacqBKL        1  1397/sched.c         c01153f4    52/inode.c
  3005        BKL        1   452/exit.c          c011b591   719/sched.c
  2137   reacqBKL        1  1397/sched.c         c01153f4   929/namei.c
  2064  spin_lock        0   443/vmscan.c        c0133f05   406/vmscan.c
  1776   reacqBKL        1  1397/sched.c         c01153f4   719/sched.c
  1695  spin_lock        0   569/sched.c         c0113634   719/sched.c
  1557  spin_lock        0   483/dcache.c        c015465a   520/dcache.c
  1385        BKL        1  2754/buffer.c        c014163a  2757/buffer.c
  1324  spin_lock        0  1398/sched.c         c0115413   719/sched.c

Adhoc c0141aac <kupdate+11c/210>
Adhoc c0133f04 <shrink_cache+2f4/590>
Adhoc c0133f6a <shrink_cache+35a/590>
Adhoc c0141aac <kupdate+11c/210>
Adhoc c0133f6a <shrink_cache+35a/590>
Adhoc c016fb28 <reiserfs_dirty_inode+58/f0>
Adhoc c016fb28 <reiserfs_dirty_inode+58/f0>
Adhoc c016fb28 <reiserfs_dirty_inode+58/f0>
Adhoc c016fb28 <reiserfs_dirty_inode+58/f0>
Adhoc c016e19c <reiserfs_get_block+9c/f30>
Adhoc c016d620 <reiserfs_delete_inode+30/110>
Adhoc c01153f4 <preempt_schedule+34/b0>
Adhoc c011b590 <do_exit+130/360>
Adhoc c01153f4 <preempt_schedule+34/b0>
Adhoc c0133f04 <shrink_cache+2f4/590>
Adhoc c01153f4 <preempt_schedule+34/b0>
Adhoc c0113634 <schedule+34/550>
Adhoc c015465a <select_parent+3a/100>
Adhoc c014163a <sync_old_buffers+2a/130>
Adhoc c0115412 <preempt_schedule+52/b0>

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Sat, 2001-09-22 at 20:15, safemode wrote:
> hrmm  strange because the only thing that could be causing the soundcard to 
> skip would be irq requests still stuck in the cpu as far as i know.  I only 
> get that with massive ide access and that's it.  Also that is when linux is 
> juggling them all equally. 

The soundcard will skip whenever there is not enough data for it to
play, this would be caused by the mp3 player not getting the needed CPU
time (or the PCI bus is saturated or some such).

This could be caused by more than just irq requests -- anytime the
kernel can't schedule the mp3 player readily enough.  With the
preemption patch, this can occur during not just interrupt handling but
any concurreny lock.

> > > even i dont get any skips when i run the player at nice -n -20.
> >
> > During dbench 16/32 and higher? Are you sure?
> 
> I ran it myself and i dont drink alcohol or take drugs.  so yea, i'm sure :)

Heh :)
 
> If i went high enough i suppose the same problem would occur.  it's probably 
> in an area of the kernel where the preempt patch doesn't work (yet).    It 
> does happen on cdparanoia -Z -B "1"    I dont think anything ide is safe from 
> that.    

By design, preemption does not occur under any lock (right now we use
SMP locks).  This means all the spinlocks in the kernel disable
preemption, the big kernel lock disables preemption, irq_off obviously
does, etc.

What we need to do now is identify the long held locks and -- if they
are causing problems -- do something about them.

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Sat, 2001-09-22 at 17:09, Dieter Nützel wrote:
> Yes, I do like I've posted in all the related threads.
> 
> Here is some more input for you. I hope it could help nail it down.
> 
> Regards,
> 	Dieter
> 
> BTW I'll now switching to 2.4.10-pre14
>
> SunWave1#time tar xIf /Pakete/Linux/linux-2.4.9.tar.bz2
> 34.570u 5.350s 0:47.84 83.4%    0+0k 0+0io 295pf+0w
> 
> I "hear" some have disk activities (disk trashing).
> 
> SunWave1#sync
> 
> Runs for ages!!!

It has to flush that whole tar job you just did, which it did in memory
:)

> User	 CPU  0%
> System	 CPU  0%
> Idle	 CPU 99%
> 
> So where did it wait???
> 
> Here comes what latencytimes show:
> 
> Worst 20 latency times of 5061 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
> 322263   reacqBKL        1  1375/sched.c         c01138b4   697/sched.c
> 216174        BKL        1    30/inode.c         c016b971    52/inode.c
> 158328        BKL        9   742/block_dev.c     c0144d51   697/sched.c

OK, these three are not acceptable...adding them to the "list".

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Roger Larsson]

On Thursday den 20 September 2001 09.57, Dieter Nützel wrote:
> Am Donnerstag, 20. September 2001 08:41 schrieb Andrea Arcangeli:

>
> But this is not enough. Even with reniced artsd (-20).
> Some shorter hiccups (0.5~1 sec).
>
> -Dieter
>
> dbench 16 (without renice)
> Throughput 31.0483 MB/sec (NB=38.8104 MB/sec  310.483 MBit/sec)
> 7.270u 29.290s 1:09.03 52.9%    0+0k 0+0io 511pf+0w
> load: 1034
>
> Worst 20 latency times of 4261 measured in this period.
>   usec      cause     mask   start line/file      address   end line/file
>   4617   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
    ^^^^

This is fantastic! It REALLY is!
When we started with the low latency work we aimed at 10 ms.
(in all situations, not only when running dbench... but still)

Lets see - no swap used? - not swapped out
But with priority altered - it is unlikely that it would not be scheduled
in for such a long time.

Might it be that the disk is busy to handle dbench requests. 16 threads ->
16 read and several (async) write requests at different disk locations in
queue - make it 20. Seek time 10 ms => queue length 200 ms... probable???
Do you have more than one disk? Try to run dbench on one and the player from
the other.

/RogerL

-- 
Roger Larsson
Skellefteå
Sweden

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Thu, 2001-09-20 at 13:37, Roger Larsson wrote:

> > Worst 20 latency times of 4261 measured in this period.
> >   usec      cause     mask   start line/file      address   end line/file
> >   4617   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
>
> This is fantastic! It REALLY is!
> When we started with the low latency work we aimed at 10 ms.
> (in all situations, not only when running dbench... but still)

Yes it really is, especially noting that that 4.6ms lock is the
_longest_ held lock on the system.

I am seeing 90% of the reported locks under 15ms, and this means that
almost all the locks on the system are even less.

However, I am also seeing some stray 20-50ms and even 60-70ms latencies
and those bother me.  I am looking into another solution, perhaps
conditional scheduling for now.

> Lets see - no swap used? - not swapped out
> But with priority altered - it is unlikely that it would not be scheduled
> in for such a long time.
> 
> Might it be that the disk is busy to handle dbench requests. 16 threads ->
> 16 read and several (async) write requests at different disk locations in
> queue - make it 20. Seek time 10 ms => queue length 200 ms... probable???
> Do you have more than one disk? Try to run dbench on one and the player from
> the other.

Good idea.

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Dieter Nützel]

Am Donnerstag, 20. September 2001 23:29 schrieb Robert Love:
> On Thu, 2001-09-20 at 13:37, Roger Larsson wrote:
> > > Worst 20 latency times of 4261 measured in this period.
> > >   usec      cause     mask   start line/file      address   end
> > > line/file 4617   reacqBKL        0  1375/sched.c         c0114d94 
> > > 1381/sched.c
> >
> > This is fantastic! It REALLY is!
> > When we started with the low latency work we aimed at 10 ms.
> > (in all situations, not only when running dbench... but still)
>
> Yes it really is, especially noting that that 4.6ms lock is the
> _longest_ held lock on the system.
>
> I am seeing 90% of the reported locks under 15ms, and this means that
> almost all the locks on the system are even less.
>
> However, I am also seeing some stray 20-50ms and even 60-70ms latencies
> and those bother me.  I am looking into another solution, perhaps
> conditional scheduling for now.
>
> > Lets see - no swap used? - not swapped out

swap is enabled but not used by artsd (only 8 MB for X and some kdeinit stuff)

  810 nuetzel   -1 -20  6820    0 6820  4380 S <   0.0  1.0   0:31 artsd
 2724 nuetzel    8   0  6820    0 6820  4380 S     0.0  1.0   0:00 artsd

SunWave1>cat /proc/meminfo
        total:    used:    free:  shared: buffers:  cached:
Mem:  658395136 437657600 220737536        0  6656000 287236096
Swap: 1052794880  8990720 1043804160
MemTotal:       642964 kB
MemFree:        215564 kB
MemShared:           0 kB
Buffers:          6500 kB
Cached:         278396 kB
SwapCached:       2108 kB
Active:         265108 kB
Inactive:        21896 kB
HighTotal:           0 kB
HighFree:            0 kB
LowTotal:       642964 kB
LowFree:        215564 kB
SwapTotal:     1028120 kB
SwapFree:      1019340 kB

> > But with priority altered - it is unlikely that it would not be scheduled
> > in for such a long time.
> >
> > Might it be that the disk is busy to handle dbench requests. 16 threads
> > -> 16 read and several (async) write requests at different disk locations
> > in queue - make it 20. Seek time 10 ms => queue length 200 ms...
> > probable??? Do you have more than one disk? Try to run dbench on one and
> > the player from the other.

OK, I moved my video and sound files to one of my "older" IBM DDRS-9GB UW 
disks (read max ~12.8 MB/s).

Did NOT help. With and without renice -20.
Same hiccup (0.5~3 sec) during the first few seconds of dbench. The hiccup 
ONLY occur at the beginning of every dbench run.

-Dieter

PS At the bottom you can find the latency and time for this copy job.

Throughput 23.7919 MB/sec (NB=29.7399 MB/sec  237.919 MBit/sec)
7.470u 29.740s 1:29.79 41.4%    0+0k 0+0io 511pf+0w
load: 1300

SunWave1>cat /proc/latencytimes
Worst 20 latency times of 5890 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 13990  spin_lock        9  2043/tcp_ipv6.c      e9072837   119/softirq.c
 11596  spin_lock        1  2111/tcp_ipv4.c      c0207287   119/softirq.c
  4616   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  4478   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  2187        BKL        1  1302/inode.c         c016f359   697/sched.c
  2172   reacqBKL        1  1375/sched.c         c0114d94   929/namei.c
  1991        BKL        0  1302/inode.c         c016f359  1381/sched.c
  1966        BKL        1  1302/inode.c         c016f359   842/inode.c
  1934        BKL        0  1437/namei.c         c014c42f  1380/sched.c
  1891        BKL        0    30/inode.c         c016ce51   697/sched.c
  1879  spin_lock        0   547/sched.c         c0112fe4  1381/sched.c
  1865  spin_lock        0  1376/sched.c         c0114db3  1380/sched.c
  1833  spin_lock        1  1376/sched.c         c0114db3   697/sched.c
  1828        BKL        0    30/inode.c         c016ce51  1380/sched.c
  1812        BKL        0  1302/inode.c         c016f359  1380/sched.c
  1792        BKL        0  1437/namei.c         c014c42f  1381/sched.c
  1782  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
  1776        BKL        0  1437/namei.c         c014c42f   929/namei.c
  1772        BKL        1  1437/namei.c         c014c42f   697/sched.c
  1767        BKL        0   129/attr.c          c01576bd  1380/sched.c

SunWave1>cat /proc/latencytimes
Worst 20 latency times of 2260 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
   583        BKL        6   712/tty_io.c        c018cfcb   714/tty_io.c
   284        BKL        0    83/file.c          c0171024  1381/sched.c
   245        BKL        0  2763/buffer.c        c01410aa  1381/sched.c
   209        BKL        0  2763/buffer.c        c01410aa   697/sched.c
   204       eth1        0   585/irq.c           c010886f   647/irq.c
   193   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
   142   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
   111   reacqBKL        0  1375/sched.c         c0114d94    98/file.c
   109        BKL        0   452/exit.c          c011af61  1380/sched.c
   109        BKL        0   927/namei.c         c014b2bf   929/namei.c
    95        BKL        0   533/inode.c         c016d9cd   842/inode.c
    91        BKL        0  1870/namei.c         c014d420  1873/namei.c
    85    unknown        3    76/softirq.c       c011c634   119/softirq.c
    76        BKL        0    30/inode.c         c016ce51    52/inode.c
    64        BKL        1    26/readdir.c       c014ed07    28/readdir.c
    62  spin_lock        0  1715/dev.c           c01dc513  1728/dev.c
    54  spin_lock        2   468/netfilter.c     c01e4363   119/softirq.c
    49  spin_lock        0   991/dev.c           c01db583   998/dev.c
    47  spin_lock        0   547/sched.c         c0112fe4  1381/sched.c
    45        BKL        0  1302/inode.c         c016f359  1306/inode.c

renice -20 artsd
Throughput 27.6322 MB/sec (NB=34.5402 MB/sec  276.322 MBit/sec)
7.180u 30.180s 1:17.44 48.2%    0+0k 0+0io 511pf+0w
load: 1222

Worst 20 latency times of 6170 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
  4883  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
  3590        BKL        0  2763/buffer.c        c01410aa  1381/sched.c
  3192   reacqBKL        1  1375/sched.c         c0114d94   697/sched.c
  2647        BKL        0  1302/inode.c         c016f359   697/sched.c
  2286        BKL        0  1302/inode.c         c016f359  1381/sched.c
  2011        BKL        1  1437/namei.c         c014c42f   697/sched.c
  1795        BKL        1   452/exit.c          c011af61   697/sched.c
  1790        BKL        1  1302/inode.c         c016f359  1380/sched.c
  1725   reacqBKL        0  1375/sched.c         c0114d94  1381/sched.c
  1700  spin_lock        0   547/sched.c         c0112fe4  1381/sched.c
  1685        BKL        1  1437/namei.c         c014c42f  1380/sched.c
  1673        BKL        0  1437/namei.c         c014c42f  1381/sched.c
  1662        BKL        0    30/inode.c         c016ce51  1381/sched.c
  1575  spin_lock        0  1376/sched.c         c0114db3  1380/sched.c
  1565        BKL        0   533/inode.c         c016d9cd  1381/sched.c
  1452        BKL        0    30/inode.c         c016ce51   697/sched.c
  1452        BKL        0   533/inode.c         c016d9cd  1380/sched.c
  1445        BKL        0   927/namei.c         c014b2bf  1380/sched.c
  1423        BKL        0   129/attr.c          c01576bd  1381/sched.c
  1413        BKL        1   927/namei.c         c014b2bf   697/sched.c

SunWave1#du -s /usr/data/sounds/
263404  /usr/data/sounds

SunWave1#time cp -a /usr/data/sounds/ /database/db1/data/
0.080u 5.800s 1:03.06 9.3%      0+0k 0+0io 127pf+0w

SunWave1#du -s /database/db1/data/sounds/
263404  /database/db1/data/sounds

Worst 20 latency times of 3398 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
 10155  spin_lock        1   291/buffer.c        c014151c   285/buffer.c
  9028        BKL        8   152/devices.c       c013c282   154/devices.c
  7007   keyboard        9    76/softirq.c       c011c634   119/softirq.c
  5999  spin_lock        8    86/softirq.c       c011c66c   112/softirq.c
  4201  spin_lock        1   257/vmscan.c        c01331e6   286/vmscan.c
  4009  spin_lock        0   978/pc_keyb.c       c01a0787   983/pc_keyb.c
  3000  spin_lock        1   375/memory.c        c0127abf   389/memory.c
  1715  spin_lock        0   468/vmscan.c        c0133c35   431/vmscan.c
  1387  spin_lock        0   678/inode.c         c01566d7   704/inode.c
  1234   reacqBKL        1  1375/sched.c         c0114d94  1381/sched.c
  1071        BKL        1  1302/inode.c         c016f359  1380/sched.c
  1049  spin_lock        1   305/dcache.c        c0153acd    86/dcache.c
  1049  spin_lock        1   468/vmscan.c        c0133c35   344/vmscan.c
   968  spin_lock        1   547/sched.c         c0112fe4   697/sched.c
   950   reacqBKL        0  1375/sched.c         c0114d94   697/sched.c
   858       eth1        0   585/irq.c           c010886f   647/irq.c
   803        BKL        4   927/namei.c         c014b2bf   929/namei.c
   736        BKL        0   452/exit.c          c011af61   697/sched.c
   696        BKL        4  1870/namei.c         c014d420  1873/namei.c
   694        BKL        0  2763/buffer.c        c01410aa  1381/sched.c

c0141400 T kupdate
c014151c ..... <<<<<
c0141610 T set_buffer_async_io

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Thu, 2001-09-20 at 03:57, Dieter Nützel wrote:
> You've forgotten a one liner.
> 
>   #include <linux/locks.h>
> +#include <linux/compiler.h>
> 
> But this is not enough. Even with reniced artsd (-20).
> Some shorter hiccups (0.5~1 sec).


Note (I am repeated myself from an email I just sent) that the
conditional schedule won't show better results if
current->need_reschedule is unset, since preemption won't be enabled.  I
need to add explicit support to the preemption-test patch for this.

So you may see some better results, but just one time the condition
schedule does not occur, you will see the worst result in
/proc/latencytimes -- remembers its the 20 worst (perhaps we need
average or total latency, too?)

Now, with all that said, you should _see_ an improvement with this
patch.  You say short hiccups.  Some? All? How much better is it?

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Tobias Diedrich]

Should the patch work with SMP systems ?
Here is what I get:

Worst 20 latency times of 1322 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
988940   reacqBKL        0  1375/sched.c         c0117ba1   772/sched.c
988940  spin_lock        0   129/file_table.c    c013f500   135/page_alloc.c
988940  spin_lock        0   103/page_alloc.c    c0136fd9   251/timer.c
988940  spin_lock        0   129/file_table.c    c013f500   135/page_alloc.c
988940  spin_lock        0    63/fork.c          c0117efc   135/page_alloc.c
988940  spin_lock        0   129/file_table.c    c013f500   135/page_alloc.c
988940  spin_lock        0   129/file_table.c    c013f500   135/page_alloc.c
988940  spin_lock        0   592/af_unix.c       c02ddd88   594/af_unix.c
988940  spin_lock        0    43/fork.c          c0117ddc   829/inode.c
988940  spin_lock        0   547/sched.c         c0115bf5   606/signal.c
988940  spin_lock        0   770/sched.c         c011641c    80/dcache.c
988940  spin_lock        0    36/dec_and_lock.c  c0319573   280/time.c
988940  spin_lock        0    36/dec_and_lock.c  c0319573   280/time.c
988940        BKL        0   714/ll_rw_blk.c     c01eaec1    80/dcache.c
988939  spin_lock        0   592/af_unix.c       c02ddd88   594/af_unix.c
988939  spin_lock        0   714/ll_rw_blk.c     c01eaec1    80/dcache.c
988939    unknown        0    76/softirq.c       c011f410   782/sched.c
988939  spin_lock        0   592/af_unix.c       c02ddd88  1380/sched.c
988939  spin_lock        0   176/fork.c          c0118608   696/namei.c
988939  spin_lock        0  1684/af_unix.c       c02e0de6   734/dcache.c

And another one about 2 seconds after the last flush:

Worst 20 latency times of 579 measured in this period.
  usec      cause     mask   start line/file      address   end line/file
988939  spin_lock        0   592/af_unix.c       c02ddd88   133/file_table.c
988930  spin_lock        0   770/sched.c         c011641c   697/sched.c
988930  spin_lock        0   547/sched.c         c0115bf5   133/file_table.c
988930  spin_lock        0  1512/es1371.c        c02408e0   133/file_table.c
  6613  spin_lock        1   547/sched.c         c0115bf5   697/sched.c
  6401  spin_lock        0   547/sched.c         c0115bf5   647/irq.c
  2557  spin_lock        0   547/sched.c         c0115bf5   647/signal.c
   833  spin_lock        0   547/sched.c         c0115bf5   133/file_table.c
   364        BKL        6   710/tty_io.c        c01d1eed   712/tty_io.c
   283        BKL        4   710/tty_io.c        c01d1eed   280/time.c
   243        BKL        0    59/ioctl.c         c014fbe5   685/socket.c
   231        BKL        4   710/tty_io.c        c01d1eed   697/sched.c
   218  spin_lock        0   798/vmscan.c        c01366a5   857/vmscan.c
   210  spin_lock        0  3169/tcp_input.c     c02b5331   697/sched.c
   191  spin_lock        2   468/netfilter.c     c0285351   119/softirq.c
   183  spin_lock        0   468/netfilter.c     c0285351   280/time.c
   176  spin_lock        0   468/netfilter.c     c0285351   697/sched.c
   168        BKL        0    26/readdir.c       c014ff8c    28/readdir.c
   134       ide0        0   585/irq.c           c0108eb1   647/irq.c
   134        BKL        0   980/inode.c         c01691a3   997/inode.c

-- 
Tobias								PGP: 0x9AC7E0BC
Hannover Fantreffen ML: mailto:fantreffen-request@mantrha.de?subject=subscribe
Manga & Anime Treff Hannover: http://www.mantrha.de/

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Thu, 2001-09-20 at 16:01, Tobias Diedrich wrote:
> Should the patch work with SMP systems ?
> Here is what I get:

I never thought that it shouldn't, but upon thinking about it maybe it
won't :)

You are the second person reporting those all-the-same latency values. 
I think the SMP locks are being reported wrongly by the patch.  I will
take a look at it.

Thanks

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Andre Pang]

On Wed, Sep 19, 2001 at 06:44:09PM -0400, Robert Love wrote:

> Available at:
> http://tech9.net/rml/linux/patch-rml-2.4.9-ac12-preempt-stats-1 and
> http://tech9.net/rml/linux/patch-rml-2.4.10-pre12-preempt-stats-1
> for 2.4.9-ac12 and 2.4.10-pre12, respectively.

hi Robert, thanks for producing the stats patches!

i did a test of it on linux-2.4.10-pre13 with Benno Senoner's
lowlatency program, which i hacked up a bit to output
/proc/latencytimes after each of the graphs.  test results are at

    http://www.algorithm.com.au/hacking/linux-lowlatency/2.4.10-pre13-pes/

and since i stared at the results in disbelief, i won't even try
to guess what's going on :).  maybe you can make some sense of
it?

i'm prety sure his latencytest program runs at real-time
priority, but i'll run another test just with the getrt and rt
programs just posted to the list to make sure.  that's the only
reason i can think why the graph is so bizarre compared to the
/proc/latencytimes results.


-- 
#ozone/algorithm <ozone@algorithm.com.au>          - trust.in.love.to.save

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Fri, 2001-09-21 at 23:57, Andre Pang wrote:
> hi Robert, thanks for producing the stats patches!

no problem, but note that the original work was by MontaVista.  They
have contributed a lot to lowering latency in the Linux kernel.

I just spruced the patch up and updated it for the current kernels.

> i did a test of it on linux-2.4.10-pre13 with Benno Senoner's
> lowlatency program, which i hacked up a bit to output
> /proc/latencytimes after each of the graphs.  test results are at
> 
>     http://www.algorithm.com.au/hacking/linux-lowlatency/2.4.10-pre13-pes/
> 
> and since i stared at the results in disbelief, i won't even try
> to guess what's going on :).  maybe you can make some sense of
> it?

Well, its not hard to decipher...and really, its actually fairly good.
the latency test program is giving you a max latency of around 12ms in
each test, which is OK.

the preemption-test patch is showing _MAX_ latencies of 0.8ms through
12ms.  this is fine, too.

> i'm prety sure his latencytest program runs at real-time
> priority, but i'll run another test just with the getrt and rt
> programs just posted to the list to make sure.  that's the only
> reason i can think why the graph is so bizarre compared to the
> /proc/latencytimes results.

well, latencytest is showing you the end result of a certain set of
operations, with a final latency of 12ms.  the /proc interface is a bit
more specific, in that it shows you latencies over individual locks.

the latencies over the specific locks held during latencytest, plus the
time to execute the instructions outside of locks, is equal to 12ms. 
the correlation between max lock and latencytest is not 1-to-1.

in an ideal world, you want latencytest to show you 10ms or less, which
we are pretty close to by your results, and you want most of your locks
under 1ms, which we also achieve since of your top 20 locks out of 20k+,
we see many still around 1ms.

thank you for these data points...

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Andre Pang]

On Sat, Sep 22, 2001 at 02:10:18AM -0400, Robert Love wrote:

> > i did a test of it on linux-2.4.10-pre13 with Benno Senoner's
> > lowlatency program, which i hacked up a bit to output
> > /proc/latencytimes after each of the graphs.  test results are at
> > 
> >     http://www.algorithm.com.au/hacking/linux-lowlatency/2.4.10-pre13-pes/
> > 
> > and since i stared at the results in disbelief, i won't even try
> > to guess what's going on :).  maybe you can make some sense of
> > it?
> 
> Well, its not hard to decipher...and really, its actually fairly good.
> the latency test program is giving you a max latency of around 12ms in
> each test, which is OK.

arrgh!  i just realised my script buggered up and was producing the same
graph for all the results.  please have a look at the page again, sorry.

apart from that, i'm still confused.  compared to other graphs produced
by the latencytest program, my system seems to have huge latencies.
unless i'm reading it wrongly, the graph is saying that i'm getting
latencies of up to 30ms, and a lot of overruns.  compare this to

    http://www.gardena.net/benno/linux/audio/2.4.0-test2/3x256.html

which shows latencytest on 2.4.0-test2, and

    http://www.gardena.net/benno/linux/audio/2.2.10-p133-3x128/3x128.html

which are the results for latencytest on 2.2.10.  admittedly these
kernels are much older, but i'm consistently getting far more latency
than those kernels.  that's the bit i'm confused about :)  i've tried
Andrew Morton's low-latency patches as well, to no avail.  i've made
sure i've tuned my hard disks correctly, and i don't have any other
realtime processes running.

am i concerned with a different issue than the one you're addressing?

> the preemption-test patch is showing _MAX_ latencies of 0.8ms through
> 12ms.  this is fine, too.

yep, i agree with that ... so why is latencytest showing scheduling
latencies of > 30ms?  i get the feeling i'm confusing two different
issues here.  from what i understand, /proc/latencytimes shows the
how long it takes for various functions in the kernel to finish, and
the latencytest result shows how long it takes for it to be
re-scheduled (represented by the white line on the graph).


-- 
#ozone/algorithm <ozone@algorithm.com.au>          - trust.in.love.to.save

Re: [PATCH] Preemption Latency Measurement Tool

[george anzinger]

Andre Pang wrote:
> 
> On Sat, Sep 22, 2001 at 02:10:18AM -0400, Robert Love wrote:
> 
> > > i did a test of it on linux-2.4.10-pre13 with Benno Senoner's
> > > lowlatency program, which i hacked up a bit to output
> > > /proc/latencytimes after each of the graphs.  test results are at
> > >
> > >     http://www.algorithm.com.au/hacking/linux-lowlatency/2.4.10-pre13-pes/
> > >
> > > and since i stared at the results in disbelief, i won't even try
> > > to guess what's going on :).  maybe you can make some sense of
> > > it?
> >
> > Well, its not hard to decipher...and really, its actually fairly good.
> > the latency test program is giving you a max latency of around 12ms in
> > each test, which is OK.
> 
> arrgh!  i just realised my script buggered up and was producing the same
> graph for all the results.  please have a look at the page again, sorry.
> 
> apart from that, i'm still confused.  compared to other graphs produced
> by the latencytest program, my system seems to have huge latencies.
> unless i'm reading it wrongly, the graph is saying that i'm getting
> latencies of up to 30ms, and a lot of overruns.  compare this to
> 
>     http://www.gardena.net/benno/linux/audio/2.4.0-test2/3x256.html
> 
> which shows latencytest on 2.4.0-test2, and
> 
>     http://www.gardena.net/benno/linux/audio/2.2.10-p133-3x128/3x128.html
> 
> which are the results for latencytest on 2.2.10.  admittedly these
> kernels are much older, but i'm consistently getting far more latency
> than those kernels.  that's the bit i'm confused about :)  i've tried
> Andrew Morton's low-latency patches as well, to no avail.  i've made
> sure i've tuned my hard disks correctly, and i don't have any other
> realtime processes running.
> 
> am i concerned with a different issue than the one you're addressing?
> 
> > the preemption-test patch is showing _MAX_ latencies of 0.8ms through
> > 12ms.  this is fine, too.
> 
> yep, i agree with that ... so why is latencytest showing scheduling
> latencies of > 30ms?  i get the feeling i'm confusing two different
> issues here.  from what i understand, /proc/latencytimes shows the
> how long it takes for various functions in the kernel to finish, and
> the latencytest result shows how long it takes for it to be
> re-scheduled (represented by the white line on the graph).

The one thing the latancytimes patch doesn't monitor is interrupt off
time.  Maybe it should...


George

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Sat, 2001-09-22 at 23:18, george anzinger wrote:
> The one thing the latancytimes patch doesn't monitor is interrupt off
> time.  Maybe it should...

Yes, it should.  And it could... I will add this.

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Sat, 2001-09-22 at 03:22, Andre Pang wrote:
> arrgh!  i just realised my script buggered up and was producing the same
> graph for all the results.  please have a look at the page again, sorry.

no problem...

> apart from that, i'm still confused.  compared to other graphs produced
> by the latencytest program, my system seems to have huge latencies.
> unless i'm reading it wrongly, the graph is saying that i'm getting
> latencies of up to 30ms, and a lot of overruns.  compare this to
> 
>     http://www.gardena.net/benno/linux/audio/2.4.0-test2/3x256.html
> 
> which shows latencytest on 2.4.0-test2, and
> 
>     http://www.gardena.net/benno/linux/audio/2.2.10-p133-3x128/3x128.html
> 
> which are the results for latencytest on 2.2.10.  admittedly these
> kernels are much older, but i'm consistently getting far more latency
> than those kernels.  that's the bit i'm confused about :)  i've tried
> Andrew Morton's low-latency patches as well, to no avail.  i've made
> sure i've tuned my hard disks correctly, and i don't have any other
> realtime processes running.
> 
> am i concerned with a different issue than the one you're addressing?

No, I understand now.  I honestly don't know what to say about your
results.

You are right, those older kernels are showing much better response
times than your kernel.  One would think your newer kernel, with
preemption or low-latency patch, would be an improvement.

I honestly don't know what to tell you.  It could be a piece of hardware
(or, more accurately) its driver ... 

the /proc/latencytimes output shows us that no single lock is accounting
for your bad times.  In fact, all your locks aren't that bad, so...

maybe the problem is in the "overruns" -- I don't know what that means
exactly.  maybe someone else on the list can shed some light? 
otheriwse, you can email the author perhaps.

With whatever buffer or whatnot is overrunning (and you are getting a
bit of them, compared to those other URLs you posted), something is
stalling or repeating.

> > the preemption-test patch is showing _MAX_ latencies of 0.8ms through
> > 12ms.  this is fine, too.
> 
> yep, i agree with that ... so why is latencytest showing scheduling
> latencies of > 30ms?  i get the feeling i'm confusing two different
> issues here.  from what i understand, /proc/latencytimes shows the
> how long it takes for various functions in the kernel to finish, and
> the latencytest result shows how long it takes for it to be
> re-scheduled (represented by the white line on the graph).

Pretty much.

/proc/latencytimes shows you how long specific locks are held in the
kernel, so this isn't the same as how long certain functions take (which
could be longer or shorter).  The reason for showing lock duration is
that preemption (with the preemptible kernel patch) can not occur during
a lock for concurrency reasons, so we want to find long-held locks and
try to find a solution to them.

latencytest does indeed show scheduling latency.  it tries to show you
how well the system can keep up with the audio buffer.  with a
preemptible kernel, you can reduce this latency to a very small number,
baring any large locks (from above).

latencytest's latency is a function of the sum of the latencies reported
by /proc/latencytimes. thus, a bad latency in latencytest could be
caused by what you see in /proc/latencytest.  you would think we would
see one or two long locks screwing everything up, but we do not.

I would try to see what the overruns mean exactly, and see if any
hardware drivers could be at fault (right now we don't report time with
interrupts disabled in /proc/latencytimes, which could be a factor too).

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

Re: [PATCH] Preemption Latency Measurement Tool

[Andre Pang]

On Sun, Sep 23, 2001 at 03:05:41AM -0400, Robert Love wrote:

> You are right, those older kernels are showing much better response
> times than your kernel.  One would think your newer kernel, with
> preemption or low-latency patch, would be an improvement.
> 
> I honestly don't know what to tell you.  It could be a piece of hardware
> (or, more accurately) its driver ... 

I found out why, it's the driver.  I'm an idiot for not trying
this before ... I was previously using ALSA's snd-card-ymfpci
driver; I switchted to the OSS ymfpci driver that comes with the
kernel.  My latencies used to be 15ms on average, with spikes >
30ms; they're now ~3ms with some occasional spikes up to 10ms.

The graphs and numbers are up at
http://www.algorithm.com.au/hacking/linux-lowlatency/

> the /proc/latencytimes output shows us that no single lock is accounting
> for your bad times.  In fact, all your locks aren't that bad, so...
> 
> maybe the problem is in the "overruns" -- I don't know what that means
> exactly.  maybe someone else on the list can shed some light? 
> otheriwse, you can email the author perhaps.

An over-run occurs when the latencytest program, which plays a
continuous sound, doesn't get re-scheduled quickly enough.  This
results in a sound dropout because it can't re-fill its buffer.
This is similar to what you would get in XMMS, except that
latencytest simulates professional audio applications which must
run with _very_ small buffers in order to get low latencies.
(Imagine your computer being sync'ed in realtime with lots of
other music equipment and have it drag behind by 30ms -- it
doesn't sound good :).

But I guess my problem's solved ... thanks so much to Andrew,
yourself, MontaVista, Dietel and all the other guys who spend
their hours benchmarking so this can be improved!  If you still
want me to run benchmarks, let me know.  The 15 kernels I've
compiled since starting testing have gotta be useful for
something.


-- 
#ozone/algorithm <ozone@algorithm.com.au>          - trust.in.love.to.save

Re: [PATCH] Preemption Latency Measurement Tool

[Robert Love]

On Sun, 2001-09-23 at 08:03, Andre Pang wrote:
> I found out why, it's the driver.  I'm an idiot for not trying
> this before ... I was previously using ALSA's snd-card-ymfpci
> driver; I switchted to the OSS ymfpci driver that comes with the
> kernel.  My latencies used to be 15ms on average, with spikes >
> 30ms; they're now ~3ms with some occasional spikes up to 10ms.

You are the second or third person to report high latencies with ALSA
drivers.  I wonder what braindead locking they do?

Good find.

> The graphs and numbers are up at
> http://www.algorithm.com.au/hacking/linux-lowlatency/

Nice results.

> > maybe the problem is in the "overruns" -- I don't know what that means
> > exactly.  maybe someone else on the list can shed some light? 
> > otheriwse, you can email the author perhaps.
> 
> An over-run occurs when the latencytest program, which plays a
> continuous sound, doesn't get re-scheduled quickly enough.  This
> results in a sound dropout because it can't re-fill its buffer.
> This is similar to what you would get in XMMS, except that
> latencytest simulates professional audio applications which must
> run with _very_ small buffers in order to get low latencies.
> (Imagine your computer being sync'ed in realtime with lots of
> other music equipment and have it drag behind by 30ms -- it
> doesn't sound good :).

Oh, ok -- its pretty much the number of times the scheduling latency was
greater than the audio buffer time.

> But I guess my problem's solved ... thanks so much to Andrew,
> yourself, MontaVista, Dietel and all the other guys who spend
> their hours benchmarking so this can be improved!  If you still
> want me to run benchmarks, let me know.  The 15 kernels I've
> compiled since starting testing have gotta be useful for
> something.

You are welcome :)

I should probably take a look at ALSA stuff and see if I can find what
exactly is the culprit.

Thank you for the feedback, now we know.

-- 
Robert M. Love
rml at ufl.edu
rml at tech9.net

ksoftirqd? (Was: Re: [PATCH] Preemption Latency Measurement Tool)

[Roger Larsson]

Hi,

We have a new kid on the block since we started thinking of a preemptive 
kernel.

ksoftirqd...

Running with nice 19 (shouldn't it really be -19?)
Or have a RT setting? (maybe not since one of the reasons for
softirqd would be lost - would be scheduled in immediately)
Can't a high prio or RT process be starved due to missing
service (bh) after an interrupt?

This will not show up in latency profiling patches since
the kernel does what is requested...

Previously it was run directly after interrupt,
before returning to the interrupted process...

See:
  /usr/src/develop/linux/kernel/softirq.c

/RogerL

-- 
Roger Larsson
Skellefteå
Sweden

Re: ksoftirqd? (Was: Re: [PATCH] Preemption Latency Measurement Tool)

[Andrea Arcangeli]

On Sat, Sep 22, 2001 at 02:56:58PM +0200, Roger Larsson wrote:
> Hi,
> 
> We have a new kid on the block since we started thinking of a preemptive 
> kernel.
> 
> ksoftirqd...
> 
> Running with nice 19 (shouldn't it really be -19?)
> Or have a RT setting? (maybe not since one of the reasons for
> softirqd would be lost - would be scheduled in immediately)
> Can't a high prio or RT process be starved due to missing
> service (bh) after an interrupt?

It cannot be starved, if ksoftirqd is never scheduled the do_softirq()
will be run by the next timer irq or apic_timer irq.

> This will not show up in latency profiling patches since
> the kernel does what is requested...
> 
> Previously it was run directly after interrupt,
> before returning to the interrupted process...

It is still the case, that's also the common case actually.

Andrea

Re: ksoftirqd? (Was: Re: [PATCH] Preemption Latency Measurement Tool)

[Roger Larsson]

On Saturday 22 September 2001 15.14, Andrea Arcangeli wrote:
> On Sat, Sep 22, 2001 at 02:56:58PM +0200, Roger Larsson wrote:
> > Hi,
> >
> > We have a new kid on the block since we started thinking of a preemptive
> > kernel.
> >
> > ksoftirqd...
> >
> > Running with nice 19 (shouldn't it really be -19?)

I repeat this question - should it be nice 19 and not nice -19 (not nice)?

> > Or have a RT setting? (maybe not since one of the reasons for
> > softirqd would be lost - would be scheduled in immediately)
> > Can't a high prio or RT process be starved due to missing
> > service (bh) after an interrupt?
>
> It cannot be starved, if ksoftirqd is never scheduled the do_softirq()
> will be run by the next timer irq or apic_timer irq.
>

Then could you please explain the output after adding a printk in
ksoftirqd like this.

--- kernel/softirq.c~   Mon Sep 17 22:37:34 2001
+++ kernel/softirq.c    Sat Sep 22 21:46:49 2001
@@ -387,6 +387,7 @@
                __set_current_state(TASK_RUNNING);

                while (softirq_pending(cpu)) {
+                       printk("ksoftirqd: do_softirq\n");
                        do_softirq();
                        if (current->need_resched)
                                schedule();


Output like this:

Sep 22 22:37:38 jeloin logger: *** ./stress_dbench begin ***
Sep 22 22:37:42 jeloin kernel: ksoftirqd: do_softirq
Sep 22 22:37:44 jeloin last message repeated 2 times
Sep 22 22:37:48 jeloin kernel: Latency   8ms PID     7 %% kupdated
Sep 22 22:37:49 jeloin kernel: ksoftirqd: do_softirq
Sep 22 22:38:19 jeloin last message repeated 18 times
Sep 22 22:38:20 jeloin su: (to root) roger on /dev/pts/2
Sep 22 22:38:20 jeloin PAM-unix2[988]: session started for user root, service 
su
Sep 22 22:38:23 jeloin kernel: ksoftirqd: do_softirq
Sep 22 22:38:24 jeloin modprobe: modprobe: Can't locate module net-pf-10
Sep 22 22:38:24 jeloin kernel: ksoftirqd: do_softirq
Sep 22 22:38:58 jeloin last message repeated 20 times
Sep 22 22:39:05 jeloin last message repeated 4 times
Sep 22 22:42:03 jeloin kernel: ksoftirqd: do_softirq
Sep 22 22:43:58 jeloin logger: *** ./stress_dbench end ***

> > This will not show up in latency profiling patches since
> > the kernel does what is requested...
> >
> > Previously it was run directly after interrupt,
> > before returning to the interrupted process...
>
> It is still the case, that's also the common case actually.
>

Possibly but the other case is quite common too...

/RogerL

-- 
Roger Larsson
Skellefteå
Sweden

Re: ksoftirqd? (Was: Re: [PATCH] Preemption Latency Measurement Tool)

[Andrea Arcangeli]

On Sat, Sep 22, 2001 at 10:51:16PM +0200, Roger Larsson wrote:
> On Saturday 22 September 2001 15.14, Andrea Arcangeli wrote:
> > On Sat, Sep 22, 2001 at 02:56:58PM +0200, Roger Larsson wrote:
> > > Hi,
> > >
> > > We have a new kid on the block since we started thinking of a preemptive
> > > kernel.
> > >
> > > ksoftirqd...
> > >
> > > Running with nice 19 (shouldn't it really be -19?)
> 
> I repeat this question - should it be nice 19 and not nice -19 (not nice)?

Being it +19 it is light with respect to the other tasks in the system,
mainly considering there's one for each cpu.

> Sep 22 22:37:38 jeloin logger: *** ./stress_dbench begin ***
> Sep 22 22:37:42 jeloin kernel: ksoftirqd: do_softirq
> Sep 22 22:37:44 jeloin last message repeated 2 times
> Sep 22 22:37:48 jeloin kernel: Latency   8ms PID     7 %% kupdated
> Sep 22 22:37:49 jeloin kernel: ksoftirqd: do_softirq
> Sep 22 22:38:19 jeloin last message repeated 18 times
> Sep 22 22:38:20 jeloin su: (to root) roger on /dev/pts/2
> Sep 22 22:38:20 jeloin PAM-unix2[988]: session started for user root, service 
> su
> Sep 22 22:38:23 jeloin kernel: ksoftirqd: do_softirq
> Sep 22 22:38:24 jeloin modprobe: modprobe: Can't locate module net-pf-10
> Sep 22 22:38:24 jeloin kernel: ksoftirqd: do_softirq
> Sep 22 22:38:58 jeloin last message repeated 20 times
> Sep 22 22:39:05 jeloin last message repeated 4 times
> Sep 22 22:42:03 jeloin kernel: ksoftirqd: do_softirq
> Sep 22 22:43:58 jeloin logger: *** ./stress_dbench end ***

one reschedule every few seconds sounds ok.

> Possibly but the other case is quite common too...

if you try to put a printk also in do_softirq you'll see why it is
not the common case :)

also you may want to put the printk in the schedule() path, ksoftirqd
may just be rescheduled once, and run many of the do_softirq().

Andrea