[linux-audio-dev] Re: [Freebob-devel] [REQUEST] test the influence of linux1394 kernel drivers on scheduling latency

[Jonathan Woithe]

Pieter Palmers wrote:

> This weekend I've discovered a (serious) kernel scheduling latency issue 
> with the current ieee1394 kernel drivers. Before I submit something 
> about this to lkml, I'd like some more tests. I've been able to 
> reproduce this on two different machines, so I suspect that this is a 
> more general problem.

I ran the tests quickly on my firewire development machine overnight. First
I started the latency monitor and left it run for about 10 minutes while I
did other things, including accessing a USB stick.  I then started the
ieee1394 stress tester; almost immediately the monitor noted maximum
latencies of the order of 1 ms (compared to tens of microseconds when the
stress tester wasn't running).  The output is blow.

  > ./latency_histogram -p 80 -n 128 -t 1 -s 1
  Histogram size: 128 bins, bin size: 1us, last bin: 128us
  aquiring RT scheduling with priority 80 ... 
  getting cpu speed... 
  67547857.763 Hz (67.548 MHz)
  Sleeping for 1us between timer reads...
  Running, press CTRL-C to stop...
   (+) New maximum: 62 cycles, 0.917868
   (-) New minimum: 62 cycles, 0.917868
   (-) New minimum: 58 cycles, 0.858650
   (+) New maximum: 298 cycles, 4.411687
   (+) New maximum: 43475 cycles, 643.617747
   (+) New maximum: 48239 cycles, 714.145520
   (+) New maximum: 52924 cycles, 783.503752
   (+) New maximum: 131949 cycles, 1953.415021
   (+) New maximum: 170136 cycles, 2518.747532
  # of iterations: 243335
  max. difference: 170136 cycles, 2518.747532us
  min. difference: 58 cycles, 0.858650us
  avg. difference: 66 cycles, 0.989601us
  
  Histogram
  ---------
   =<        1us:       33
          1us   :   243285
          2us   :        9
          3us   :        1
          4us   :        3
          5us   :        2
          6us   :        1
          7us   :        1
                       ...
   >=      128us:       33

The "New maximum: 298 cycles" appeared very soon after the stress
tester was started, with the ones below it following soon after.

Despite what the log says, this was running a 2.0 GHz "Dothan" Centrino CPU.
Kernel was 2.6.16-rt25, distro was Slackware 10.2.  Both the stress tester
and the monitor were run with RT privilege access.  The firewire interface
used has a TI OHCI chipset.

I apologise that the run was particularly short and that therefore the
statistics aren't particularly good, but it does seem to confirm the
observations you made on your machine.  The large latencies only occur
when the stress tester is running.

Regards
  jonathan