Re: jack, PREEMPT_DESKTOP, delayed interrupts?

[Ingo Molnar <mingo@elte.hu>]

* 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) {