linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
From: Mark_H_Johnson@raytheon.com
To: Ingo Molnar <mingo@elte.hu>
Cc: Mark_H_Johnson@raytheon.com, Amit Shah <amit.shah@codito.com>,
	Karsten Wiese <annabellesgarden@yahoo.de>,
	Bill Huey <bhuey@lnxw.com>, Adam Heath <doogie@debian.org>,
	emann@mrv.com, Gunther Persoons <gunther_persoons@spymac.com>,
	"K.R. Foley" <kr@cybsft.com>,
	linux-kernel@vger.kernel.org,
	Florian Schmidt <mista.tapas@gmx.net>,
	Fernando Pablo Lopez-Lezcano <nando@ccrma.Stanford.EDU>,
	Lee Revell <rlrevell@joe-job.com>,
	Rui Nuno Capela <rncbc@rncbc.org>,
	Shane Shrybman <shrybman@aei.ca>,
	Esben Nielsen <simlo@phys.au.dk>,
	Thomas Gleixner <tglx@linutronix.de>,
	Michal Schmidt <xschmi00@stud.feec.vutbr.cz>
Subject: Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15
Date: Fri, 10 Dec 2004 14:03:44 -0600	[thread overview]
Message-ID: <OF27B09B8B.40A67C86-ON86256F66.006E33A8-86256F66.006E34B3@raytheon.com> (raw)

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


             reply	other threads:[~2004-12-10 20:06 UTC|newest]

Thread overview: 29+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2004-12-10 20:03 Mark_H_Johnson [this message]
  -- strict thread matches above, loose matches on Subject: below --
2004-12-13 23:14 [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15 Mark_H_Johnson
2004-12-13 20:02 Mark_H_Johnson
2004-12-13 22:39 ` Ingo Molnar
2004-12-13 17:05 Mark_H_Johnson
2004-12-13 22:33 ` Ingo Molnar
2004-12-10 22:06 Mark_H_Johnson
2004-12-10 22:24 ` Ingo Molnar
2004-12-10 21:58 Mark_H_Johnson
2004-12-10 21:54 Mark_H_Johnson
2004-12-10 22:14 ` Ingo Molnar
2004-12-10 21:31 Mark_H_Johnson
2004-12-10 21:54 ` Ingo Molnar
2004-12-10 21:06 Mark_H_Johnson
2004-12-10 21:40 ` Ingo Molnar
2004-12-10 17:49 Mark_H_Johnson
2004-12-10 21:09 ` Ingo Molnar
2004-12-10 21:12 ` Ingo Molnar
2004-12-10 21:24 ` Ingo Molnar
2004-12-13  0:16 ` Fernando Lopez-Lezcano
2004-12-13  6:47   ` Ingo Molnar
2004-12-14  0:46     ` Fernando Lopez-Lezcano
2004-12-14  4:42       ` K.R. Foley
2004-12-14  8:47         ` Rui Nuno Capela
2004-12-14 11:35           ` Ingo Molnar
2004-12-09 21:58 [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-6 Mark_H_Johnson
2004-12-09 22:55 ` Ingo Molnar
2004-12-10 10:53   ` [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.32-15 Ingo Molnar
2004-12-10 14:59     ` Gene Heskett
2004-12-10 15:59       ` Gene Heskett
2004-12-10 19:09     ` Lee Revell

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=OF27B09B8B.40A67C86-ON86256F66.006E33A8-86256F66.006E34B3@raytheon.com \
    --to=mark_h_johnson@raytheon.com \
    --cc=amit.shah@codito.com \
    --cc=annabellesgarden@yahoo.de \
    --cc=bhuey@lnxw.com \
    --cc=doogie@debian.org \
    --cc=emann@mrv.com \
    --cc=gunther_persoons@spymac.com \
    --cc=kr@cybsft.com \
    --cc=linux-kernel@vger.kernel.org \
    --cc=mingo@elte.hu \
    --cc=mista.tapas@gmx.net \
    --cc=nando@ccrma.Stanford.EDU \
    --cc=rlrevell@joe-job.com \
    --cc=rncbc@rncbc.org \
    --cc=shrybman@aei.ca \
    --cc=simlo@phys.au.dk \
    --cc=tglx@linutronix.de \
    --cc=xschmi00@stud.feec.vutbr.cz \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body. 
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).