jack, PREEMPT_DESKTOP, delayed interrupts?

jack, PREEMPT_DESKTOP, delayed interrupts?

[Fernando Lopez-Lezcano]

Hi, I'm starting to look at a strange problem. The configuration is:
hardware: AMD X2 4400+ dual core, NForce3 chipset, Midiman 66 soundcard
software: 2.6.13 smp + patch-2.6.13-rt1, PREEMPT_DESKTOP
          jack 0.100.4, current cvs
          alsa 1.0.10rc1

This is the sequence of events. Start Jack inside Qjackctl (a Jack Audio
Connection Kit GUI front end) with 2 x 128 frames, start Ardour (a
digital audio workstation) - load a very simple recording session, start
Hydrogen (a drum machine). Play around with them, everything seems to
work fine. No glitches, very solid performance. 

Do a "tar cvf usr.tar /usr" just to read/write a lot to disk (this
within the same SATA disk). Watch memory being used in a system monitor
applet up to 100%. After a while, hard to say how long (maybe 10/15
minutes?) the system eventually can get into a state where Jack starts
printing messages of the type "delay of 3856.000 usecs exceeds estimated
spare time of 2653.000; restart ..." (if I understand correctly this
means interrupts are being delayed on their way to Jack, or at least
Jack thinks they are arriving too late), along with some less frequent
xun notices. 

Now the strange thing is that this condition seems to be persistent.
Nothing I do after it starts to happen seems to halt those messages.
Including stopping Jack and starting it again, and even (tried it once)
stopping the alsa sound driver and loading it again. Nothing out of the
ordinary in dmesg or /var/log/messages. I would guess that something
"breaks" inside the kernel with regards to interrupt handling and/or
whatever Jack uses to measure time inside the kernel? Interrupts are
prioritized correctly (rtc, then audio and jack runs at lower realtime
priority than the audio interrupts), everything else looks fine. 

I could not get this to happen while running a uniprocessor kernel on
the same machine but I may not have tried long enough. I do see a "delay
exceeds" or "xun" message every once in a while but not a steady,
unstoppable stream of them. 

This seemed to be much worse, or easier to trigger, when running an
older realtime-preempt-2.6.12-final-V0.7.51-27 smp kernel. 

I don't know what information may be useful to even start making some
sense out of this. 

-- Fernando

Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Lee Revell]

On Tue, 2005-08-30 at 19:03 -0700, Fernando Lopez-Lezcano wrote:
> Hi, I'm starting to look at a strange problem. The configuration is:
> hardware: AMD X2 4400+ dual core, NForce3 chipset, Midiman 66 soundcard
> software: 2.6.13 smp + patch-2.6.13-rt1, PREEMPT_DESKTOP
>           jack 0.100.4, current cvs
>           alsa 1.0.10rc1
> 

Enable all latency debug options and post the contents
of /proc/latency_trace when this happens.  Also what file system are you
using?  And is the SMT scheduler enabled?

Lee

Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Fernando Lopez-Lezcano]

On Tue, 2005-08-30 at 19:39, Lee Revell wrote:
> On Tue, 2005-08-30 at 19:03 -0700, Fernando Lopez-Lezcano wrote:
> > Hi, I'm starting to look at a strange problem. The configuration is:
> > hardware: AMD X2 4400+ dual core, NForce3 chipset, Midiman 66 soundcard
> > software: 2.6.13 smp + patch-2.6.13-rt1, PREEMPT_DESKTOP
> >           jack 0.100.4, current cvs
> >           alsa 1.0.10rc1
> > 
> 
> Enable all latency debug options and post the contents
> of /proc/latency_trace when this happens. 

Will try to, I'm about to go on a trip so that may have to wait. 

> Also what file system are you using? 

Ext3, Jack mounts its pipes and stuff in /dev/shm

>  And is the SMT scheduler enabled?

Is this it?: CONFIG_SCHED_SMT=y

-- Fernando

Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Ingo Molnar]

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

> Do a "tar cvf usr.tar /usr" just to read/write a lot to disk (this 
> within the same SATA disk). Watch memory being used in a system 
> monitor applet up to 100%. After a while, hard to say how long (maybe 
> 10/15 minutes?) the system eventually can get into a state where Jack 
> starts printing messages of the type "delay of 3856.000 usecs exceeds 
> estimated spare time of 2653.000; restart ..." (if I understand 
> correctly this means interrupts are being delayed on their way to 
> Jack, or at least Jack thinks they are arriving too late), along with 
> some less frequent xun notices.
> 
> Now the strange thing is that this condition seems to be persistent.  
> Nothing I do after it starts to happen seems to halt those messages.  
> Including stopping Jack and starting it again, and even (tried it 
> once) stopping the alsa sound driver and loading it again. Nothing out 
> of the ordinary in dmesg or /var/log/messages. I would guess that 
> something "breaks" inside the kernel with regards to interrupt 
> handling and/or whatever Jack uses to measure time inside the kernel?  
> Interrupts are prioritized correctly (rtc, then audio and jack runs at 
> lower realtime priority than the audio interrupts), everything else 
> looks fine.

are the messages unstoppable, even if the system is completely idle? And 
you get this only with the SMP kernel, correct?

i dont know what's going on, but here are a couple of ideas to debug 
this further:

- could you check whether there are any SCHED_FIFO tasks that shouldnt 
  be there:

    ps -meo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:14,comm | grep FF

  we had bugs in the past that caused RT priorities to 'leak' on SMP 
  systems.

- please enable all latency tracing options like Lee suggested, and do 
  "echo 0 > /proc/sys/kernel/preempt_max_latency" to get some traces. 

- if everything fails and automatic latency tracing does not show 
  anything out of ordinary, then you could try to do "user-triggered 
  tracing" of jackd's critical path. This is more laborous to do, but
  should pinpoint the latency reason in a pretty sure way.

  user-triggered tracing is done via adding those special gettimeofday 
  calls to jackd and recompiling jackd. I've attached an older hack
  against jackd below, you might need to merge it to recent jackd. NOTE: 
  this patch will only work if you are getting xrun messages from ALSA.  
  It has to be reworked if your latencies are not actual xruns.

  then, once the patched jackd is running, you can enable user-triggered
  tracing via:

	echo 1 > /proc/sys/kernel/trace_user_triggered

  then you should start seeing jackd's latency path measured, not the
  kernel's internal critical sections. [ Tracing overhead tip: for
  user-triggered tracing it is enough to have CONFIG_WAKEUP_TIMING and 
  CONFIG_LATENCY_TRACE enabled, the other debugging options can be 
  turned off, to minimize overhead. ]

	Ingo

diff -dupPNr jackit.0/drivers/alsa/alsa_driver.c jackit.1/drivers/alsa/alsa_driver.c
--- jackit.0/drivers/alsa/alsa_driver.c	2004-11-26 17:24:24.000000000 +0000
+++ jackit.1/drivers/alsa/alsa_driver.c	2004-11-30 13:41:24.521791456 +0000
@@ -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,12 @@ alsa_driver_wait (alsa_driver_t *driver,
 			nfds++;
 		}
 
+		{	// Trigger off trace every other poll...
+			static unsigned int xruntrace_count = 0;
+			if ((xruntrace_count++ % 1) == 0)
+				gettimeofday(0,1);
+		}
+  
 		poll_enter = jack_get_microseconds ();
 
 		if (poll_enter > driver->poll_next) {

Re: [Jackit-devel] Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Jack O'Quin]

Ingo Molnar <mingo@elte.hu> writes:

> - if everything fails and automatic latency tracing does not show 
>   anything out of ordinary, then you could try to do "user-triggered 
>   tracing" of jackd's critical path. This is more laborous to do, but
>   should pinpoint the latency reason in a pretty sure way.
>
>   user-triggered tracing is done via adding those special gettimeofday 
>   calls to jackd and recompiling jackd. I've attached an older hack
>   against jackd below, you might need to merge it to recent jackd. NOTE: 
>   this patch will only work if you are getting xrun messages from ALSA.  
>   It has to be reworked if your latencies are not actual xruns.

JACK sources already include a CHECK_PREEMPTION() macro which expands
to Ingo's special gettimeofday() calls.  The trace is turned on and
then off automatically before and after the realtime critical section
in the process thread (see libjack/client.c).  

Ingo's suggested ALSA backend patch is not presently included.

There are probably some other places where these macros could usefully
be added.  We will integrate patches adding them in appropriate spots.
They do no harm in vanilla kernels without tracing enabled.

-- 
  joq

Re: [Jackit-devel] Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Florian Schmidt]

On Wed, 31 Aug 2005 07:08:08 -0500
"Jack O'Quin" <joq@io.com> wrote:

> JACK sources already include a CHECK_PREEMPTION() macro which expands
> to Ingo's special gettimeofday() calls.  The trace is turned on and
> then off automatically before and after the realtime critical section
> in the process thread (see libjack/client.c).  

Just for completeness sake:

you need to build jackd with --enable-preemption-check

Flo


-- 
Palimm Palimm!
http://tapas.affenbande.org

Re: [Jackit-devel] Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Ingo Molnar]

* Florian Schmidt <mista.tapas@gmx.net> wrote:

> > JACK sources already include a CHECK_PREEMPTION() macro which expands
> > to Ingo's special gettimeofday() calls.  The trace is turned on and
> > then off automatically before and after the realtime critical section
> > in the process thread (see libjack/client.c).  
> 
> Just for completeness sake:
> 
> you need to build jackd with --enable-preemption-check

this is another feature, unrelated to latency tracing. So (an adapted 
version of) the latency-tracing patch i sent should still be tried.

--enable-preemption-check does the 'send SIGUSR2 if jackd gets scheduled 
unexpectedly'. That might unearth latencies, but it does not by itself 
measure latencies. Right now we are more interested in the latencies 
themselves.

i suspect the confusion comes from the API hacks i'm using: user-space 
tracing is started/stopped via:

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

while 'jackd does not want to be scheduled' flag is switched on/off via:

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

(introducing extra syscalls for this is an overkill.)

	Ingo

Re: [Jackit-devel] Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Jack O'Quin]

Ingo Molnar <mingo@elte.hu> writes:

> i suspect the confusion comes from the API hacks i'm using: user-space 
> tracing is started/stopped via:
>
> 	gettimeofday(0,1);
> 	gettimeofday(0,0);
>
> while 'jackd does not want to be scheduled' flag is switched on/off via:
>
> 	gettimeofday(1,1);
> 	gettimeofday(1,0);

D'oh!  No wonder I was confused.

Sorry to have mixed up the conversation with erroneous information,
but glad to have the gettimeofday() API clarified.
-- 
  joq

Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Fernando Lopez-Lezcano]

On Wed, 2005-08-31 at 00:35, Ingo Molnar wrote:
> * Fernando Lopez-Lezcano <nando@ccrma.Stanford.EDU> wrote:
> 
> > Do a "tar cvf usr.tar /usr" just to read/write a lot to disk (this 
> > within the same SATA disk). Watch memory being used in a system 
> > monitor applet up to 100%. After a while, hard to say how long (maybe 
> > 10/15 minutes?) the system eventually can get into a state where Jack 
> > starts printing messages of the type "delay of 3856.000 usecs exceeds 
> > estimated spare time of 2653.000; restart ..." (if I understand 
> > correctly this means interrupts are being delayed on their way to 
> > Jack, or at least Jack thinks they are arriving too late), along with 
> > some less frequent xun notices.
> > 
> > Now the strange thing is that this condition seems to be persistent.  
> > Nothing I do after it starts to happen seems to halt those messages.  
> > Including stopping Jack and starting it again, and even (tried it 
> > once) stopping the alsa sound driver and loading it again. Nothing out 
> > of the ordinary in dmesg or /var/log/messages. I would guess that 
> > something "breaks" inside the kernel with regards to interrupt 
> > handling and/or whatever Jack uses to measure time inside the kernel?  
> > Interrupts are prioritized correctly (rtc, then audio and jack runs at 
> > lower realtime priority than the audio interrupts), everything else 
> > looks fine.
> 
> are the messages unstoppable, even if the system is completely idle? And 
> you get this only with the SMP kernel, correct?

That's correct. I have to try harder with a UP kernel but I'm short on
time. I should see how idle I can get the system (ie: logout, start
stopping processes), but quitting jack and all related apps and/or
restarting alsa does not fix the problem. Top does not show anything
strange in terms of cpu usage.

> i dont know what's going on, but here are a couple of ideas to debug 
> this further:
> 
> - could you check whether there are any SCHED_FIFO tasks that shouldnt 
>   be there:
> 
>     ps -meo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:14,comm | grep FF

Seems to be fine (I'm doing this remotely so I can't look at the screen
to see if jack is still spewing messages):

    -     2 FF      99   - 139   0  0.0 S    migration_thre -
    -     3 FF       1   -  41   0  0.0 S    ksoftirqd      -
    -     4 FF       1   -  41   0  0.0 S    ksoftirqd      -
    -     5 FF       1   -  41   0  0.0 S    ksoftirqd      -
    -     6 FF       1   -  41   0  0.0 S    ksoftirqd      -
    -     7 FF       1   -  41   0  0.0 S    ksoftirqd      -
    -     8 FF       1   -  41   0  0.0 S    ksoftirqd      -
    -    10 FF      99   - 139   0  0.0 S    watchdog       -
    -    11 FF      99   - 139   1  0.0 S    migration_thre -
    -    12 FF       1   -  41   1  0.0 S    ksoftirqd      -
    -    13 FF       1   -  41   1  0.0 S    ksoftirqd      -
    -    14 FF       1   -  41   1  0.0 S    ksoftirqd      -
    -    15 FF       1   -  41   1  0.0 S    ksoftirqd      -
    -    16 FF       1   -  41   1  0.0 S    ksoftirqd      -
    -    17 FF       1   -  41   1  0.0 S    ksoftirqd      -
    -    19 FF      99   - 139   1  0.0 S    watchdog       -
    -    20 FF       1   -  41   0  0.0 S<   worker_thread  -
    -    21 FF       1   -  41   1  0.0 S<   worker_thread  -
    -    27 FF      49   -  89   0  0.0 S<   irqd           -
    -   295 FF      80   - 120   0  0.0 S<   irqd           -
    -   313 FF      49   -  89   0  0.0 S<   irqd           -
    -   346 FF      46   -  86   0  0.0 S<   irqd           -
    -   378 FF      50   -  90   0  0.0 S<   irqd           -
    -   408 FF      44   -  84   0  0.0 S<   irqd           -
    -   421 FF      60   - 100   0  0.0 S<   irqd           -
    -   923 FF      42   -  82   0  0.0 S<   irqd           -
    -   947 FF      41   -  81   0  0.0 S<   irqd           -
the next line is the soundcard interrupt:
    -  1033 FF      70   - 110   0  0.0 S<   irqd           -
    -  1046 FF      69   - 109   0  0.0 S<   irqd           -
    -  1205 FF      59   -  99   0  0.0 S<   irqd           -
    -  3946 FF      37   -  77   0  0.0 S<   irqd           -
    -  3947 FF      36   -  76   0  0.0 S<   irqd           -
    -  3972 FF      35   -  75   0  0.0 S<   irqd           -
    -  4434 FF      34   -  74   0  0.0 S<   irqd           -
These guys should be jackd (no clients are running):
    -  4674 FF      61   - 101   1  0.2 SLl  -              -
    -  4671 FF      72   - 112   1  0.0 SLsl -              -
    -  4672 FF      62   - 102   1  0.6 SLsl -              -

Interrupt lines:
# cat /proc/interrupts
           CPU0       CPU1
  0:     112487   51273672  IO-APIC-edge   [.........N/  0]  timer
  1:          1        638  IO-APIC-edge   [........../  0]  i8042
  7:          2          1  IO-APIC-edge   [..P......./  0]  parport0
  8:          0          1  IO-APIC-edge   [.........N/  0]  rtc
  9:          0          0  IO-APIC-level  [........../  0]  acpi
 12:        128      25211  IO-APIC-edge   [........../  0]  i8042
 14:       1271     459434  IO-APIC-edge   [........../  0]  ide0
177:          0          0  IO-APIC-level  [........../  0]  libata
185:       2613     701940  IO-APIC-level  [........../  0]  libata,
ehci_hcd:usb1
193:        609     174347  IO-APIC-level  [........../  0]  SysKonnect
SK-98xx
201:      25124   38426783  IO-APIC-level  [.........N/  0]  ICE1712,
ohci1394
209:          0          0  IO-APIC-level  [.........N/  0]  NVidia
CK8S, ohci_hcd:usb2
217:          0          0  IO-APIC-level  [........../  0] 
ohci_hcd:usb3
225:      11191    3327675  IO-APIC-level  [........../  0] 
radeon@pci:0000:01:00.0
NMI:          0          0
LOC:   51386600   51386544
ERR:          1
MIS:          0

Thanks for all the debugging tips!!
I'll see what I can do today. 
-- Fernando

Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Fernando Lopez-Lezcano]

On Wed, 2005-08-31 at 09:35 +0200, Ingo Molnar wrote:
> * Fernando Lopez-Lezcano <nando@ccrma.Stanford.EDU> wrote:
> > Do a "tar cvf usr.tar /usr" just to read/write a lot to disk (this 
> > within the same SATA disk). Watch memory being used in a system 
> > monitor applet up to 100%. After a while, hard to say how long (maybe 
> > 10/15 minutes?) the system eventually can get into a state where Jack 
> > starts printing messages of the type "delay of 3856.000 usecs exceeds 
> > estimated spare time of 2653.000; restart ..." (if I understand 
> > correctly this means interrupts are being delayed on their way to 
> > Jack, or at least Jack thinks they are arriving too late), along with 
> > some less frequent xun notices.
> > 
> > Now the strange thing is that this condition seems to be persistent.  
> > Nothing I do after it starts to happen seems to halt those messages.  
> > Including stopping Jack and starting it again, and even (tried it 
> > once) stopping the alsa sound driver and loading it again. Nothing out 
> > of the ordinary in dmesg or /var/log/messages. I would guess that 
> > something "breaks" inside the kernel with regards to interrupt 
> > handling and/or whatever Jack uses to measure time inside the kernel?  
> > Interrupts are prioritized correctly (rtc, then audio and jack runs at 
> > lower realtime priority than the audio interrupts), everything else 
> > looks fine.
> 
[MUNCH]
> - please enable all latency tracing options like Lee suggested, and do 
>   "echo 0 > /proc/sys/kernel/preempt_max_latency" to get some traces. 

I have done that, finally, but I'm not sure I'm clear on the sequence of
things I have to do, sorry. 

echo 0 > /proc/sys/kernel/preempt_max_latency
(zeroes the max latency, I guess). 

When should I look at /proc/latency_trace? What exactly does it show? (I
know it is nicely commented :-) Is it just one trace?

I'm including one sample output...
-- Fernando


# cat /proc/latency_trace
preemption latency trace v1.1.5 on 2.6.13-0.3.rdtd.rhfc4.ccrmasmp
--------------------------------------------------------------------
 latency: 10852 us, #70/70, CPU#0 | (M:preempt VP:0, KP:1, SP:1 HP:1
#P:2)
    -----------------
    | task: qjackctl-4797 (uid:743 nice:0 policy:1 rt_prio:61)
    -----------------

                 _------=> CPU#
                / _-----=> irqs-off
               | / _----=> need-resched
               || / _---=> hardirq/softirq
               ||| / _--=> preempt-depth
               |||| /
               |||||     delay
   cmd     pid ||||| time  |   caller
      \   /    |||||   \   |   /
   <...>-4593  1Dnh3    0us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3    0us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3    0us : MacUpdate (MacPrivateStat)
   <...>-4593  1Dnh3    0us : GetStatVal (MacPrivateStat)
   <...>-4593  1Dnh3    0us : GetPhysStatVal (GetStatVal)
   <...>-4593  1Dnh3    1us+: SkGmMacStatistic (GetPhysStatVal)
   <...>-4593  1Dnh3    3us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3    3us : MacUpdate (MacPrivateStat)
   <...>-4593  1Dnh3    3us : GetStatVal (MacPrivateStat)
   <...>-4593  1Dnh3    3us : GetPhysStatVal (GetStatVal)
   <...>-4593  1Dnh3    3us+: SkGmMacStatistic (GetPhysStatVal)
   <...>-4593  1Dnh3    5us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3    6us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3    6us : MacUpdate (MacPrivateStat)
   <...>-4593  1Dnh3    6us : GetStatVal (MacPrivateStat)
   <...>-4593  1Dnh3    6us : GetPhysStatVal (GetStatVal)
   <...>-4593  1Dnh3    6us+: SkGmMacStatistic (GetPhysStatVal)
   <...>-4593  1Dnh3    8us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3    9us : MacUpdate (MacPrivateStat)
   <...>-4593  1Dnh3    9us : GetStatVal (MacPrivateStat)
   <...>-4593  1Dnh3    9us : GetPhysStatVal (GetStatVal)
   <...>-4593  1Dnh3    9us+: SkGmMacStatistic (GetPhysStatVal)
   <...>-4593  1Dnh3   11us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3   11us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3   12us : MacUpdate (MacPrivateStat)
   <...>-4593  1Dnh3   12us : GetStatVal (MacPrivateStat)
   <...>-4593  1Dnh3   12us : GetPhysStatVal (GetStatVal)
   <...>-4593  1Dnh3   12us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3   12us : MacUpdate (MacPrivateStat)
   <...>-4593  1Dnh3   12us : GetStatVal (MacPrivateStat)
   <...>-4593  1Dnh3   13us : GetPhysStatVal (GetStatVal)
   <...>-4593  1Dnh3   13us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3   13us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3   13us : MacUpdate (MacPrivateStat)
   <...>-4593  1Dnh3   13us : GetStatVal (MacPrivateStat)
   <...>-4593  1Dnh3   13us : GetPhysStatVal (GetStatVal)
   <...>-4593  1Dnh3   13us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3   13us : MacUpdate (MacPrivateStat)
   <...>-4593  1Dnh3   13us : GetStatVal (MacPrivateStat)
   <...>-4593  1Dnh3   14us : GetPhysStatVal (GetStatVal)
   <...>-4593  1Dnh3   14us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3   14us : MacPrivateStat (SkPnmiGetStruct)
   <...>-4593  1Dnh3   14us : MacUpdate (MacPrivateStat)
   <...>-4593  1Dnh3   14us : GetStatVal (MacPrivateStat)
   <...>-4593  1Dnh3   14us : GetPhysStatVal (GetStatVal)
   <...>-4593  1Dnh3   14us+: SkGmMacStatistic (GetPhysStatVal)
   <...>-4593  1Dnh3   17us : GetStatVal (MacPrivateStat)
   <...>-4593  1Dnh3   18us : GetPhysStatVal (GetStatVal)
   <...>-4593  1Dnh3   18us : SkGmMacStatistic (GetPhysStatVal)
   <...>-4593  1Dnh3   20us : GetStatVal (MacPrivateStat)
   <...>-4593  1Dnh3   20us : GetPhysStatVal (GetStatVal)
   <...>-4593  1Dnh3   20us+: SkGmMacStatistic (GetPhysStatVal)
   <...>-4593  1Dnh3   22us : GetStatVal (MacPrivateStat)
   <...>-4593  1Dnh3   22us : GetPhysStatVal (GetStatVal)
   <...>-4593  1Dnh3   22us+: SkGmMacStatistic (GetPhysStatVal)
   <...>-4593  1Dnh3   24us!: MacPrivateStat (SkPnmiGetStruct)
softirq--8     0Dnh4 9901us : trace_change_sched_cpu (1 0 0)
softirq--8     0Dnh4 9901us : _raw_spin_unlock (trace_change_sched_cpu)
softirq--8     0Dnh3 9902us : enqueue_task (move_tasks)
softirq--8     0Dnh3 9902us : resched_task (move_tasks)
softirq--8     0Dnh3 9902us : _raw_spin_unlock (load_balance_newidle)
softirq--8     0Dnh2 9902us : preempt_schedule (_raw_spin_unlock)
   <...>-4797  0Dnh2 9903us : __switch_to (__schedule)
   <...>-4797  0Dnh2 9904us : __schedule <softirq--8> (62 26)
   <...>-4797  0Dnh2 9904us : _raw_spin_unlock_irq (__schedule)
   <...>-4797  0...1 9904us : trace_stop_sched_switched (__schedule)
   <...>-4797  0Dnh1 9905us : _raw_spin_lock (trace_stop_sched_switched)
   <...>-4797  0Dnh2 9905us : trace_stop_sched_switched <<...>-4797> (26
0)
   <...>-4797  0Dnh2 9905us : trace_stop_sched_switched (__schedule)

Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Karsten Wiese]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="us-ascii", Size: 1713 bytes --]

> # cat /proc/latency_trace
> preemption latency trace v1.1.5 on 2.6.13-0.3.rdtd.rhfc4.ccrmasmp
> --------------------------------------------------------------------
>  latency: 10852 us, #70/70, CPU#0 | (M:preempt VP:0, KP:1, SP:1 HP:1
> #P:2)
>     -----------------
>     | task: qjackctl-4797 (uid:743 nice:0 policy:1 rt_prio:61)
>     -----------------
> 
>                  _------=> CPU#
>                 / _-----=> irqs-off
>                | / _----=> need-resched
>                || / _---=> hardirq/softirq
>                ||| / _--=> preempt-depth
>                |||| /
>                |||||     delay
>    cmd     pid ||||| time  |   caller
>       \   /    |||||   \   |   /
>    <...>-4593  1Dnh3    0us : MacPrivateStat (SkPnmiGetStruct)
>    <...>-4593  1Dnh3    0us : MacPrivateStat (SkPnmiGetStruct)
<snip>
>    <...>-4593  1Dnh3   18us : SkGmMacStatistic (GetPhysStatVal)
>    <...>-4593  1Dnh3   20us : GetStatVal (MacPrivateStat)
>    <...>-4593  1Dnh3   20us : GetPhysStatVal (GetStatVal)
>    <...>-4593  1Dnh3   20us+: SkGmMacStatistic (GetPhysStatVal)
>    <...>-4593  1Dnh3   22us : GetStatVal (MacPrivateStat)
>    <...>-4593  1Dnh3   22us : GetPhysStatVal (GetStatVal)
>    <...>-4593  1Dnh3   22us+: SkGmMacStatistic (GetPhysStatVal)
>    <...>-4593  1Dnh3   24us!: MacPrivateStat (SkPnmiGetStruct)
> softirq--8     0Dnh4 9901us : trace_change_sched_cpu (1 0 0)

Maybe your ethernet device is getting in the way.
Do you also get jack dropouts with ethernet chip disabled,
it's Module unloaded?

      Karsten

		
___________________________________________________________ 
Was denken Sie über E-Mail? Wir hören auf Ihre Meinung: http://surveylink.yahoo.com/wix/p0379378.aspx

Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Ingo Molnar]

* Karsten Wiese <annabellesgarden@yahoo.de> wrote:

> >  latency: 10852 us, #70/70, CPU#0 | (M:preempt VP:0, KP:1, SP:1 HP:1

> > softirq--8     0Dnh4 9901us : trace_change_sched_cpu (1 0 0)
> 
> Maybe your ethernet device is getting in the way.
> Do you also get jack dropouts with ethernet chip disabled,
> it's Module unloaded?

also, the M:preempt suggests that it's not a PREEMPT_RT kernel but a 
PREEMPT_DESKTOP kernel. Do the dropouts happen even with a PREEMPT_RT 
kernel?

	Ingo

Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Fernando Lopez-Lezcano]

On Wed, 2005-09-28 at 11:38 +0200, Ingo Molnar wrote:
> * Karsten Wiese <annabellesgarden@yahoo.de> wrote:
> 
> > >  latency: 10852 us, #70/70, CPU#0 | (M:preempt VP:0, KP:1, SP:1 HP:1
> 
> > > softirq--8     0Dnh4 9901us : trace_change_sched_cpu (1 0 0)
> > 
> > Maybe your ethernet device is getting in the way.
> > Do you also get jack dropouts with ethernet chip disabled,
> > it's Module unloaded?
> 
> also, the M:preempt suggests that it's not a PREEMPT_RT kernel but a 
> PREEMPT_DESKTOP kernel. Do the dropouts happen even with a PREEMPT_RT 
> kernel?

Last time I tried a PREEMPT_RT (not that long ago) I was not able to
boot into it, it was failing very very early in the boot sequence. I
could try again if it would be valuable. 

-- Fernando