Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Mark_H_Johnson]

A comparison of PREEMPT_RT (no tracing) to PREEMPT_DESKTOP
(no tracing) to help answer previous requests.

Comparison of .32-20RT and .32-20PK results
20RT has PREEMPT_RT (all tracing disabled)
20PK has PREEMPT_DESKTOP and no threaded IRQ's (all tracing disabled)
2.4 has lowlat + preempt patches applied

      within 100 usec
       CPU loop (%)   Elapsed Time (sec)    2.4
Test   RT     PK        RT      PK   |   CPU  Elapsed
X     99.87  99.75      65 *    59 * |  97.20   70
top   99.35  99.97      31 *    30 * |  97.48   29
neto  96.94  98.65     113 *   135 * |  96.23   36
neti  97.05  98.59     119 *   140 * |  95.86   41
diskw 94.36  91.69      30 *    70 * |  77.64   29
diskc 93.85  98.88      98 *   151 * |  84.12   77
diskr 99.39  99.92     133 *   210 * |  90.66   86
total                  589     795   |         368
 [higher is better]  [lower is better]
* wide variation in audio duration
+ long stretch of audio duration "too fast"

With the two versions of -20, they are quite similar in the
percentage of CPU loop duration within 100 usec of nominal.

Looking at ping response time:
  RT 0.134 / 0.208 / 1.502 / 0.075 msec
  PK 0.089 / 0.159 / 0.467 / 0.047 msec
for min / average / max / mdev values. You can see that
-20PK does much better than -20RT in this measure.

The maximum duration of the CPU loop (as measured by the
application) is in the range of 1.42 msec to 2.57 compared
to the nominal 1.16 msec duration for -20RT. The equivalent
numbers for -20PK are 1.28 to 1.93 msec. Its a little odd
that the big outlier for -20PK was during the X 11 stress
test. Its chart was one of the smoothest (less variation)
than the others.

I repeated the test without cpu_burn (non RT, nice) for the
20PK kernel as well.  For -20PK, all the elapsed times were
reduced [as I expected for both RT and PK] and with exception
of the network tests, were roughly the same as the 2.4 results.

-20RT
  with cpu_burn      65  31 113 119  30  98 133
  without cpu_burn   63  30 121 150  32  87  97
-20PK
  with cpu_burn      59  30 135 140  70 151 210
  without cpu_burn   62  30  94  60  27  89  93

I reran the 2.4 tests and the network tests ran in 39 and 37
seconds respectively. I guess this shows we have something odd
going on in the network stack under 2.6.

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

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Ingo Molnar]

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

> The maximum duration of the CPU loop (as measured by the application)
> is in the range of 1.42 msec to 2.57 compared to the nominal 1.16 msec
> duration for -20RT.  The equivalent numbers for -20PK are 1.28 to 1.93
> msec. [...]

so -20RT has resolved all the CPU-loop-max-delay issues of the -RT
kernel regarding the RT-priority CPU loop and in essence adds only a
small amount of delay (100 usecs?) to the nominal (==minimum possible)
delay?

i suspect the 100 usecs comparison is an effect of the cutoff value
being a single value. Also, 100 usecs is so close to the DMA related
delay which makes it hard to compare it - other than stating that -RT
has higher CPU overhead.

are the ping times still considered anomalous? Could be a side-effect of
the different flow of control between hardirq/softirq contexts. (There
have been a (low but nonzero) number of assumptions about the flow in
pieces of softirq code, and there could be more.)

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Ingo Molnar]

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

> Isn't this tightly related to mkinitrd sometimes hanging while on
> mount -o loop, that I've been reporting a couple of times before? It
> used to hang on any other time I do a new kernel install, but latetly
> it seems to be OK (RT-V0.9.32-19 and -20).

yeah, i've added Thomas Gleixner's earlier semaphore->completion
conversion to the loop device, to -19 or -18.

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Rui Nuno Capela]

K.R. Foley wrote:
> Fernando Lopez-Lezcano wrote:
>> On Sun, 2004-12-12 at 22:47, Ingo Molnar wrote:
>>
>>>* Fernando Lopez-Lezcano <nando@ccrma.Stanford.EDU> wrote:
>>>
>>>
>>>>Something that just happened to me: running 0.7.32-14
>>>>(PREEMPT_DESKTOP) and trying to install 0.7.32-19 from a custom built
>>>>rpm package completely hangs the machine (p4 laptop - I tried twice).
>>>>No clues left behind. If I boot into 0.7.32-9 I can install 0.7.32-19
>>>>with no problems.
>>>
>>>does 0.7.32-19 work better if you reverse (patch -R) the loop.h and
>>>loop.c bits (see below)?
>>
>>
>> Running 0.7.32-19 (no changes) I managed to install 0.7.32-20 with no
>> problems... probably a problem in -14 that was somehow fixed in later
>> releases.
>>
>> -- Fernando
>
> Possibly. I have had the occasional problem with running make install
> locking one of my systems. Rebooting and running make install again
> works fine in my case. It is by no means a regular occurrence, even
> installing 2 or 3 new kernels daily on 3 different machines.
>

Isn't this tightly related to mkinitrd sometimes hanging while on mount -o
loop, that I've been reporting a couple of times before? It used to hang
on any other time I do a new kernel install, but latetly it seems to be OK
(RT-V0.9.32-19 and -20).
-- 
rncbc aka Rui Nuno Capela
rncbc@rncbc.org

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[K.R. Foley]

Fernando Lopez-Lezcano wrote:
> On Sun, 2004-12-12 at 22:47, Ingo Molnar wrote:
> 
>>* Fernando Lopez-Lezcano <nando@ccrma.Stanford.EDU> wrote:
>>
>>
>>>Something that just happened to me: running 0.7.32-14
>>>(PREEMPT_DESKTOP) and trying to install 0.7.32-19 from a custom built
>>>rpm package completely hangs the machine (p4 laptop - I tried twice).
>>>No clues left behind. If I boot into 0.7.32-9 I can install 0.7.32-19
>>>with no problems. 
>>
>>does 0.7.32-19 work better if you reverse (patch -R) the loop.h and
>>loop.c bits (see below)?
> 
> 
> Running 0.7.32-19 (no changes) I managed to install 0.7.32-20 with no
> problems... probably a problem in -14 that was somehow fixed in later
> releases. 
> 
> -- Fernando

Possibly. I have had the occasional problem with running make install 
locking one of my systems. Rebooting and running make install again 
works fine in my case. It is by no means a regular occurrence, even 
installing 2 or 3 new kernels daily on 3 different machines.

kr

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Fernando Lopez-Lezcano]

On Sun, 2004-12-12 at 22:47, Ingo Molnar wrote:
> * Fernando Lopez-Lezcano <nando@ccrma.Stanford.EDU> wrote:
> 
> > Something that just happened to me: running 0.7.32-14
> > (PREEMPT_DESKTOP) and trying to install 0.7.32-19 from a custom built
> > rpm package completely hangs the machine (p4 laptop - I tried twice).
> > No clues left behind. If I boot into 0.7.32-9 I can install 0.7.32-19
> > with no problems. 
> 
> does 0.7.32-19 work better if you reverse (patch -R) the loop.h and
> loop.c bits (see below)?

Running 0.7.32-19 (no changes) I managed to install 0.7.32-20 with no
problems... probably a problem in -14 that was somehow fixed in later
releases. 

-- Fernando

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Mark_H_Johnson]

> * Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:
>
> > The maximum duration of the CPU loop (as measured by the application)
> > is in the range of 1.42 msec to 2.57 compared to the nominal 1.16 msec
> > duration for -20RT.  The equivalent numbers for -20PK are 1.28 to 1.93
> > msec. [...]
>
> so -20RT has resolved all the CPU-loop-max-delay issues of the -RT
> kernel regarding the RT-priority CPU loop and in essence adds only a
> small amount of delay (100 usecs?) to the nominal (==minimum possible)
> delay?
I believe so, or in other words a minor penalty to average latency impact
to get a reduction in maximum latency [though I am not sure I actually
measured such a reduction].

> i suspect the 100 usecs comparison is an effect of the cutoff value
> being a single value. Also, 100 usecs is so close to the DMA related
> delay which makes it hard to compare it - other than stating that -RT
> has higher CPU overhead.
I think we agree on this assessment. I don't think the threading overhead
is 100 usec but more likely 50 usec [at least on my hardware - see below].
That the extra 50 usec puts us over the 100 usec measure is unfortunate.

> are the ping times still considered anomalous? Could be a side-effect of
> the different flow of control between hardirq/softirq contexts. (There
> have been a (low but nonzero) number of assumptions about the flow in
> pieces of softirq code, and there could be more.)
Please note that to get the ping times I stated, I set the priority of
ksoftirqd/0 and /1 to 99 (along with the IRQ threads). Others won't be
so generous and get different results.

I believe the longer duration with -20RT is due to the threading overhead.
Look at the numbers for -20PK and -20RT, the minimums are
  -20PK 0.089 msec (or 089 usec)
  -20RT 0.134 msec (or 134 usec)
or a difference of about 50 usec. If the sequence of steps is something
like
  Network Interrupt -T-> Network IRQ -T-> ksoftirqd/0 -> ping reply
on -RT and
  Network Interrupt -> Network IRQ -> soft IRQ -> ping reply
on -PK, the difference measured is likely reasonable.

[where -T-> represents a new thread activation, and -> represents something
like a function call]

Again, the benefit of PREEMPT_RT (over PREEMPT_DESKTOP) should be reduced
maximum latencies with a modest (or very little) impact to overall
performance / throughput. We are certainly getting a lot closer on
reaching that goal.

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

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Ingo Molnar]

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

> A comparison of PREEMPT_RT (no tracing) to PREEMPT_DESKTOP
> (with tracing) to help answer previous requests.
> 
> Comparison of .32-20RT and .32-18PK results
> 20RT has PREEMPT_RT (all tracing disabled)
> 18PK has PREEMPT_DESKTOP and no threaded IRQ's (tracing enabled)
> 2.4 has lowlat + preempt patches applied
> 
>       within 100 usec
>        CPU loop (%)   Elapsed Time (sec)    2.4
> Test   RT     PK        RT      PK   |   CPU  Elapsed
> X     99.87 100.00&     65 *    64+  |  97.20   70
> top   99.35 100.00&     31 *    31+  |  97.48   29
> neto  96.94 100.00&    113 *   184+  |  96.23   36
> neti  97.05 100.00&    119 *   170+  |  95.86   41

interesting - the PK kernel with tracing enabled performs better than
the PK kernel with tracing disabled? Sounds counter-intuitive.

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Mark_H_Johnson]

A comparison of PREEMPT_RT (no tracing) to PREEMPT_DESKTOP
(with tracing) to help answer previous requests.

Comparison of .32-20RT and .32-18PK results
20RT has PREEMPT_RT (all tracing disabled)
18PK has PREEMPT_DESKTOP and no threaded IRQ's (tracing enabled)
2.4 has lowlat + preempt patches applied

      within 100 usec
       CPU loop (%)   Elapsed Time (sec)    2.4
Test   RT     PK        RT      PK   |   CPU  Elapsed
X     99.87 100.00&     65 *    64+  |  97.20   70
top   99.35 100.00&     31 *    31+  |  97.48   29
neto  96.94 100.00&    113 *   184+  |  96.23   36
neti  97.05 100.00&    119 *   170+  |  95.86   41
diskw 94.36  99.99      30 *    61+  |  77.64   29
diskc 93.85  99.34      98 *   310+  |  84.12   77
diskr 99.39  99.96     133 *   310+  |  90.66   86
total                  589    1130   |         368
 [higher is better]  [lower is better]
* wide variation in audio duration
+ long stretch of audio duration "too fast"
& 100% to digits shown, had a FEW samples > 100 usec.

The results for -20RT (without tracing) are much better than
-18RT (with tracing) but still not quite as good as -18PK
with respect to the 100 usec delays.

The overhead of threading the IRQ's (and rescheduling the
RT application making the measurements) is likely cause of
the difference in 100 usec latency measurements.

I believe the threading overhead is confirmed by the slightly
slower ping response measurements:
  RT 0.134 / 0.208 / 1.502 / 0.075 msec
  PK 0.102 / 0.164 / 0.708 / 0.044 msec
for min / average / max / mdev values. These are much
better than with -18RT (with tracing) as well. Apparently the
tracing overhead is pretty high in the task switching area.

The maximum duration of the CPU loop (as measured by the
application) is in the range of 1.42 msec to 2.57 compared
to the nominal 1.16 msec duration for -20RT.

The non RT starvation problem appears to be mitigated quite
a bit by removing the tracing. I did a follow up test without
cpu_burn (non RT, nice) and the elapsed times varied in an
odd pattern:

  with cpu_burn      65  31 113 119  30  98 133
  without cpu_burn   63  30 121 150  32  87  97

The disk numbers are getting much closer to the 2.4 values
so removal of cpu_burn definitely helps prevent starvation.
The larger network numbers are something I should probably
confirm on my 2.4 test system to see if something changed
on the network to skew the results.

I will be building a -20PK without tracing for a more complete
comparison.

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

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Ingo Molnar]

* Fernando Lopez-Lezcano <nando@ccrma.Stanford.EDU> wrote:

> Something that just happened to me: running 0.7.32-14
> (PREEMPT_DESKTOP) and trying to install 0.7.32-19 from a custom built
> rpm package completely hangs the machine (p4 laptop - I tried twice).
> No clues left behind. If I boot into 0.7.32-9 I can install 0.7.32-19
> with no problems. 

does 0.7.32-19 work better if you reverse (patch -R) the loop.h and
loop.c bits (see below)?

	Ingo

--- linux/drivers/block/loop.c.orig
+++ linux/drivers/block/loop.c
@@ -378,7 +378,7 @@ static void loop_add_bio(struct loop_dev
 		lo->lo_bio = lo->lo_biotail = bio;
 	spin_unlock_irqrestore(&lo->lo_lock, flags);
 
-	up(&lo->lo_bh_mutex);
+	complete(&lo->lo_bh_done);
 }
 
 /*
@@ -427,7 +427,7 @@ static int loop_make_request(request_que
 	return 0;
 err:
 	if (atomic_dec_and_test(&lo->lo_pending))
-		up(&lo->lo_bh_mutex);
+		complete(&lo->lo_bh_done);
 out:
 	bio_io_error(old_bio, old_bio->bi_size);
 	return 0;
@@ -495,12 +495,12 @@ static int loop_thread(void *data)
 	/*
 	 * up sem, we are running
 	 */
-	up(&lo->lo_sem);
+	complete(&lo->lo_done);
 
 	for (;;) {
-		down_interruptible(&lo->lo_bh_mutex);
+		wait_for_completion_interruptible(&lo->lo_bh_done);
 		/*
-		 * could be upped because of tear-down, not because of
+		 * could be completed because of tear-down, not because of
 		 * pending work
 		 */
 		if (!atomic_read(&lo->lo_pending))
@@ -521,7 +521,7 @@ static int loop_thread(void *data)
 			break;
 	}
 
-	up(&lo->lo_sem);
+	complete(&lo->lo_done);
 	return 0;
 }
 
@@ -708,7 +708,7 @@ static int loop_set_fd(struct loop_devic
 	set_blocksize(bdev, lo_blocksize);
 
 	kernel_thread(loop_thread, lo, CLONE_KERNEL);
-	down(&lo->lo_sem);
+	wait_for_completion(&lo->lo_done);
 	return 0;
 
  out_putf:
@@ -773,10 +773,10 @@ static int loop_clr_fd(struct loop_devic
 	spin_lock_irq(&lo->lo_lock);
 	lo->lo_state = Lo_rundown;
 	if (atomic_dec_and_test(&lo->lo_pending))
-		up(&lo->lo_bh_mutex);
+		complete(&lo->lo_bh_done);
 	spin_unlock_irq(&lo->lo_lock);
 
-	down(&lo->lo_sem);
+	wait_for_completion(&lo->lo_done);
 
 	lo->lo_backing_file = NULL;
 
@@ -1153,8 +1153,8 @@ int __init loop_init(void)
 		if (!lo->lo_queue)
 			goto out_mem4;
 		init_MUTEX(&lo->lo_ctl_mutex);
-		init_MUTEX_LOCKED(&lo->lo_sem);
-		init_MUTEX_LOCKED(&lo->lo_bh_mutex);
+		init_completion(&lo->lo_done);
+		init_completion(&lo->lo_bh_done);
 		lo->lo_number = i;
 		spin_lock_init(&lo->lo_lock);
 		disk->major = LOOP_MAJOR;
--- linux/include/linux/loop.h.orig
+++ linux/include/linux/loop.h
@@ -58,9 +58,9 @@ struct loop_device {
 	struct bio 		*lo_bio;
 	struct bio		*lo_biotail;
 	int			lo_state;
-	struct semaphore	lo_sem;
+	struct completion	lo_done;
+	struct completion	lo_bh_done;
 	struct semaphore	lo_ctl_mutex;
-	struct semaphore	lo_bh_mutex;
 	atomic_t		lo_pending;
 
 	request_queue_t		*lo_queue;

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Fernando Lopez-Lezcano]

logOn Fri, 2004-12-10 at 09:49, Mark_H_Johnson@raytheon.com wrote:
> >The -32-15 kernel can be downloaded from the
> >usual place:
> >
> > http://redhat.com/~mingo/realtime-preempt/
> 
> By the time I started today, the directory had -18 so that is what I built
> with. Here are some initial results from running cpu_delay (the simple
> RT test / user tracing) on a -18 PREEMPT_RT kernel. Have not started
> any of the stress tests yet.

Something that just happened to me: running 0.7.32-14 (PREEMPT_DESKTOP)
and trying to install 0.7.32-19 from a custom built rpm package
completely hangs the machine (p4 laptop - I tried twice). No clues left
behind. If I boot into 0.7.32-9 I can install 0.7.32-19 with no
problems. 

-- Fernando

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Ingo Molnar]

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

> Here is my get_ltrace.sh script (at the end).
> 
> So I read the preempt_max_latency (to see if its changed) before I
> copy the latency_trace output. I am not so sure that cat is really
> doing an "atomic" read when some of the latency traces are over 300
> Kbytes in length.

reading preempt_max_latency ought to be fine to detect changes.

yes, even a 300 KB trace should be read atomically too, even if it takes
3 seconds to save, hence all the different layers of trace buffers. The
kernel does not update the output buffer until the 'cat' has finished.
(unless a parallel 'cat' interferes - all your scripts are serialized,
right?)

> Also note that some of the files were empty :-(. I don't think I've
> seen that symptom before.

hm, an empty file occurs if the saved output trace is empty. This should
only be the case shortly after resetting preempt_max_latency. (or after
bootup, until it's set for the first time.)

> Note that the preempt_max_latency value DID match the last line of the
> trace output in the example I described. It is just the header that
> had some stale data in it.

yeah. It's weird. Ahh .. reviewing the header-generation code again i
noticed a buglet, which could cause spuriously wrong latency values on
SMP systems. Does the patch below fix this particular symptom?

	Ingo

--- linux/kernel/latency.c.orig
+++ linux/kernel/latency.c
@@ -542,7 +542,7 @@ static void update_out_trace(void)
 	 * trace buffer.
 	 */
 	tmp_out = out_tr.traces + 0;
-	*tmp_out = max_tr.traces[0]; // TODO: dont copy the traces
+	*tmp_out = max_tr.traces[max_tr.cpu]; // TODO: dont copy the traces
 	out_tr.cpu = max_tr.cpu;
 	out_entry = tmp_out->trace + 0;
 

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Ingo Molnar]

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

> The code does not quite match either pattern but is perhaps
> more like your second example.
> 
> For reference, the cpu_delay loop looks like this...
> 
>   t1 = mygettime();
>   for(u=0;u<(loops/1000);u++) {
>     t0 = t1;
>     if (do_a_trace) {
>       gettimeofday(0, (struct timezone*)1);
>     }
>     for (v=0;v<1000;v++)
>       k+=1;

If this is the code then on any modern CPU this is a delay on the order
of 2000 cycles - 2-3 usecs on your CPUs. The overhead of kernel entries
plus tracing is likely larger than this, so the window for the timing
race to occur ought to be pretty large.

this also means that the elapsed time of the CPU loop will be quite
variable, it will largely depend on the level and type of
tracing/debugging activated in the kernel. This could perhaps explain
the observed weirdnesses of the 'elapsed time' metric.

> [do some tests...]
> Now I'm 5 for 5 with the revised code. Odd that all the numbers
> are within about 2 or 3 usec (application measured / kernel measured).
> If it was as bad as I was measuring it, I would have expected
> one or two to be really off.

(5 for 5 means no missed latencies by the kernel tracer so far?)

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Mark_H_Johnson]

Here is my get_ltrace.sh script (at the end).

So I read the preempt_max_latency (to see if its changed) before
I copy the latency_trace output. I am not so sure that cat is
really doing an "atomic" read when some of the latency traces
are over 300 Kbytes in length.

Also note that some of the files were empty :-(. I don't think
I've seen that symptom before.

Note that the preempt_max_latency value DID match the last line of
the trace output in the example I described. It is just the header
that had some stale data in it.

  --Mark

--- get_ltrace.sh ---

#!/bin/sh

let MAX=`cat /proc/sys/kernel/preempt_max_latency`
let I=0 J=1
let MP=${1:-1000}
echo "Current Maximum is $MAX, limit will be $MP."
while (( I < 100 )) ; do
    sleep 1s
    let NOW=`cat /proc/sys/kernel/preempt_max_latency`
    if (( MAX != NOW )) ; then
        echo "New trace $I w/ $NOW usec latency."
        cat /proc/latency_trace > lt.`printf "%02d" $I`
#       sync ; sync
        let I++
        let MAX=NOW
    elif (( J++ >= 10 )) ; then
        if (( MAX != MP )) ; then
            echo "Resetting max latency from $MAX to $MP."
            echo $MP > /proc/sys/kernel/preempt_max_latency
            let MAX=$MP
        else
            echo "No new latency samples at `date`."
        fi
        let J=1
# else do nothing...
    fi
done

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Mark_H_Johnson]

>the only recent thing added was the global RT balancer, which is not
>active under PREEMPT_DESKTOP. Maybe this code somehow interferes with
>your workload? Could you try to disable it, ...

Real life will intervene before I can get the kernel built & tested
[have to pick up the kids...]. Will try this (w/o any tracing as well)
on Monday (and see if I can put RT in a good light...).

  --Mark

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Ingo Molnar]

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

> Hmm. Now that I look at it, the duration in the header (99 usec) is
> the duration of lt.01 (as reported by the script) but the total
> duration of the trace (248 usec) is the duration from the script for
> lt.02.

how do your collection scripts access /proc/latency_trace? The output is 
only atomic if the file is read as a whole, i.e.:

	cat /proc/latency_trace > wherever

or:

	cp /proc/latency wherever

but i guess you are doing this already ...

obviously tracing goes on while the scripts are saving the latency
trace, so the kernel goes to great lengths to try to guarantee
atomicity. There are 3 levels of tracing buffers:

	- 'current' trace buffers (per CPU)
	- 'max' trace buffer
	- 'output' trace buffer

the max trace is updated whenever a new max latency is detected. (not
stricly true: if one CPU is already saving a trace and this CPU detects
a new latency too then this CPU skips the trace, instead of spinning
waiting for the other CPU. This makes the tracing code more atomic, but
it opens up a window to 'lose' a latency - but statistically every
_type_ of latency should be saved sooner or later, since the 'dropping'
of traces is random, not systematic.)

the output trace is atomically filled in from the max trace, whenever
userspace accesses offset 0 of /proc/latency_trace. It will stay the
same until userspace finishes reading /proc/latency_trace (arrives to
the maximum offset of the file). Hence userspace can take all time it
wants to save a trace, it will stay the same. At least this is the
theory.

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Mark_H_Johnson]

The code does not quite match either pattern but is perhaps
more like your second example.

For reference, the cpu_delay loop looks like this...

  t1 = mygettime();
  for(u=0;u<(loops/1000);u++) {
    t0 = t1;
    if (do_a_trace) {
      gettimeofday(0, (struct timezone*)1);
    }
    for (v=0;v<1000;v++)
      k+=1;
    t1 = mygettime();
    if ((t1-t0)>max_delay){
      delay++;
      if (do_a_trace) {
        gettimeofday(0,0);
        do_a_trace = 0;
        printf("Trace triggered with %f second delay.\n",t1-t0);
      }
    }
  }

I was trying to avoid the extra "rdtsc" overhead (plus the
floating point calculations) so - yes, I could have cases
where the time I measure is not caught by the kernel tracer.

[do some tests...]
Now I'm 5 for 5 with the revised code. Odd that all the numbers
are within about 2 or 3 usec (application measured / kernel measured).
If it was as bad as I was measuring it, I would have expected
one or two to be really off.

  --Mark

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Ingo Molnar]

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

> Comparison of .32-18RT and .32-18PK results
> RT has PREEMPT_RT,
> PK has PREEMPT_DESKTOP and no threaded IRQ's.
> 2.4 has lowlat + preempt patches applied
> 
>       within 100 usec
>        CPU loop (%)   Elapsed Time (sec)    2.4
> Test   RT     PK        RT      PK   |   CPU  Elapsed
> X     90.40 100.00&     73 *    64+  |  97.20   70
> top   78.56 100.00&     39 *    31+  |  97.48   29
> neto  92.82 100.00&    350 *   184+  |  96.23   36
> neti  90.69 100.00&    350 *   170+  |  95.86   41
> diskw 82.96  99.99     360 *    61+  |  77.64   29
> diskc 91.41  99.34     350 *   310+  |  84.12   77
> diskr 88.41  99.96     360 *   310+  |  90.66   86
> total                 1881    1130   |         368
>  [higher is better]  [lower is better]
> * wide variation in audio duration
> + long stretch of audio duration "too fast"
> & 100% to digits shown, had a FEW samples > 100 usec.
> 
> WOW! Look at the 100% values measured on -18PK. The performance of 2.6
> with PREEMPT_DESKTOP is far better than 2.4 preempt+lowlat in every
> way except the non RT starvation problem. Something fixed between -12
> and -18 really made a big improvement.

yep, i guess it's the two missed-preemption points i fixed in -16.

> It is still disturbing to see the worse results for -18RT and I wish I
> knew what the cause was. Perhaps the traces I sent earlier can provide
> a clue.

are you sure you got the order of the columns right? :-|

e.g. the lt004.18PK traces you sent show a number of huge latencies,
biggest one being 1949µs. The biggest one in lt001.18RT is 250 usecs,
and much of that i believe is due to debugging overhead. (It's not
apples to apples because i dont have the RT-under-stress traces yet.) 

something's really not kosher here.

> Other notes:
> 
> [1] -PK has many more latency traces > 250 usec [some MUCH longer]
> than -RT. I ended up collecting more traces for -RT since I set the
> limit to 100 usec, but only got about 8 > 250 usec traces compared to
> 40 for -PK.

this too is suspicious to me. How can then the PREEMPT_RT kernel end up
performing within 100 usecs in only 78.56% of the measurements - it's
ridiculously low! The tracer might have a bug, but such a selective bug?

the only recent thing added was the global RT balancer, which is not
active under PREEMPT_DESKTOP. Maybe this code somehow interferes with
your workload? Could you try to disable it, by changing kernel/sched.c's
#ifdefs from:

 #if defined(CONFIG_PREEMPT_RT) && defined(CONFIG_SMP)

to:

 #if 0

(there are ~5 such places in sched.c)

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Mark_H_Johnson]

>* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:
>
>> [1] I still do not get traces where cpu_delay switches CPU's. I only
>> get trace output if it starts and ends on a single CPU. [...]
>
>lt001.18RT/lt.02 is such a trace. It starts on CPU#1:
>
> <unknown-3556  1...1    0µs : find_next_bit (user_trace_start)
>
>and ends on CPU#0:
>
> <unknown-3556  1...1  247µs : _raw_spin_lock_irqsave (user_trace_stop)
>
>the trace shows a typical migration of an RT task.

Hmm. Now I look at it more clearly like...
 # grep '^<unknown-3556' lt001.18RT/lt.02
I can see what you mean. Though this time it moved from one [22 usec]
to zero [189 usec] and back to one [238 usec] before it finally stopped
the trace at 248 usec. [the attempt to reschedule on CPU zero was
clearly ineffective]

This trace is also odd in that the duration of the trace in the header is
listed as 99 usec (and the application confirmed that) but the trace
ends at 248 usec.

Hmm. Now that I look at it, the duration in the header (99 usec) is the
duration of lt.01 (as reported by the script) but the total duration
of the trace (248 usec) is the duration from the script for lt.02.


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

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Ingo Molnar]

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

> [...] I also had several cases where I "triggered" a trace but no
> output - I assume those are related symptoms. For example:
> 
> # ./cpu_delay 0.000100
> Delay limit set to 0.00010000 seconds
> calibrating loop ....
> time diff= 0.504598 or 396354830 loops/sec.
> Trace activated with 0.000100 second delay.
> Trace triggered with 0.000102 second delay. [not recorded]
> Trace activated with 0.000100 second delay.
> Trace triggered with 0.000164 second delay. [not recorded]

is the userspace delay measurement nested inside the kernel-based
method? I.e. is it something like:

	gettimeofday(0,1);
	timestamp1 = cycles();

	... loop some ...

	timestamp2 = cycles();
	gettimeofday(0,0);

and do you get 'unreported' latencies in such a case too? If yes then
that would indeed indicate a tracer bug. But if the measurement is done
like this:

	gettimeofday(0,1);
	timestamp1 = cycles();

	... loop some ...

	gettimeofday(0,0);		// [1]
	timestamp2 = cycles();		// [2]

then a delay could get inbetween [1] and [2].

OTOH if the 'loop some' time is long enough then the [1]-[2] window is
too small to be significant statistically, while your logs show a near
50% 'miss rate'.

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Ingo Molnar]

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

> [3] Some traces show information on both CPU's and then a long period
> with no traces from the other. Here is an example...

> <unknown-2847  1d.h.    4µs : rebalance_tick (scheduler_tick)
> <unknown-2847  1d.h.    5µs : irq_exit (apic_timer_interrupt)
> <unknown-2847  1d...    5µs < (0)

> ... no more traces from CPU 1 ...

PID 2847 returned to userspace at timestamp 5µs. Userspace then can take
an arbitrary amount of time until it calls the kernel again.

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Ingo Molnar]

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

> [1] I still do not get traces where cpu_delay switches CPU's. I only
> get trace output if it starts and ends on a single CPU. [...]

lt001.18RT/lt.02 is such a trace. It starts on CPU#1:

 <unknown-3556  1...1    0µs : find_next_bit (user_trace_start)

and ends on CPU#0:

 <unknown-3556  1...1  247µs : _raw_spin_lock_irqsave (user_trace_stop)

the trace shows a typical migration of an RT task.

(but ... i have to say the debugging overhead is horrible. Please try a
completely-non-debug-non-tracing kernel just to see the difference.)

	Ingo

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Mark_H_Johnson]

Comparison of .32-18RT and .32-18PK results
RT has PREEMPT_RT,
PK has PREEMPT_DESKTOP and no threaded IRQ's.
2.4 has lowlat + preempt patches applied

      within 100 usec
       CPU loop (%)   Elapsed Time (sec)    2.4
Test   RT     PK        RT      PK   |   CPU  Elapsed
X     90.40 100.00&     73 *    64+  |  97.20   70
top   78.56 100.00&     39 *    31+  |  97.48   29
neto  92.82 100.00&    350 *   184+  |  96.23   36
neti  90.69 100.00&    350 *   170+  |  95.86   41
diskw 82.96  99.99     360 *    61+  |  77.64   29
diskc 91.41  99.34     350 *   310+  |  84.12   77
diskr 88.41  99.96     360 *   310+  |  90.66   86
total                 1881    1130   |         368
 [higher is better]  [lower is better]
* wide variation in audio duration
+ long stretch of audio duration "too fast"
& 100% to digits shown, had a FEW samples > 100 usec.

WOW! Look at the 100% values measured on -18PK. The performance
of 2.6 with PREEMPT_DESKTOP is far better than 2.4 preempt+lowlat
in every way except the non RT starvation problem. Something
fixed between -12 and -18 really made a big improvement.

It is still disturbing to see the worse results for -18RT
and I wish I knew what the cause was. Perhaps the traces I sent
earlier can provide a clue.

Other notes:

[1] -PK has many more latency traces > 250 usec [some MUCH longer]
than -RT. I ended up collecting more traces for -RT since I set
the limit to 100 usec, but only got about 8 > 250 usec traces
compared to 40 for -PK.

[2] Some of the traces in -PK are extremely long (up to 2 msec) and
I guess I'm glad I have an SMP system to run the RT application on
the other CPU. Here's an extract of one example:

reemption latency trace v1.1.4 on 2.6.10-rc2-mm3-V0.7.32-18PK
--------------------------------------------------------------------
 latency: 1698 us, #3137/3137, CPU#0 | (M:preempt VP:0, KP:1, SP:0 HP:0
#P:2)
    -----------------
    | task: kjournald-1203 (uid:0 nice:0 policy:0 rt_prio:0)
    -----------------

                 _------=> CPU#
                / _-----=> irqs-off
               | / _----=> need-resched
               || / _---=> hardirq/softirq
               ||| / _--=> preempt-depth
               |||| /
               |||||     delay
   cmd     pid ||||| time  |   caller
      \   /    |||||   \   |   /
<unknown-1203  0d..1    0µs < (54)
<unknown-1203  0...1    0µs : journal_remove_journal_head
(journal_commit_transaction)
<unknown-1203  0...1    1µs : __journal_remove_journal_head
(journal_remove_journal_head)
<unknown-1203  0...1    1µs : __brelse (__journal_remove_journal_head)
<unknown-1203  0...1    1µs : journal_free_journal_head
(journal_remove_journal_head)
<unknown-1203  0...1    1µs : kmem_cache_free (journal_free_journal_head)
<unknown-1203  0d..1    2µs : cache_flusharray (kmem_cache_free)
<unknown-1203  0d..1    2µs : _raw_spin_lock (cache_flusharray)
<unknown-1203  0d..2    2µs+: free_block (cache_flusharray)
<unknown-1203  0d..2    5µs : _raw_spin_unlock (cache_flusharray)
<unknown-1203  0d..1    5µs : memmove (cache_flusharray)
<unknown-1203  0d..1    5µs : memcpy (memmove)
<unknown-1203  0...1    6µs : inverted_lock (journal_commit_transaction)
<unknown-1203  0...1    6µs : __journal_unfile_buffer
(journal_commit_transaction)
<unknown-1203  0...1    7µs : journal_remove_journal_head
(journal_commit_transaction)
<unknown-1203  0...1    7µs : __journal_remove_journal_head
(journal_remove_journal_head)
<unknown-1203  0...1    8µs : __brelse (__journal_remove_journal_head)
<unknown-1203  0...1    8µs : journal_free_journal_head
(journal_remove_journal_head)
<unknown-1203  0...1    8µs : kmem_cache_free (journal_free_journal_head)
<unknown-1203  0...1    9µs : inverted_lock (journal_commit_transaction)
<unknown-1203  0...1    9µs : __journal_unfile_buffer
(journal_commit_transaction)
...
<unknown-1203  0...1  835µs : journal_remove_journal_head
(journal_commit_transaction)
<unknown-1203  0...1  835µs : __journal_remove_journal_head
(journal_remove_journal_head)
<unknown-1203  0...1  836µs : __brelse (__journal_remove_journal_head)
<unknown-1203  0...1  836µs : journal_free_journal_head
(journal_remove_journal_head)
<unknown-1203  0...1  837µs : kmem_cache_free (journal_free_journal_head)
<unknown-1203  0d..1  837µs : cache_flusharray (kmem_cache_free)
<unknown-1203  0d..1  837µs : _raw_spin_lock (cache_flusharray)
<unknown-1203  0d..2  838µs : free_block (cache_flusharray)
<unknown-1203  0d.h2  839µs : do_nmi (__mcount)
<unknown-1203  0d.h2  840µs : do_nmi (<08048340>)
<unknown-1203  0d.h2  840µs+: do_nmi (<00200282>)
<unknown-1203  0d..2  843µs : _raw_spin_unlock (cache_flusharray)
<unknown-1203  0d..1  844µs : memmove (cache_flusharray)
<unknown-1203  0d..1  844µs : memcpy (memmove)
<unknown-1203  0...1  844µs : inverted_lock (journal_commit_transaction)
...
<unknown-1203  0d.h2 1686µs : __mod_timer (ide_execute_command)
<unknown-1203  0d.h2 1686µs : _raw_spin_lock_irqsave (__mod_timer)
<unknown-1203  0d.h3 1687µs : _raw_spin_lock (__mod_timer)
<unknown-1203  0d.h4 1687µs : internal_add_timer (__mod_timer)
<unknown-1203  0d.h4 1687µs : _raw_spin_unlock (__mod_timer)
<unknown-1203  0d.h3 1688µs : _raw_spin_unlock_irqrestore (__mod_timer)
<unknown-1203  0d.h2 1688µs : ide_outbsync (ide_execute_command)
<unknown-1203  0d.h2 1689µs : __const_udelay (ide_execute_command)
<unknown-1203  0d.h2 1690µs : __delay (ide_execute_command)
<unknown-1203  0d.h2 1690µs : delay_tsc (__delay)
<unknown-1203  0d.h2 1691µs : _raw_spin_unlock_irqrestore
(ide_dma_exec_cmd)
<unknown-1203  0..h1 1691µs : ide_dma_start (__ide_do_rw_disk)
<unknown-1203  0..h1 1692µs : ide_inb (ide_dma_start)
<unknown-1203  0..h1 1692µs : ide_outb (ide_dma_start)
<unknown-1203  0..h1 1693µs : _raw_spin_lock_irq (ide_do_request)
<unknown-1203  0..h1 1693µs : _raw_spin_lock_irqsave (ide_do_request)
<unknown-1203  0d.h2 1694µs : _raw_spin_unlock_irqrestore (ide_intr)
<unknown-1203  0d.h1 1695µs : _raw_spin_lock (__do_IRQ)
<unknown-1203  0d.h2 1695µs : note_interrupt (__do_IRQ)
<unknown-1203  0d.h2 1696µs : end_edge_ioapic_irq (__do_IRQ)
<unknown-1203  0d.h2 1696µs : _raw_spin_unlock (__do_IRQ)
<unknown-1203  0d.h1 1696µs : irq_exit (do_IRQ)

[3] The charts are very smooth on -PK, very similar to those on
2.4 other than the "too fast" symptom for the audio duration.
[the white line is shifted down when compared to the nominal
duration yellow line]

[4] -PK also had two of the non RT starvation periods. Each was
almost 3 minutes long (should be a 5 second sleep). -RT had
none.

Will send the traces separately.
  --Mark

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Mark_H_Johnson]

This time, initial test results on -18PK (PREEMPT_DESKTOP, no IRQ
threading).

Again, results running cpu_delay and collecting user triggered traces.

[1] Similar symptoms where I do not get traces that span CPU's plus
the missing trace symptom.

# ./cpu_delay 0.000100
Delay limit set to 0.00010000 seconds
calibrating loop ....
time diff= 0.503365 or 397326229 loops/sec.
Trace activated with 0.000100 second delay.
Trace triggered with 0.000321 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000136 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000139 second delay. [00]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000130 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000240 second delay. [01]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000104 second delay. [02]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000130 second delay. [03]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000109 second delay. [04]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000109 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000155 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000100 second delay. [05]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000105 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000128 second delay. [06]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000123 second delay. [07]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000100 second delay. [08]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000113 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000136 second delay. [09]

# chrt -f 1 ./get_ltrace.sh 50
Current Maximum is 4965280, limit will be 50.
Resetting max latency from 4965280 to 50.
No new latency samples at Fri Dec 10 13:42:31 CST 2004.
No new latency samples at Fri Dec 10 13:42:41 CST 2004.
No new latency samples at Fri Dec 10 13:42:51 CST 2004.
No new latency samples at Fri Dec 10 13:43:01 CST 2004.
New trace 0 w/ 139 usec latency.
Resetting max latency from 139 to 50.
No new latency samples at Fri Dec 10 13:43:23 CST 2004.
New trace 1 w/ 241 usec latency.
Resetting max latency from 241 to 50.
No new latency samples at Fri Dec 10 13:43:44 CST 2004.
New trace 2 w/ 103 usec latency.
Resetting max latency from 103 to 50.
New trace 3 w/ 130 usec latency.
Resetting max latency from 130 to 50.
No new latency samples at Fri Dec 10 13:44:17 CST 2004.
No new latency samples at Fri Dec 10 13:44:27 CST 2004.
No new latency samples at Fri Dec 10 13:44:37 CST 2004.
New trace 4 w/ 109 usec latency.
Resetting max latency from 109 to 50.
No new latency samples at Fri Dec 10 13:44:58 CST 2004.
New trace 5 w/ 100 usec latency.
Resetting max latency from 100 to 50.
New trace 6 w/ 128 usec latency.
Resetting max latency from 128 to 50.
New trace 7 w/ 123 usec latency.
Resetting max latency from 123 to 50.
New trace 8 w/ 100 usec latency.
Resetting max latency from 100 to 50.
No new latency samples at Fri Dec 10 13:45:54 CST 2004.
New trace 9 w/ 135 usec latency.
Resetting max latency from 135 to 50.

I don't see a significant difference in failures to record when compared
with -18RT (7 vs. 8).

[2] I get no ksoftirqd activity (as expected).

[3] Long sequences of one CPU only was seen again. Though in looking
at these traces I find several incomplete ones like this:

preemption latency trace v1.1.4 on 2.6.10-rc2-mm3-V0.7.32-18PK
--------------------------------------------------------------------
 latency: 139 us, #55/55, CPU#1 | (M:preempt VP:0, KP:1, SP:0 HP:0 #P:2)
    -----------------
    | task: cpu_delay-3517 (uid:0 nice:0 policy:1 rt_prio:30)
    -----------------
 => started at: <00000000>
 => ended at:   <00000000>

                 _------=> CPU#
                / _-----=> irqs-off
               | / _----=> need-resched
               || / _---=> hardirq/softirq
               ||| / _--=> preempt-depth
               |||| /
               |||||     delay
   cmd     pid ||||| time  |   caller
      \   /    |||||   \   |   /
<unknown-0     0d.h1    0µs : do_nmi (default_idle)
<unknown-0     0d.h1    0µs : do_nmi (_raw_spin_lock_irqsave)
<unknown-3517  1d.H2    0µs : do_nmi (default_idle)
<unknown-0     0d.h1    0µs : do_nmi (<00200246>)
<unknown-3517  1d.H2    0µs+: do_nmi ((514))
<unknown-0     0...1    3µs : default_idle (cpu_idle)
<unknown-3517  1d.H2    3µs : do_IRQ (c013a0cc 0 0)
<unknown-3517  1d.H2    3µs : _raw_spin_lock (__do_IRQ)
<unknown-3517  1d.H3    4µs : ack_edge_ioapic_irq (__do_IRQ)
<unknown-3517  1d.H3    4µs : redirect_hardirq (__do_IRQ)
<unknown-3517  1d.H3    5µs : _raw_spin_unlock (__do_IRQ)
<unknown-3517  1d.H2    5µs : handle_IRQ_event (__do_IRQ)
<unknown-3517  1d.H2    5µs : timer_interrupt (handle_IRQ_event)
<unknown-3517  1d.H2    6µs : _raw_spin_lock (timer_interrupt)
<unknown-3517  1d.H3    6µs : mark_offset_tsc (timer_interrupt)
<unknown-3517  1d.H3    7µs : _raw_spin_lock (mark_offset_tsc)
<unknown-3517  1d.H4    7µs+: _raw_spin_lock_irqsave (mark_offset_tsc)
<unknown-3517  1d.H5   13µs : _raw_spin_unlock_irqrestore (mark_offset_tsc)
<unknown-3517  1d.H4   14µs : _raw_spin_unlock (mark_offset_tsc)
<unknown-3517  1d.H3   14µs+: _raw_spin_lock_irqsave (timer_interrupt)
<unknown-3517  1d.H4   18µs : _raw_spin_unlock_irqrestore (timer_interrupt)
<unknown-3517  1d.H3   18µs : do_timer (timer_interrupt)
<unknown-3517  1d.H3   19µs : _raw_spin_unlock (timer_interrupt)
<unknown-3517  1d.H2   19µs : _raw_spin_lock (__do_IRQ)
<unknown-3517  1d.H3   20µs : note_interrupt (__do_IRQ)
<unknown-3517  1d.H3   20µs : end_edge_ioapic_irq (__do_IRQ)
<unknown-3517  1d.H3   21µs : _raw_spin_unlock (__do_IRQ)
<unknown-3517  1d.H2   21µs : irq_exit (do_IRQ)
<unknown-3517  1d.s2   21µs < (0)
<unknown-3517  1..s1   22µs : mod_timer (rt_check_expire)
<unknown-3517  1..s1   23µs : __mod_timer (rt_check_expire)
<unknown-3517  1..s1   23µs : _raw_spin_lock_irqsave (__mod_timer)
<unknown-3517  1d.s2   24µs : _raw_spin_lock (__mod_timer)
<unknown-3517  1d.s3   24µs : internal_add_timer (__mod_timer)
<unknown-3517  1d.s3   25µs : _raw_spin_unlock (__mod_timer)
<unknown-3517  1d.s2   25µs : _raw_spin_unlock_irqrestore (__mod_timer)
<unknown-3517  1..s1   26µs : cond_resched_all (run_timer_softirq)
<unknown-3517  1..s1   26µs : cond_resched_softirq (run_timer_softirq)
<unknown-3517  1..s1   26µs : _raw_spin_lock_irq (run_timer_softirq)
<unknown-3517  1..s1   27µs : _raw_spin_lock_irqsave (run_timer_softirq)
<unknown-3517  1d.s2   28µs : _raw_spin_unlock_irq (run_timer_softirq)
<unknown-3517  1..s1   29µs : __wake_up (run_timer_softirq)
<unknown-3517  1..s1   29µs : _raw_spin_lock_irqsave (__wake_up)
<unknown-3517  1d.s2   29µs : __wake_up_common (__wake_up)
<unknown-3517  1d.s2   30µs : _raw_spin_unlock_irqrestore
(run_timer_softirq)
<unknown-3517  1..s1   30µs : cond_resched_all (___do_softirq)
<unknown-3517  1..s1   30µs : cond_resched_softirq (___do_softirq)
<unknown-3517  1d...   31µs < (0)
<unknown-3517  1d...   32µs+< (0)
<unknown-3517  1....   35µs > sys_gettimeofday (00000000 00000000 0000007b)
<unknown-3517  1....   35µs : sys_gettimeofday (sysenter_past_esp)
<unknown-3517  1....   35µs : user_trace_stop (sys_gettimeofday)
<unknown-3517  1...1   36µs : user_trace_stop (sys_gettimeofday)
<unknown-3517  1...1   36µs : _raw_spin_lock_irqsave (user_trace_stop)
<unknown-3517  1d..2   37µs : _raw_spin_unlock_irqrestore (user_trace_stop)

I assume that since it does not start with user_trace_start (or something
like that) that the missing portion is the first portion.

[4] Not sure if I can make the same comment on -18PK as I did for -18RT
on changing CPU's [since I understand we do not have the opportunity to
do so unless the IRQ's are threaded].

[5] The trace output cosmetic problems are on PREEMPT_DESKTOP as well.

Traces to come shortly in a separate message.
  --Mark

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Lee Revell]

On Fri, 2004-12-10 at 11:53 +0100, Ingo Molnar wrote:
> The -32-15 kernel can be downloaded from the
> usual place:
> 
>  http://redhat.com/~mingo/realtime-preempt/

Any chance this will work on x86_64 anytime soon?  Not necessarily
PREEMPT_RT, it would be nice if PREEMPT_DESKTOP worked.  You mentioned a
few weeks ago it needs the timer interrupt threading changes.

  CC      arch/x86_64/kernel/asm-offsets.s
In file included from include/asm/timex.h:12,
                 from include/linux/timex.h:61,
                 from include/linux/sched.h:11,
                 from arch/x86_64/kernel/asm-offsets.c:7:
include/asm/vsyscall.h:55: error: conflicting types for \'xtime_lock\'
include/linux/time.h:83: error: previous declaration of \'xtime_lock\'
was here
include/asm/vsyscall.h:55: error: conflicting types for \'xtime_lock\'
include/linux/time.h:83: error: previous declaration of \'xtime_lock\'
was here
make[1]: *** [arch/x86_64/kernel/asm-offsets.s] Error 1
make: *** [arch/x86_64/kernel/asm-offsets.s] Error 2

Lee 

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Mark_H_Johnson]

>The -32-15 kernel can be downloaded from the
>usual place:
>
> http://redhat.com/~mingo/realtime-preempt/

By the time I started today, the directory had -18 so that is what I built
with. Here are some initial results from running cpu_delay (the simple
RT test / user tracing) on a -18 PREEMPT_RT kernel. Have not started
any of the stress tests yet.

To recap, all IRQ # tasks, ksoftirqd/# and events/# tasks are RT FIFO
priority 99. The test program runs at RT FIFO 30 and should use about
70% of the CPU time on the two CPU SMP system under test.

[1] I still do not get traces where cpu_delay switches CPU's. I only
get trace output if it starts and ends on a single CPU. I also had
several cases where I "triggered" a trace but no output - I assume
those are related symptoms. For example:

# ./cpu_delay 0.000100
Delay limit set to 0.00010000 seconds
calibrating loop ....
time diff= 0.504598 or 396354830 loops/sec.
Trace activated with 0.000100 second delay.
Trace triggered with 0.000102 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000164 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000132 second delay. [00]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000128 second delay. [01]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000144 second delay. [not recorded]
Trace triggered with 0.000355 second delay. [02]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000101 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000126 second delay. [not recorded]
Trace triggered with 0.000205 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000147 second delay. [03]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000135 second delay. [04]
Trace triggered with 0.000110 second delay. [not recorded]
Trace triggered with 0.000247 second delay. [05]
Trace triggered with 0.000120 second delay. [06]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000107 second delay. [07]
Trace triggered with 0.000104 second delay. [not recorded]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000100 second delay. [08]
Trace activated with 0.000100 second delay.
Trace triggered with 0.000201 second delay. [09]

# chrt -f 1 ./get_ltrace.sh 50
Current Maximum is 4965280, limit will be 50.
Resetting max latency from 4965280 to 50.
No new latency samples at Fri Dec 10 11:01:22 CST 2004.
No new latency samples at Fri Dec 10 11:01:32 CST 2004.
No new latency samples at Fri Dec 10 11:01:42 CST 2004.
No new latency samples at Fri Dec 10 11:01:53 CST 2004.
No new latency samples at Fri Dec 10 11:02:03 CST 2004.
No new latency samples at Fri Dec 10 11:02:13 CST 2004.
New trace 0 w/ 117 usec latency.
Resetting max latency from 117 to 50.
No new latency samples at Fri Dec 10 11:02:35 CST 2004.
No new latency samples at Fri Dec 10 11:02:45 CST 2004.
New trace 1 w/ 99 usec latency.
Resetting max latency from 99 to 50.
New trace 2 w/ 248 usec latency.
Resetting max latency from 248 to 50.
New trace 3 w/ 146 usec latency.
Resetting max latency from 146 to 50.
New trace 4 w/ 134 usec latency.
Resetting max latency from 134 to 50.
New trace 5 w/ 250 usec latency.
Resetting max latency from 250 to 50.
New trace 6 w/ 120 usec latency.
Resetting max latency from 120 to 50.
New trace 7 w/ 105 usec latency.
Resetting max latency from 105 to 50.
New trace 8 w/ 91 usec latency.
Resetting max latency from 91 to 50.
New trace 9 w/ 200 usec latency.

For the most part, the elapsed times in the traces match closely to what
was measured by the application.

[2] The all CPU traces appear to show some cases where both ksoftirqd
tasks are active during a preemption of the RT task. That is expected
with my priority settings. [though the first trace shows BOTH getting
activated within 2 usec!]

[3] Some traces show information on both CPU's and then a long period
with no traces from the other. Here is an example...

preemption latency trace v1.1.4 on 2.6.10-rc2-mm3-V0.7.32-18RT
--------------------------------------------------------------------
 latency: 99 us, #275/275, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
    -----------------
    | task: cpu_delay-3556 (uid:0 nice:0 policy:1 rt_prio:30)
    -----------------
 => started at: <00000000>
 => ended at:   <00000000>

                 _------=> CPU#
                / _-----=> irqs-off
               | / _----=> need-resched
               || / _---=> hardirq/softirq
               ||| / _--=> preempt-depth
               |||| /
               |||||     delay
   cmd     pid ||||| time  |   caller
      \   /    |||||   \   |   /
<unknown-2847  1d...    0µs : smp_apic_timer_interrupt (86a89bf 0 0)
cpu_dela-3556  0d.h1    0µs : update_process_times
(smp_apic_timer_interrupt)
cpu_dela-3556  0d.h1    0µs : account_system_time (update_process_times)
cpu_dela-3556  0d.h1    0µs : check_rlimit (account_system_time)
<unknown-2847  1d.h.    0µs : update_process_times
(smp_apic_timer_interrupt)
cpu_dela-3556  0d.h1    0µs : account_it_prof (account_system_time)
...
<unknown-2847  1d.h1    4µs : _raw_spin_unlock (scheduler_tick)
cpu_dela-3556  0d.h1    4µs : irq_exit (apic_timer_interrupt)
<unknown-2847  1d.h.    4µs : rebalance_tick (scheduler_tick)
cpu_dela-3556  0d..2    4µs : do_softirq (irq_exit)
cpu_dela-3556  0d..2    4µs : __do_softirq (do_softirq)
<unknown-2847  1d.h.    5µs : irq_exit (apic_timer_interrupt)
cpu_dela-3556  0d..2    5µs : wake_up_process (do_softirq)
cpu_dela-3556  0d..2    5µs : try_to_wake_up (wake_up_process)
cpu_dela-3556  0d..2    5µs : task_rq_lock (try_to_wake_up)
<unknown-2847  1d...    5µs < (0)
cpu_dela-3556  0d..2    5µs : _raw_spin_lock (task_rq_lock)
cpu_dela-3556  0d..3    6µs : activate_task (try_to_wake_up)
cpu_dela-3556  0d..3    6µs : sched_clock (activate_task)
cpu_dela-3556  0d..3    7µs : recalc_task_prio (activate_task)
cpu_dela-3556  0d..3    7µs : effective_prio (recalc_task_prio)
cpu_dela-3556  0d..3    7µs : activate_task <ksoftirq-4> (0 1):
cpu_dela-3556  0d..3    7µs : enqueue_task (activate_task)
cpu_dela-3556  0d..3    8µs : resched_task (try_to_wake_up)
cpu_dela-3556  0dn.3    8µs : __trace_start_sched_wakeup (try_to_wake_up)
cpu_dela-3556  0dn.3    8µs : try_to_wake_up <ksoftirq-4> (0 45):
cpu_dela-3556  0dn.3    9µs : _raw_spin_unlock_irqrestore (try_to_wake_up)
cpu_dela-3556  0dn.2    9µs : preempt_schedule (try_to_wake_up)
cpu_dela-3556  0dn.2    9µs : wake_up_process (do_softirq)
cpu_dela-3556  0dn.1   10µs < (0)
cpu_dela-3556  0.n.1   10µs : preempt_schedule (up)
cpu_dela-3556  0.n..   10µs : preempt_schedule (user_trace_start)
cpu_dela-3556  0dn..   11µs : __sched_text_start (preempt_schedule)
cpu_dela-3556  0dn.1   11µs : sched_clock (__sched_text_start)
cpu_dela-3556  0dn.1   11µs : _raw_spin_lock_irq (__sched_text_start)
cpu_dela-3556  0dn.1   12µs : _raw_spin_lock_irqsave (__sched_text_start)
cpu_dela-3556  0dn.2   12µs : pull_rt_tasks (__sched_text_start)
cpu_dela-3556  0dn.2   12µs : find_next_bit (pull_rt_tasks)
cpu_dela-3556  0dn.2   13µs : find_next_bit (pull_rt_tasks)
cpu_dela-3556  0d..2   13µs : trace_array (__sched_text_start)
cpu_dela-3556  0d..2   13µs : trace_array <ksoftirq-4> (0 1):
cpu_dela-3556  0d..2   15µs : trace_array <cpu_dela-3556> (45 46):
cpu_dela-3556  0d..2   16µs+: trace_array (__sched_text_start)
ksoftirq-4     0d..2   19µs : __switch_to (__sched_text_start)
ksoftirq-4     0d..2   20µs : __sched_text_start <cpu_dela-3556> (45 0):
ksoftirq-4     0d..2   20µs : finish_task_switch (__sched_text_start)
ksoftirq-4     0d..2   20µs : smp_send_reschedule_allbutself
(finish_task_switch)
ksoftirq-4     0d..2   20µs : send_IPI_allbutself
(smp_send_reschedule_allbutself)
ksoftirq-4     0d..2   21µs : __bitmap_weight (send_IPI_allbutself)
ksoftirq-4     0d..2   21µs : __send_IPI_shortcut (send_IPI_allbutself)
ksoftirq-4     0d..2   21µs : _raw_spin_unlock (finish_task_switch)
ksoftirq-4     0d..1   22µs : trace_stop_sched_switched
(finish_task_switch)
ksoftirq-4     0....   23µs : _do_softirq (ksoftirqd)
ksoftirq-4     0d...   23µs : ___do_softirq (_do_softirq)
ksoftirq-4     0....   23µs : run_timer_softirq (___do_softirq)
ksoftirq-4     0....   24µs : _spin_lock (run_timer_softirq)
ksoftirq-4     0....   24µs : __spin_lock (_spin_lock)
ksoftirq-4     0....   24µs : __might_sleep (__spin_lock)
<unknown-2847  1d...   24µs : smp_reschedule_interrupt (86a8bd8 0 0)
ksoftirq-4     0....   24µs : _down_mutex (__spin_lock)
<unknown-2847  1d...   25µs < (0)
ksoftirq-4     0....   25µs : __down_mutex (__spin_lock)
ksoftirq-4     0....   25µs : __might_sleep (__down_mutex)
ksoftirq-4     0d...   25µs : _raw_spin_lock (__down_mutex)
ksoftirq-4     0d..1   25µs : _raw_spin_lock (__down_mutex)
ksoftirq-4     0d..2   26µs : _raw_spin_lock (__down_mutex)
ksoftirq-4     0d..3   26µs : set_new_owner (__down_mutex)
ksoftirq-4     0d..3   26µs : set_new_owner <ksoftirq-4> (0 0):
ksoftirq-4     0d..3   27µs : _raw_spin_unlock (__down_mutex)
ksoftirq-4     0d..2   27µs : _raw_spin_unlock (__down_mutex)
ksoftirq-4     0d..1   27µs : _raw_spin_unlock (__down_mutex)
... no more traces from CPU 1 ...
ksoftirq-4     0....   77µs : rcu_check_quiescent_state
(__rcu_process_callbacks)
ksoftirq-4     0....   77µs : cond_resched_all (___do_softirq)
ksoftirq-4     0....   77µs : cond_resched (___do_softirq)
ksoftirq-4     0....   78µs : cond_resched (ksoftirqd)
ksoftirq-4     0....   78µs : kthread_should_stop (ksoftirqd)
ksoftirq-4     0....   78µs : schedule (ksoftirqd)
ksoftirq-4     0....   78µs : __sched_text_start (schedule)
ksoftirq-4     0...1   79µs : sched_clock (__sched_text_start)
ksoftirq-4     0...1   79µs : _raw_spin_lock_irq (__sched_text_start)
ksoftirq-4     0...1   79µs : _raw_spin_lock_irqsave (__sched_text_start)
ksoftirq-4     0d..2   80µs : deactivate_task (__sched_text_start)
ksoftirq-4     0d..2   80µs : dequeue_task (deactivate_task)
ksoftirq-4     0d..2   81µs : trace_array (__sched_text_start)
ksoftirq-4     0d..2   82µs : trace_array <cpu_dela-3556> (45 46):
ksoftirq-4     0d..2   84µs+: trace_array (__sched_text_start)
cpu_dela-3556  0d..2   86µs : __switch_to (__sched_text_start)
cpu_dela-3556  0d..2   87µs : __sched_text_start <ksoftirq-4> (0 45):
cpu_dela-3556  0d..2   87µs : finish_task_switch (__sched_text_start)
cpu_dela-3556  0d..2   87µs : _raw_spin_unlock (finish_task_switch)
cpu_dela-3556  0d..1   88µs : trace_stop_sched_switched
(finish_task_switch)
cpu_dela-3556  0d...   89µs+< (0)
cpu_dela-3556  0d...   92µs : math_state_restore (device_not_available)
cpu_dela-3556  0d...   92µs : restore_fpu (math_state_restore)
cpu_dela-3556  0d...   93µs < (0)
cpu_dela-3556  0....   93µs > sys_gettimeofday (00000000 00000000 0000007b)
cpu_dela-3556  0....   93µs : sys_gettimeofday (sysenter_past_esp)
cpu_dela-3556  0....   94µs : user_trace_stop (sys_gettimeofday)
cpu_dela-3556  0...1   94µs : user_trace_stop (sys_gettimeofday)
cpu_dela-3556  0...1   95µs : _raw_spin_lock_irqsave (user_trace_stop)
cpu_dela-3556  0d..2   95µs : _raw_spin_unlock_irqrestore (user_trace_stop)

If I read this right, we tried to reschedule cpu_delay on CPU #1 (at
24 usec) but it never happened and cpu_delay was still "ready to run"
on CPU #0 70 usec later.

[4] I have a trace where cpu_delay was bumped off of CPU #1 at 20 usec
while the X server (not RT) was the active process on CPU #0 for another
130 usec (several traces with preempt-depth ==0) when it finally gets
bumped by IRQ 0.

[5] More of a cosmetic problem, several traces still show the
application name as "unknown" - even for long lived processes like
ksoftirqd/0 and X.

Due to the file size, I will send the traces separately.
  --Mark

Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Gene Heskett]

On Friday 10 December 2004 09:59, Gene Heskett wrote:
>On Friday 10 December 2004 05:53, Ingo Molnar wrote:
>>* Ingo Molnar <mingo@elte.hu> wrote:
>>> this smells too. [...]
>
>Humm, something else does too Ingo.  Amanda failed on this
>machine last night, and so did an amcheck just now, returning this:
>
>[amanda@coyote driver]$ amcheck Daily
>Amanda Tape Server Host Check
>-----------------------------
>Holding disk /dumps: 26444 MB disk space available, using 25944 MB
>amcheck-server: slot 8: date 20041210 label Dailys-8 (active tape)
>amcheck-server: slot 9: date 20041124 label Dailys-9 (exact label
>match)
>NOTE: skipping tape-writable test
>Tape Dailys-9 label ok
>Server check took 0.386 seconds
>
>Amanda Backup Client Hosts Check
>--------------------------------
>WARNING: coyote: selfcheck reply timed out.
>Client check: 2 hosts checked in 22.199 seconds, 1 problem found
>
>(brought to you by Amanda 2.4.5b1-20041122)
>------------------
>This was while running 32-12, which otherwise feels good and gave
>me no other indication of a problem.  I've also looked at the log,
>but its silent on this subject.  I'll get the latest and try it.

Ok, the 32-18 is up and running, and it appears that amanda is not
so unhappy now as I seem to have a hand launched session thats
running nominally now.

To toss in a few more items, I noted that I had several copies of
amandad, and a copy of self-check that were getting 0 cpu according
to htop.  They were killable however, and re-running the amcheck
again left them behind.

Another factoid.  kpm, the kde version of htop, was unable to
display a process table listing while -12 was running.

32-18 seems to have restored all those to normal.

Is there a way I can run tvtime without making /var/log/messages
bigger by about 20k a minute with those 3 line reports it
apparently spits out for every frame of tv?  These patches aren't
apparently doing anything for the problem one way or the other, so
AFAIAC the constant flow messages are a waste of time and may even
be causing their own problem with the constant traffic to the
logfile..

>
>>found two brown-paperbag bugs that caused bad latencies in the -RT
>>kernel: when i added PREEMPT_DIRECT (which first showed up in
>> -32-10) i also added a missed-reschedule bug to try_to_wake_up()
>> and to mutex/semaphore-unlock (__up()). Oops.
>>
>>i dont think this bug could explain a msec-range latency because
>> the syscall return path should catch the missed reschedule and it
>> would need continuous syscall execution in the milliseconds range
>> by a lowprio task for a latency to be transported to latencytest,
>> but certainly the bug doesnt help latencies. The -32-15 kernel can
>> be downloaded from the usual place:
>>
>> http://redhat.com/~mingo/realtime-preempt/
>>
>>other changes in -32-15: more work on the tracer, cleaner trace
>> output and the tracing of syscall entries and returns, with
>> arguments and return values displayed as well (i.e. a simple
>> strace variant). Here is how a syscall now looks like in
>> /proc/latency_trace:
>>
>> loop-tes-3885  0....  100µs > sys_getppid (002fcffc 00000001
>> 0000007b) loop-tes-3885  0....  101µs+: sys_getppid
>> (sysenter_past_esp) loop-tes-3885  0d...  103µs < (3868)
>>
>>'< (return-val)' is the syscall return value, '> sys_name(params)'
>> is the syscall itself. (note that the return path is also used by
>> interrupts, so it's not purely a syscall-return point) This makes
>> it easier to track userspace execution.
>>
>> Ingo
>>-
>>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/

-- 
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.30% 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: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Gene Heskett]

On Friday 10 December 2004 05:53, Ingo Molnar wrote:
>* Ingo Molnar <mingo@elte.hu> wrote:
>> this smells too. [...]

Humm, something else does too Ingo.  Amanda failed on this
machine last night, and so did an amcheck just now, returning this:

[amanda@coyote driver]$ amcheck Daily
Amanda Tape Server Host Check
-----------------------------
Holding disk /dumps: 26444 MB disk space available, using 25944 MB
amcheck-server: slot 8: date 20041210 label Dailys-8 (active tape)
amcheck-server: slot 9: date 20041124 label Dailys-9 (exact label
match)
NOTE: skipping tape-writable test
Tape Dailys-9 label ok
Server check took 0.386 seconds

Amanda Backup Client Hosts Check
--------------------------------
WARNING: coyote: selfcheck reply timed out.
Client check: 2 hosts checked in 22.199 seconds, 1 problem found

(brought to you by Amanda 2.4.5b1-20041122)
------------------
This was while running 32-12, which otherwise feels good and gave
me no other indication of a problem.  I've also looked at the log,
but its silent on this subject.  I'll get the latest and try it.

>found two brown-paperbag bugs that caused bad latencies in the -RT
>kernel: when i added PREEMPT_DIRECT (which first showed up in
> -32-10) i also added a missed-reschedule bug to try_to_wake_up()
> and to mutex/semaphore-unlock (__up()). Oops.
>
>i dont think this bug could explain a msec-range latency because the
>syscall return path should catch the missed reschedule and it would
> need continuous syscall execution in the milliseconds range by a
> lowprio task for a latency to be transported to latencytest, but
> certainly the bug doesnt help latencies. The -32-15 kernel can be
> downloaded from the usual place:
>
> http://redhat.com/~mingo/realtime-preempt/
>
>other changes in -32-15: more work on the tracer, cleaner trace
> output and the tracing of syscall entries and returns, with
> arguments and return values displayed as well (i.e. a simple strace
> variant). Here is how a syscall now looks like in
> /proc/latency_trace:
>
> loop-tes-3885  0....  100µs > sys_getppid (002fcffc 00000001
> 0000007b) loop-tes-3885  0....  101µs+: sys_getppid
> (sysenter_past_esp) loop-tes-3885  0d...  103µs < (3868)
>
>'< (return-val)' is the syscall return value, '> sys_name(params)'
> is the syscall itself. (note that the return path is also used by
> interrupts, so it's not purely a syscall-return point) This makes
> it easier to track userspace execution.
>
>	Ingo
>-
>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/

-- 
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.30% 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.

[patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15

[Ingo Molnar]

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

> this smells too. [...]

found two brown-paperbag bugs that caused bad latencies in the -RT
kernel: when i added PREEMPT_DIRECT (which first showed up in -32-10) i
also added a missed-reschedule bug to try_to_wake_up() and to
mutex/semaphore-unlock (__up()). Oops.

i dont think this bug could explain a msec-range latency because the
syscall return path should catch the missed reschedule and it would need
continuous syscall execution in the milliseconds range by a lowprio task
for a latency to be transported to latencytest, but certainly the bug
doesnt help latencies. The -32-15 kernel can be downloaded from the
usual place:

 http://redhat.com/~mingo/realtime-preempt/

other changes in -32-15: more work on the tracer, cleaner trace output
and the tracing of syscall entries and returns, with arguments and
return values displayed as well (i.e. a simple strace variant). Here is
how a syscall now looks like in /proc/latency_trace:

 loop-tes-3885  0....  100µs > sys_getppid (002fcffc 00000001 0000007b)
 loop-tes-3885  0....  101µs+: sys_getppid (sysenter_past_esp)
 loop-tes-3885  0d...  103µs < (3868)

'< (return-val)' is the syscall return value, '> sys_name(params)' is
the syscall itself. (note that the return path is also used by
interrupts, so it's not purely a syscall-return point) This makes it
easier to track userspace execution.

	Ingo