Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Eran Mann]

> Hi Ingo,
> 
> I'm getting this error with V0.7.31-13
> 
...
> CC kernel/latency.o
> kernel/latency.c: In function `check_critical_timing':
> kernel/latency.c:730: too few arguments to function `___trace'
> kernel/latency.c:730: warning: too few arguments passed to inline function, suppressing inlining
> kernel/latency.c: In function `__start_critical_timing':
> kernel/latency.c:810: incompatible type for argument 1 of `____trace'
> kernel/latency.c:810: warning: passing arg 2 of `____trace' makes pointer from integer without a cast
...

> kernel/latency.c:810: warning: too few arguments passed to inline function, suppressing inlining
> make[1]: *** [kernel/latency.o] Error 1
> make: *** [kernel] Error 2
> [root@tigre01 im]#
> 
> Regards
> Remi
I'm guessing here, but with the following patch it at least compiles:

--- kernel/latency.c.orig       2004-11-28 21:32:04.757015856 +0200
+++ kernel/latency.c    2004-11-28 21:28:28.000000000 +0200
@@ -727,7 +727,7 @@
         tr->critical_end = parent_eip;

  #ifdef CONFIG_LATENCY_TRACE
-       ___trace(CALLER_ADDR0, parent_eip);
+       ___trace(TRACE_FN, CALLER_ADDR0, parent_eip, 0, 0, 0);
         update_max_trace(tr);
  #endif

@@ -807,7 +807,7 @@
         tr->critical_start = eip;
  #ifdef CONFIG_LATENCY_TRACE
         tr->trace_idx = 0;
-       ____trace(tr, eip, parent_eip, 0, 0, 0);
+       ____trace(TRACE_FN, tr, eip, parent_eip, 0, 0, 0);
  #endif

         atomic_dec(&tr->disabled);

-- 
Eran Mann
Senior Software Engineer
MRV International
Tel: 972-4-9936297
Fax: 972-4-9890430
www.mrv.com

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Eran Mann <emann@mrv.com> wrote:

> I'm guessing here, but with the following patch it at least compiles:

yeah, this is the correct patch, included in the -31-14 and later
patches.

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Gene Heskett]

On Tuesday 30 November 2004 03:58, Ingo Molnar wrote:
>* Eran Mann <emann@mrv.com> wrote:
>> I'm guessing here, but with the following patch it at least
>> compiles:
>
>yeah, this is the correct patch, included in the -31-14 and later
>patches.
>
> Ingo

I hadn't hit this one yet, up since about midnight with -13, and just 
now found -15 so I'll build it.

-- 
Cheers, Gene
"There are four boxes to be used in defense of liberty:
 soap, ballot, jury, and ammo. Please use in that order."
-Ed Howdershelt (Author)
99.29% setiathome rank, not too shabby for a WV hillbilly
Yahoo.com attorneys please note, additions to this message
by Gene Heskett are:
Copyright 2004 by Maurice Eugene Heskett, all rights reserved.

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Mark_H_Johnson]

>interesting numbers. The slowdown in networking could easily be due to
>IRQ and softirq threading, so it would make sense to also add a "PNT"
>test (preempt, non-threaded), just to have something functionally
>comparable to 2.4 lowlat+preempt.
Unless I am mistaken, my "PK" config is the closest to 2.4 lowlat+preempt.
For the relevant differences in .config:
  PK                                  RT
  CONFIG_PREEMPT_DESKTOP=y            CONFIG_PREEMPT_DESKTOP is not set
  CONFIG_PREEMPT_RT is not set        CONFIG_PREEMPT_RT=y
  CONFIG_PREEMPT=y                    CONFIG_PREEMPT=y
  CONFIG_PREEMPT_SOFTIRQS is not set  CONFIG_PREEMPT_SOFTIRQS=y
  CONFIG_PREEMPT_HARDIRQS is not set  CONFIG_PREEMPT_HARDIRQS=y
(though the system still creates ksoftirqd/0 and /1 on both...)
  CONFIG_SPINLOCK_BKL is not set      [not present]
  CONFIG_PREEMPT_BKL=y                CONFIG_PREEMPT_BKL=y
  CONFIG_ASM_SEMAPHORES=y             [not present]
  CONFIG_RWSEM_XCHGADD_ALGORITHM=y    [not present]
  ...
  [not present]                       CONFIG_RT_DEADLOCK_DETECT=y
  ...

Unless you are saying that I should back off to one of the other
preempt settings (to replicate the 2.4 config on 2.6).

Also, I ran another set of tests with -15 late yesterday. The
results were not necessarily consistent with -9. I had to run
the -PK tests twice due to an error that
  /dev/dsp was busy
which aborted one of the latencytest runs (not the first one...).
The line below with "dnr" is from that run.

[the -15 data follows in the same format as the -9 data yesterday]
The 2.4 numbers are from 2.4.24 w/ low latency / preempt patches.

      within 100 usec
       CPU loop (%)   Elapsed Time (sec)    2.4
Test    PK     RT       PK      RT   |   CPU  Elapsed
X     99.66  99.22      53 *    68   |  97.20   70
top   99.92  97.96     240+     34   |  97.48   29
neto    dnr  99.98     dnr     360   |  96.23   36
neti  98.22  98.31     270 *   350   |  95.86   41
diskw 94.11  99.57     295+*   360 * |  77.64   29
diskc 99.67  97.49     310+*   360   |  84.12   77
diskr 99.52  98.35     310+*   180   |  90.66   86
total                 1478    1712   |         368
did not count neto in this total^^
* wide variation in audio duration
+ had long stretches of audio duration well below the nominal
duration

Both the -PK and -RT tests had long pauses where the sampling
scripts I use did not capture any data. The profile script had
elapsed times of 77, 192, 52, 106, 305, and 82 seconds [for a
5 second sleep]. The load average after each of these pauses
ranged from 8.8 to 16.1. It still looks like the cpu_burn program
(non RT, nice) is starving the other normal non RT tasks
(should not happen...).

I am still getting lots of truncated latency_trace results.

The latency_trace output doesn't seem to get the process name
right. Most traces look something like this [truncated example]

preemption latency trace v1.1.1 on 2.6.10-rc2-mm3-V0.7.31-15RT
--------------------------------------------------------
 latency: 102 us, entries: 1(1)    |   [VP:0 KP:1 SP:1 HP:1 #CPUS:2]
    -----------------
    | task: cat/9789, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: buffered_rmqueue+0x69/0x180 <c014f859>
 => ended at:   buffered_rmqueue+0xa3/0x180 <c014f89e>
========>
<unknown-9789 80000000 0.000ms (+0.000ms): buffered_rmqueue (__alloc_pages)

So the name is correct in the header but not in the trace lines in
most (but not ALL) cases. I have another example where IRQ 0/2 was
traced and its lines were OK in the trace, but I had references to
unknown-2036, unknown-2044, and unknown-3802 in the trace. This
one example appeared to be a task switch from unknown-2036 to
IRQ 0-2 and the traces are OK after the line with __switch_to in it.
Let me know if you need examples (I have plenty to choose from).

--Mark H Johnson
  <mailto:Mark_H_Johnson@raytheon.com>

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> Unless I am mistaken, my "PK" config is the closest to 2.4 lowlat+preempt.

indeed, you are right.

> For the relevant differences in .config:
>   PK                                  RT
>   CONFIG_PREEMPT_DESKTOP=y            CONFIG_PREEMPT_DESKTOP is not set
>   CONFIG_PREEMPT_RT is not set        CONFIG_PREEMPT_RT=y
>   CONFIG_PREEMPT=y                    CONFIG_PREEMPT=y
>   CONFIG_PREEMPT_SOFTIRQS is not set  CONFIG_PREEMPT_SOFTIRQS=y
>   CONFIG_PREEMPT_HARDIRQS is not set  CONFIG_PREEMPT_HARDIRQS=y
> (though the system still creates ksoftirqd/0 and /1 on both...)
>   CONFIG_SPINLOCK_BKL is not set      [not present]
>   CONFIG_PREEMPT_BKL=y                CONFIG_PREEMPT_BKL=y
>   CONFIG_ASM_SEMAPHORES=y             [not present]
>   CONFIG_RWSEM_XCHGADD_ALGORITHM=y    [not present]
>   ...
>   [not present]                       CONFIG_RT_DEADLOCK_DETECT=y
>   ...

the only thing i'd suggest to change is to also generate an RT (and 
perhaps PK) result with all debugging options disabled - i.e. both 
RT_DEADLOCK_DETECT and all LATENCY_TRACING/timing related options 
disabled.

but your tests did trigger asserts not so long ago so it might not be
wise to run without debugging. But it's definitely a thing to try in the
future.

> Unless you are saying that I should back off to one of the other
> preempt settings (to replicate the 2.4 config on 2.6).

no, i think the PK kernel is supposed to be quite close to what
2.4+lowlat offers.

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Mark_H_Johnson]

I have results from two builds of -V0.7.31-9. The first
build is CONFIG_RT (RT) and the second is CONFIG_DESKTOP (PK or
as described in .config help - Preempt Kernel).

Both booted OK - so the SMP lockup on _DESKTOP appears to
be fixed. Both ran my test series faster than previous 2.6
kernels. I was seeing run times over 30 minutes before
(mainly due to starvation of non-RT tasks) but both completed
in about 20 minutes.

General notes:

[1] Audio duration was much more variable on the PK than the
RT kernel. The variability on PK audio duration is about 30%
of nominal time. The RT kernel was less variable but tended to
finish well before the nominal time (and you could hear the
difference). The PK results look like buffering inside ALSA
that was not present in OSS?. Not sure why the RT kernel
is almost always finishing too soon.

[2] The PK kernel has much longer latencies as measured by
the in kernel tracing code. The RT kernel basically had NO
latencies > 50 usec where the PK kernel had several over a
millisecond (usually related to disk writes). By this measure
the RT kernel is clearly better.

[3] The overhead of RT (as measured by the CPU loop timing and
by pings from remote systems) is more than the PK kernel. I
believe this is due to the IRQ threading overhead. By these
measures, the PK kernel is better. By elapsed time, the 2.4
kernel is far superior.

More specifics:
The 2.4 numbers are from 2.4.24 w/ low latency / preempt patches.

      within 100 usec
       CPU loop (%)   Elapsed Time (sec)    2.4
Test    PK     RT       PK      RT   |   CPU  Elapsed
X     99.69  99.34      90      70   |  97.20   70
top   99.31  98.33      30      31   |  97.48   29
neto  97.28  97.69     205     315   |  96.23   36
neti  97.76  98.11     198     325   |  95.86   41
diskw 69.16* 94.98      51     115   |  77.64   29
diskc 96.44  98.39     230     250   |  84.12   77
diskr 99.60  98.77     240     180   |  90.66   86
total                 1044    1286   |         368

* several multiple millisecond latencies measured by the
tracing code. Will send traces separately.

           min     ave       max     mdev
PK ping - 0.100 / 0.176 /   1.009 / 0.053
RT ping - 0.194 / 0.322 / 527.635 / 2.263
[not sure why the high max on RT, but I did see a few
1 msec or longer ping responses and many over 400 usec]

--Mark H Johnson
  <mailto:Mark_H_Johnson@raytheon.com>

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Mark_H_Johnson@Raytheon.com <Mark_H_Johnson@Raytheon.com> wrote:

> I have results from two builds of -V0.7.31-9. The first build is
> CONFIG_RT (RT) and the second is CONFIG_DESKTOP (PK or as described in
> .config help - Preempt Kernel).

interesting numbers. The slowdown in networking could easily be due to
IRQ and softirq threading, so it would make sense to also add a "PNT"
test (preempt, non-threaded), just to have something functionally
comparable to 2.4 lowlat+preempt.

	Ingo

Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Rui Nuno Capela]

Hi Ingo et al.

(Sorry on the previous post, touched the wrong button :)


I'm sending (sent) some XRUN latencies captured just a minute ago.

  xruntrace1.0.tar.gz
     - scripts used for xrun trace capture automation

  xruntrace1-2.6.10-rc2-mm3-RT-V0.7.31-7.tar.gz
     - actual xrun traces captured while running jackd on RT-V0.7.31-7

  config-2.6.10-rc2-mm3-RT-V0.7.31-7.gz
     - kernel configuration as of my laptop, taken from /proc/config.gz

Cheers.
-- 
rncbc aka Rui Nuno Capela
rncbc@rncbc.org

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Rui Nuno Capela <rncbc@rncbc.org> wrote:

>   config-2.6.10-rc2-mm3-RT-V0.7.31-7.gz
>      - kernel configuration as of my laptop, taken from /proc/config.gz

Here are some .config suggestion to reduce tracing costs. Here's the
relevant portion of your .config:

 CONFIG_DEBUG_KERNEL=y
 CONFIG_MAGIC_SYSRQ=y
 # CONFIG_SCHEDSTATS is not set
 # CONFIG_DEBUG_SLAB is not set
 CONFIG_DEBUG_PREEMPT=y
 CONFIG_WAKEUP_TIMING=y
 CONFIG_PREEMPT_TRACE=y
 CONFIG_CRITICAL_PREEMPT_TIMING=y
 CONFIG_CRITICAL_IRQSOFF_TIMING=y
 CONFIG_CRITICAL_TIMING=y
 CONFIG_LATENCY_TIMING=y
 CONFIG_LATENCY_TRACE=y
 CONFIG_MCOUNT=y
 CONFIG_RT_DEADLOCK_DETECT=y
 # CONFIG_DEBUG_KOBJECT is not set
 CONFIG_DEBUG_BUGVERBOSE=y
 # CONFIG_DEBUG_INFO is not set
 CONFIG_FRAME_POINTER=y
 CONFIG_EARLY_PRINTK=y
 CONFIG_DEBUG_STACKOVERFLOW=y

i'd suggest to use the following one:

 CONFIG_DEBUG_KERNEL=y
 CONFIG_MAGIC_SYSRQ=y
 # CONFIG_SCHEDSTATS is not set
 # CONFIG_DEBUG_SLAB is not set
 # CONFIG_DEBUG_PREEMPT is not set
 # CONFIG_DEBUG_SPINLOCK_SLEEP is not set
 CONFIG_WAKEUP_TIMING=y
 # CONFIG_CRITICAL_PREEMPT_TIMING is not set
 # CONFIG_CRITICAL_IRQSOFF_TIMING is not set
 CONFIG_LATENCY_TIMING=y
 CONFIG_LATENCY_TRACE=y
 CONFIG_MCOUNT=y
 # CONFIG_RT_DEADLOCK_DETECT is not set
 # CONFIG_DEBUG_KOBJECT is not set
 CONFIG_DEBUG_BUGVERBOSE=y
 # CONFIG_DEBUG_INFO is not set
 CONFIG_FRAME_POINTER=y
 CONFIG_EARLY_PRINTK=y
 # CONFIG_DEBUG_STACKOVERFLOW is not set

especially PREEMPT_TIMING, IRQSOFF_TIMING and RT_DEADLOCK_DETECT are
quite expensive options.

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Rui Nuno Capela <rncbc@rncbc.org> wrote:

>   xruntrace1.0.tar.gz
>      - scripts used for xrun trace capture automation
>
>   xruntrace1-2.6.10-rc2-mm3-RT-V0.7.31-7.tar.gz
>      - actual xrun traces captured while running jackd on RT-V0.7.31-7

the trace buffer is too small to capture a significant portion of the
xrun - i'd suggest for you to increase it from 4096-1 to 4096*16-1, to
be able to capture a couple of hundreds of millisecs worth of traces.

also, i think it produces more stable results if the tracing is
activated and deactivated from userspace - i.e. the patch below will
measure the latency of poll() executed by the ALSA glue code within
JACK. (i also removed the xrun printf, because it can cause delays.)

this patch can be used the following way: do not activate xrun_debug via
/proc (to not create additional latencies that make xruns worse), but
otherwise set the /proc/sys/kernel/ flags the same way you do already. 
If the patch is applied to jackd then /proc/latency_trace will show the
latest and highest latency that was measured.

note that this captures latencies visible in the ALSA glue, which doesnt
cover the whole jackd critical path - but it should be pretty good as an
initial start. It will definitely show all jackd-unrelated delay
sources.

to cover all latency paths, the last chunk of the patch could perhaps be
modified to do:

+		gettimeofday(1,0);
+		gettimeofday(1,1);

this will also capture latencies within jackd itself. But i think it is
better to separate 'external' from 'internal' latencies, because the two
situations are quite different and it might be hard to identify which
particular latency we are seeing in /proc/latency_trace.

	Ingo

--- ./drivers/alsa/alsa_driver.c.orig	2004-11-26 14:11:26.000000000 +0100
+++ ./drivers/alsa/alsa_driver.c	2004-11-26 14:24:41.000000000 +0100
@@ -1081,9 +1081,11 @@ alsa_driver_xrun_recovery (alsa_driver_t
 		snd_pcm_status_get_trigger_tstamp(status, &tstamp);
 		timersub(&now, &tstamp, &diff);
 		*delayed_usecs = diff.tv_sec * 1000000.0 + diff.tv_usec;
+#if 0
 		fprintf(stderr, "\n\n**** alsa_pcm: xrun of at least %.3f "
 			"msecs\n\n",
 			*delayed_usecs / 1000.0);
+#endif
 	}
 
 	if (alsa_driver_stop (driver) ||
@@ -1187,6 +1189,7 @@ alsa_driver_wait (alsa_driver_t *driver,
 
 		poll_enter = jack_get_microseconds ();
 
+		gettimeofday(1,1);
 		if (poll (driver->pfd, nfds, driver->poll_timeout) < 0) {
 
 			if (errno == EINTR) {
@@ -1206,6 +1209,7 @@ alsa_driver_wait (alsa_driver_t *driver,
 			return 0;
 			
 		}
+		gettimeofday(1,0);
 
 		poll_ret = jack_get_microseconds ();
 

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> --- ./drivers/alsa/alsa_driver.c.orig	2004-11-26 14:11:26.000000000 +0100
> +++ ./drivers/alsa/alsa_driver.c	2004-11-26 14:24:41.000000000 +0100

i think the one below is a better approach - it will only trace events
that the ALSA driver has reported to be an xrun. I.e. the full latency
path from the point where poll() is called, up to the point where jackd
[after the latency has occured] considers it an xrun worth
counting/reporting. The tracing restarts at every poll(), so only the 
latency is captured. If you up your tracebuffer to 40K+ entries then i'd 
suggest to use the following trace settings:

 echo 0 > /proc/asound/card0/pcm0p/xrun_debug

 echo 1 > /proc/sys/kernel/trace_user_triggered
 echo 0 > /proc/sys/kernel/trace_freerunning
 echo 0 > /proc/sys/kernel/preempt_max_latency
 echo 0 > /proc/sys/kernel/preempt_thresh
 echo 0 > /proc/sys/kernel/preempt_wakeup_timing

i.e. dont use trace_freerunning - this will give much easier to parse
traces.

a suggestion wrt. the format of the .trc files: it would be nice if you
could dump the PIDs of all relevant tasks into it too, to make it easier
to identify who causes what latency. Ideally it would be useful to 
have a more symbolic trace - i.e. instead of:

 3570 00000000 254981.991ms (+0.000ms): up (ext3_orphan_del)

it would be:

 jackd-3570 00000000 254981.991ms (+0.000ms): up (ext3_orphan_del)

but this is easier done in the kernel - some of the tasks involved in a
latency might be long gone by the time you detect the xrun.

	Ingo

--- ./drivers/alsa/alsa_driver.c.orig	2004-11-26 14:11:26.000000000 +0100
+++ ./drivers/alsa/alsa_driver.c	2004-11-26 15:31:37.000000000 +0100
@@ -1077,13 +1077,16 @@ alsa_driver_xrun_recovery (alsa_driver_t
 	    && driver->process_count > XRUN_REPORT_DELAY) {
 		struct timeval now, diff, tstamp;
 		driver->xrun_count++;
+		gettimeofday(0,0);
 		gettimeofday(&now, 0);
 		snd_pcm_status_get_trigger_tstamp(status, &tstamp);
 		timersub(&now, &tstamp, &diff);
 		*delayed_usecs = diff.tv_sec * 1000000.0 + diff.tv_usec;
+#if 0
 		fprintf(stderr, "\n\n**** alsa_pcm: xrun of at least %.3f "
 			"msecs\n\n",
 			*delayed_usecs / 1000.0);
+#endif
 	}
 
 	if (alsa_driver_stop (driver) ||
@@ -1185,6 +1188,7 @@ alsa_driver_wait (alsa_driver_t *driver,
 			nfds++;
 		}
 
+		gettimeofday(0,1);
 		poll_enter = jack_get_microseconds ();
 
 		if (poll (driver->pfd, nfds, driver->poll_timeout) < 0) {

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

> > --- ./drivers/alsa/alsa_driver.c.orig	2004-11-26 14:11:26.000000000 +0100
> > +++ ./drivers/alsa/alsa_driver.c	2004-11-26 14:24:41.000000000 +0100

find yet another approach below - it aborts jackd when the first xrun
happens. Since an xrun can trigger other xruns, the most reliable trace
would be the first xrun that triggers.

	Ingo

--- ./drivers/alsa/alsa_driver.c.orig	2004-11-26 14:11:26.000000000 +0100
+++ ./drivers/alsa/alsa_driver.c	2004-11-29 17:39:15.985918576 +0100
@@ -1077,13 +1077,17 @@ alsa_driver_xrun_recovery (alsa_driver_t
 	    && driver->process_count > XRUN_REPORT_DELAY) {
 		struct timeval now, diff, tstamp;
 		driver->xrun_count++;
+		gettimeofday(0,0);
 		gettimeofday(&now, 0);
 		snd_pcm_status_get_trigger_tstamp(status, &tstamp);
 		timersub(&now, &tstamp, &diff);
 		*delayed_usecs = diff.tv_sec * 1000000.0 + diff.tv_usec;
+#if 1
 		fprintf(stderr, "\n\n**** alsa_pcm: xrun of at least %.3f "
 			"msecs\n\n",
 			*delayed_usecs / 1000.0);
+#endif
+		exit(-1);
 	}
 
 	if (alsa_driver_stop (driver) ||
@@ -1185,6 +1189,7 @@ alsa_driver_wait (alsa_driver_t *driver,
 			nfds++;
 		}
 
+		gettimeofday(0,1);
 		poll_enter = jack_get_microseconds ();
 
 		if (poll (driver->pfd, nfds, driver->poll_timeout) < 0) {

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Rui Nuno Capela]

Ingo Molnar wrote:
>
> * Rui Nuno Capela wrote:
>
>>   xruntrace1.0.tar.gz
>>      - scripts used for xrun trace capture automation
>>
>>   xruntrace1-2.6.10-rc2-mm3-RT-V0.7.31-7.tar.gz
>>      - actual xrun traces captured while running jackd on RT-V0.7.31-7
>
> the trace buffer is too small to capture a significant portion of the
> xrun - i'd suggest for you to increase it from 4096-1 to 4096*16-1, to
> be able to capture a couple of hundreds of millisecs worth of traces.
>

and how I do that? Is it some /proc magic or its in the kernel configuration?

please forgive my ignorance:)

bye.
-- 
rncbc aka Rui Nuno Capela
rncbc@rncbc.org

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Rui Nuno Capela <rncbc@rncbc.org> wrote:

> > the trace buffer is too small to capture a significant portion of the
> > xrun - i'd suggest for you to increase it from 4096-1 to 4096*16-1, to
> > be able to capture a couple of hundreds of millisecs worth of traces.
> >
> 
> and how I do that? Is it some /proc magic or its in the kernel configuration?

it's the MAX_TRACE define in kernel/latency.c.

but please try to the -31-10 kernel that i've just uploaded, it has a
number of tracer enhancements:

 - process name tracking. The new format is:

    bash- 3633 80000003 0.264ms (+0.000ms): idle_cpu (wake_idle)
    bash- 3633 80000003 0.264ms (+0.000ms): idle_cpu (wake_idle)
    bash- 3633 80000003 0.264ms (+0.000ms): find_next_bit (wake_idle)

  this makes it easier to identify which process does what. This feature 
  has no significant overhead in the tracer itself, all the hard work is
  done when /proc/latency_trace is read by the user.

 - /proc/sys/kernel/mcount_enabled flag: if disabled then 
   /proc/latency_trace will only contain 'custom' events, but no 
   per-function entries. This can be useful to trace really long 
   latencies, to get a rough idea of what is going on.

 - /proc/latency_trace atomicity. It was fundamentally non-atomic, due 
   to it being a 4K-granular file interface. Now the kernel has a second
   layer of saved-trace logic, which makes sure that the only time the
   trace is switched is when the header of the trace is read. I.e. when
   cp-ing or cat-ing /proc/latency_trace, no new trace info will be
   used. This change could solve some of the 'truncated traces'
   weirdnesses reported.

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> but please try to the -31-10 kernel that i've just uploaded, it has a
> number of tracer enhancements:

make that -31-13 (or later). Earlier kernels had a bug in where the
process name tracking only worked for the first latency trace saved,
subsequent traces showed 'unknown' for the process name. In -13 i've
also added a printk that shows the latest user latency in a one-line
printk - just like the built-in latency tracing modes do:

 (gettimeofday/3671/CPU#0): new 3068 us user-latency.
 (gettimeofday/3784/CPU#0): new 1008627 us user-latency.

(this should also make it easier for helper scripts to save the traces,
whenever they happen.)

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Rui Nuno Capela]

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

Ingo Molnar wrote:
>
> * Ingo Molnar <mingo@elte.hu> wrote:
>
>> but please try to the -31-10 kernel that i've just uploaded, it has a
>> number of tracer enhancements:
>
> make that -31-13 (or later). Earlier kernels had a bug in where the
> process name tracking only worked for the first latency trace saved,
> subsequent traces showed 'unknown' for the process name. In -13 i've
> also added a printk that shows the latest user latency in a one-line
> printk - just like the built-in latency tracing modes do:
>
>  (gettimeofday/3671/CPU#0): new 3068 us user-latency.
>  (gettimeofday/3784/CPU#0): new 1008627 us user-latency.
>
> (this should also make it easier for helper scripts to save the traces,
> whenever they happen.)
>

OK.

I did my homework and managed to grab some latency traces for you to take
a look and see if it's alright. Please.

On attach you may find the files:

    xruntrace1.1.tar.gz
        - scripts used to arm and capture the latency traces;

    jack-0.99.14.0xruntrace-alsa.patch.gz
        - the actual patch applied to jack for trace auto-triggering;

    config-2.6.10-rc2-mm3-RT-V0.7.31-13.gz
        - the running kernel configuration, as taken from /proc/config.gz

    xruntrace1-2.6.10-rc2-mm3-RT-V0.7.31-13-*.trc.gz
        - the captured traces, as dumped with xruntrace1_watch.sh script.

    jack_test3.2.tar.gz
        - updated my jack_test3 benchmarking suite.


The traces were captured, while running a usual KDE desktop session (from
qjackctl) on my P4@2.53Ghz laptop (Mandrake 10.1):

    jackd -R -P60 -dalsa -dhw:0 -r44100 -p64 -n2 -S -P

Each trace shows only the first XRUN occurrence on a distinct jackd
session. Every other trace were triggered and captured after restarting
jackd.

Must say that XRUNs are rare but do occurr. Using the same jackd command
line, my jack_test3 suite is showing these figures by now:

    *********** CONSOLIDATED RESULTS ************
    Total seconds ran . . . . . . :  7200
    Number of clients . . . . . . :    16
    Ports per client  . . . . . . :     4
    *********************************************
    Summary Result Count  . . . . :     2 /     2
    *********************************************
    Timeout Rate  . . . . . . . . :(    0.0)/hour
    XRUN Rate . . . . . . . . . . :    13.8 /hour
    Delay Rate (>spare time)  . . :    13.8 /hour
    Delay Rate (>1000 usecs)  . . :     7.0 /hour
    Delay Maximum . . . . . . . . :  1022   usecs
    Cycle Maximum . . . . . . . . :  1048   usecs
    Average DSP Load. . . . . . . :    62.2 %
    Average CPU System Load . . . :    20.6 %
    Average CPU User Load . . . . :    48.5 %
    Average CPU Nice Load . . . . :     0.0 %
    Average CPU I/O Wait Load . . :     0.0 %
    Average CPU IRQ Load  . . . . :     0.0 %
    Average CPU Soft-IRQ Load . . :     0.0 %
    Average Interrupt Rate  . . . :  1689.2 /sec
    Average Context-Switch Rate . : 19778.2 /sec
    *********************************************

The IRQ process/threading priority status has been fixed as shown below:

  PID CLS RTPRIO  NI PRI %CPU STAT COMMAND
    2 FF      90   - 130  0.0 S    IRQ 0
  728 FF      80   - 120  0.0 S<   IRQ 8
 2943 FF      70   - 110  0.0 S<   IRQ 5
 1500 FF      60   - 100  0.0 S<   IRQ 10
  841 FF      50   -  90  0.0 S<   IRQ 1
  736 FF      49   -  89  0.0 S<   IRQ 12
   20 FF      48   -  88  0.0 S<   IRQ 9
  814 FF      45   -  85  0.0 S<   IRQ 6
  821 FF      44   -  84  0.0 S<   IRQ 14
  823 FF      43   -  83  0.0 S<   IRQ 15
 2227 FF      40   -  80  0.0 S<   IRQ 11

# cat /proc/interrupts

           CPU0
  0:    6435186          XT-PIC  timer  0/35186
  1:       1164          XT-PIC  i8042  1/1164
  2:          0          XT-PIC  cascade  0/0
  5:         73          XT-PIC  ALI 5451  0/72
  8:          1          XT-PIC  rtc  0/1
  9:      20602          XT-PIC  acpi  0/20602
 10:          0          XT-PIC  ohci_hcd, ohci_hcd  0/0
 11:          5          XT-PIC  yenta  5/5
 12:      64317          XT-PIC  i8042  0/64317
 14:      11772          XT-PIC  ide0  0/11772
 15:         19          XT-PIC  ide1  0/19
NMI:          0
LOC:          0
ERR:          0
MIS:          0


Cheers.
-- 
rncbc aka Rui Nuno Capela
rncbc@rncbc.org

[-- Attachment #2: xruntrace1.1.tar.gz --]
[-- Type: application/x-gzip-compressed, Size: 1688 bytes --]

[-- Attachment #3: jack-0.99.14.0xruntrace-alsa.patch.gz --]
[-- Type: application/x-gzip-compressed, Size: 548 bytes --]

[-- Attachment #4: config-2.6.10-rc2-mm3-RT-V0.7.31-13.gz --]
[-- Type: application/x-gzip-compressed, Size: 8248 bytes --]

[-- Attachment #5: xruntrace1-2.6.10-rc2-mm3-RT-V0.7.31-13-20041129154425.trc.gz --]
[-- Type: application/x-gzip-compressed, Size: 1695 bytes --]

[-- Attachment #6: xruntrace1-2.6.10-rc2-mm3-RT-V0.7.31-13-20041129184639.trc.gz --]
[-- Type: application/x-gzip-compressed, Size: 1659 bytes --]

[-- Attachment #7: xruntrace1-2.6.10-rc2-mm3-RT-V0.7.31-13-20041129195721.trc.gz --]
[-- Type: application/x-gzip-compressed, Size: 1667 bytes --]

[-- Attachment #8: jack_test3.2.tar.gz --]
[-- Type: application/x-gzip-compressed, Size: 10159 bytes --]

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Rui Nuno Capela <rncbc@rncbc.org> wrote:

>     xruntrace1-2.6.10-rc2-mm3-RT-V0.7.31-13-*.trc.gz
>         - the captured traces, as dumped with xruntrace1_watch.sh script.

> Each trace shows only the first XRUN occurrence on a distinct jackd
> session. Every other trace were triggered and captured after
> restarting jackd.

interesting - the trace shows only a latency of 20-40 usecs. Perhaps the
tracing should be done over two periods?

Could you try to hack alsa_driver.c to do the gettimeofday(1,1) call for
only every second case. Something like this ought to be enough:

	{
		static count = 0;

		if (!(count++ & 1))
			gettimeofday(0,1);
	}

(only one thread accesses this particular variable so there are no
threading issues.)

with this variant there's a 50% chance that we get the trace of the last
2 poll() instances. (and there's a 50% chance that we get only 1 period
covered.)

in any case, the scripts & approach seems to be almost there, i hope we
only need the above change to see the true source of the xruns.

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Rui Nuno Capela]

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

> Ingo Molnar
>
> * Rui Nuno Capela wrote:
>
>>     xruntrace1-2.6.10-rc2-mm3-RT-V0.7.31-13-*.trc.gz
>>         - the captured traces, as dumped with xruntrace1_watch.sh
>>           script.
>
>> Each trace shows only the first XRUN occurrence on a distinct jackd
>> session. Every other trace were triggered and captured after
>> restarting jackd.
>
> interesting - the trace shows only a latency of 20-40 usecs. Perhaps the
> tracing should be done over two periods?
>
> Could you try to hack alsa_driver.c to do the gettimeofday(1,1) call for
> only every second case. Something like this ought to be enough:
>
> 	{
> 		static count = 0;
>
> 		if (!(count++ & 1))
> 			gettimeofday(0,1);
> 	}
>
> (only one thread accesses this particular variable so there are no
> threading issues.)
>
> with this variant there's a 50% chance that we get the trace of the last
> 2 poll() instances. (and there's a 50% chance that we get only 1 period
> covered.)
>
> in any case, the scripts & approach seems to be almost there, i hope we
> only need the above change to see the true source of the xruns.
>

Done that.

New XRUN traces are attached, while running RT-V0.7.31-15 now. However, I
don't seem to get any notorious difference on the results, since previous
ones. All latencies traced ca. 26-27 usecs.

Bye.
-- 
rncbc aka Rui Nuno Capela
rncbc@rncbc.org

[-- Attachment #2: config-2.6.10-rc2-mm3-RT-V0.7.31-15.gz --]
[-- Type: application/x-gzip-compressed, Size: 8232 bytes --]

[-- Attachment #3: xruntrace1-2.6.10-rc2-mm3-RT-V0.7.31-15-20041130140917.trc.gz --]
[-- Type: application/x-gzip-compressed, Size: 1670 bytes --]

[-- Attachment #4: xruntrace1-2.6.10-rc2-mm3-RT-V0.7.31-15-20041130141834.trc.gz --]
[-- Type: application/x-gzip-compressed, Size: 1648 bytes --]

[-- Attachment #5: xruntrace1-2.6.10-rc2-mm3-RT-V0.7.31-15-20041130142405.trc.gz --]
[-- Type: application/x-gzip-compressed, Size: 1654 bytes --]

[-- Attachment #6: jackit-0.99.15.1xruntrace-alsa.patch.gz --]
[-- Type: application/x-gzip-compressed, Size: 626 bytes --]

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Rui Nuno Capela <rncbc@rncbc.org> wrote:

> Done that.
> 
> New XRUN traces are attached, while running RT-V0.7.31-15 now.
> However, I don't seem to get any notorious difference on the results,
> since previous ones. All latencies traced ca. 26-27 usecs.

hm, weird. Next idea: could you activate trace_freerunning and change
the alsa_driver.c count hack to do:

	if (!count) {
		gettimeofday(0,1);
		count = 1;
	}

this means that tracing will only be activated once, and the tracing
goes on non-stop from that point on, up until the first xrun, at which
point the full tracebuffer is saved. Ok?

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Rui Nuno Capela <rncbc@rncbc.org> wrote:

> > 		if (!(count++ & 1))
> > 			gettimeofday(0,1);
> > 	}

> Done that.
> 
> New XRUN traces are attached, while running RT-V0.7.31-15 now.
> However, I don't seem to get any notorious difference on the results,
> since previous ones. All latencies traced ca. 26-27 usecs.

ah, found the reason why the trace length didnt improve:

+               {       // Trigger off trace every other poll...
+                       static unsigned int xruntrace_count = 0;
+                       if ((xruntrace_count++ % 1) == 0)
+                               gettimeofday(0,1);
+               }

this should either be '& 1' as i originally suggested, or '% 2'. The way 
it is right now it will stop the trace every time - i.e. what we had 
before.

so please disregard my freerunning suggestionsand try the two-periods
solution first.

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

> New XRUN traces are attached, while running RT-V0.7.31-15 now.
> However, I don't seem to get any notorious difference on the results,
> since previous ones. All latencies traced ca. 26-27 usecs.

another thing: could you try the latest jackd CVS tree too? I found
spurious xruns in 99-0 (the last official release), while with 99-11 i
dont see any xruns on my box, up until i completely saturate CPU time.

I.e. both latest -RT kernels are needed for this (earlier RT kernels,
prior the PI fixes still generated lots of xruns even with latest jack
CVS), and latest jack CVS is needed.

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Rui Nuno Capela]

Ingo Molnar wrote:
>
>> New XRUN traces are attached, while running RT-V0.7.31-15 now.
>> However, I don't seem to get any notorious difference on the results,
>> since previous ones. All latencies traced ca. 26-27 usecs.
>
> another thing: could you try the latest jackd CVS tree too? I found
> spurious xruns in 99-0 (the last official release), while with 99-11 i
> dont see any xruns on my box, up until i completely saturate CPU time.
>
> I.e. both latest -RT kernels are needed for this (earlier RT kernels,
> prior the PI fixes still generated lots of xruns even with latest jack
> CVS), and latest jack CVS is needed.
>

I am using the latest-as-it-could-be jack CVS snapshot, as handed by Jack
O'Quin, since sourceforge's CVS service has been broken for a while.

The latest of my last report is 0.99.15.
-- 
rncbc aka Rui Nuno Capela
rncbc@rncbc.org

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Rui Nuno Capela]

Ingo Molnar wrote:
>
> * Rui Nuno Capela <rncbc@rncbc.org> wrote:
>
>> > 		if (!(count++ & 1))
>> > 			gettimeofday(0,1);
>> > 	}
>
>> Done that.
>>
>> New XRUN traces are attached, while running RT-V0.7.31-15 now.
>> However, I don't seem to get any notorious difference on the results,
>> since previous ones. All latencies traced ca. 26-27 usecs.
>
> ah, found the reason why the trace length didnt improve:
>
> +               {       // Trigger off trace every other poll...
> +                       static unsigned int xruntrace_count = 0;
> +                       if ((xruntrace_count++ % 1) == 0)
> +                               gettimeofday(0,1);
> +               }
>
> this should either be '& 1' as i originally suggested, or '% 2'. The way
> it is right now it will stop the trace every time - i.e. what we had
> before.
>
> so please disregard my freerunning suggestionsand try the two-periods
> solution first.
>

Very good eyes! It was all my mistake. Sorry, sorry. It was a sure typo
after all, the '%' key is right next to '&', at least on my on my keyboard
:)

Will correct it and bbl...
-- 
rncbc aka Rui Nuno Capela
rncbc@rncbc.org

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

ok, got the latest traces from Rui offlist.

here's a summary of an xrun that went like this:

   jackd-4711  00000000 0.002ms (+0.000ms): do_poll (sys_poll)
   ...
   jackd-4711  80000002 0.012ms (+0.000ms): dequeue_task (deactivate_task)
   ...
   IRQ 5-3052  ........ 1.946ms (+0.000ms): ->    jackd-4711
                     [ 00000027 00000001 ]: try_to_wake_up
   ...
qjackctl-4719  ........ 2.362ms (+0.000ms): common_interrupt:
                     [ b75e9090 00000005 00000000 ]
   ...
   IRQ 5-3052  00000000 2.473ms (+0.000ms): xrun (snd_pcm_period_elapsed)
   ...

this shows an interesting phenomenon: for whatever reason IRQ5's thread
didnt run until timestamp 1.946ms. There is lots of idle time between
timestamps 0.012ms and 1.946ms, so this must be some weird condition. 

Rui, could you activate trace_freerunning and send me a couple of 'big'
traces that result out of it? Apparently there is some other, earlier
activity that caused this to happen to IRQ5. Nothing seems to have woken
up IRQ5 when it ran, which is weird by itself too.

if IRQ thread 5 got delayed somehow that might explain the xrun: the
hardware interrupt had no chance to run. But how IRQ5 could stay on the
runqueue while the idle thread managed to run is strange.

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> this shows an interesting phenomenon: for whatever reason IRQ5's
> thread didnt run until timestamp 1.946ms. There is lots of idle time
> between timestamps 0.012ms and 1.946ms, so this must be some weird
> condition. 

ok, this could be ACPI CPU-sleep related. Could you disable all ACPI
options in your .config (as a workaround), and re-check whether the
xruns still occur?

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Remi Colinet]

Hi Ingo,

I'm getting this error with V0.7.31-13

CC kernel/wait.o
CC kernel/kfifo.o
CC kernel/sys_ni.o
CC kernel/rt.o
CC kernel/latency.o
kernel/latency.c: In function `check_critical_timing':
kernel/latency.c:730: too few arguments to function `___trace'
kernel/latency.c:730: warning: too few arguments passed to inline 
function, suppressing inlining
kernel/latency.c: In function `__start_critical_timing':
kernel/latency.c:810: incompatible type for argument 1 of `____trace'
kernel/latency.c:810: warning: passing arg 2 of `____trace' makes 
pointer from integer without a cast
kernel/latency.c:810: too few arguments to function `____trace'
kernel/latency.c: In function `trace_irqs_off':
kernel/latency.c:810: warning: too few arguments passed to inline 
function, suppressing inlining
kernel/latency.c: In function `add_preempt_count':
kernel/latency.c:810: warning: too few arguments passed to inline 
function, suppressing inlining
kernel/latency.c: At top level:
kernel/latency.c:810: warning: too few arguments passed to inline 
function, suppressing inlining
make[1]: *** [kernel/latency.o] Error 1
make: *** [kernel] Error 2
[root@tigre01 im]#

Regards
Remi

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Remi Colinet <remi.colinet@free.fr> wrote:

> Hi Ingo,
> 
> I'm getting this error with V0.7.31-13

> CC kernel/latency.o
> kernel/latency.c: In function `check_critical_timing':
> kernel/latency.c:730: too few arguments to function `___trace'
> kernel/latency.c:730: warning: too few arguments passed to inline 

fixed this in -V0.7.31-14.

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Eran Mann]

Ingo Molnar wrote:
> 
> 
> fixed this in -V0.7.31-14.
> 
> 	Ingo
>  This mail arrived via mail.mrv.com
> 
> 

Compiling -V0.7.31-15 without CONFIG_LATENCY_TRACE results in:
...
   CC      kernel/latency.o
kernel/latency.c: In function `check_critical_timing':
kernel/latency.c:765: warning: implicit declaration of function `__trace'
...
   LD      .tmp_vmlinux1
kernel/built-in.o(.text+0x1e407): In function `check_critical_timing':
: undefined reference to `__trace'
make: *** [.tmp_vmlinux1] Error 1

Seems to be fixed by the patch below:

--- kernel/latency.c.orig       2004-12-01 10:21:45.000000000 +0200
+++ kernel/latency.c    2004-12-01 10:11:37.000000000 +0200
@@ -762,7 +762,9 @@
         tr->critical_sequence = max_sequence;
         tr->preempt_timestamp = cycles();
         tr->early_warning = 0;
+#ifdef CONFIG_LATENCY_TRACE
         __trace(CALLER_ADDR0, parent_eip);
+#endif
  }

  void notrace touch_critical_timing(void)
-- 
Eran Mann

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Ingo Molnar]

* Eran Mann <emann@mrv.com> wrote:

> Seems to be fixed by the patch below:
> 
> --- kernel/latency.c.orig       2004-12-01 10:21:45.000000000 +0200
> +++ kernel/latency.c    2004-12-01 10:11:37.000000000 +0200
> @@ -762,7 +762,9 @@
>         tr->critical_sequence = max_sequence;
>         tr->preempt_timestamp = cycles();
>         tr->early_warning = 0;
> +#ifdef CONFIG_LATENCY_TRACE
>         __trace(CALLER_ADDR0, parent_eip);
> +#endif

thanks, applied it and uploaded -V0.7.31-16.

	Ingo

Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-7

[Adam Heath]

On Wed, 1 Dec 2004, Ingo Molnar wrote:

>
> * Eran Mann <emann@mrv.com> wrote:
>
> > Seems to be fixed by the patch below:
> >
> > --- kernel/latency.c.orig       2004-12-01 10:21:45.000000000 +0200
> > +++ kernel/latency.c    2004-12-01 10:11:37.000000000 +0200
> > @@ -762,7 +762,9 @@
> >         tr->critical_sequence = max_sequence;
> >         tr->preempt_timestamp = cycles();
> >         tr->early_warning = 0;
> > +#ifdef CONFIG_LATENCY_TRACE
> >         __trace(CALLER_ADDR0, parent_eip);
> > +#endif
>
> thanks, applied it and uploaded -V0.7.31-16.

Wouldn't it be better to change the definition of __trace()?  Always have it
defined, but make it empty if CONFIG_LATENCY_TRACE isn't set?

It'd keep the code from being littered with ifdef.