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

[Ingo Molnar <mingo@elte.hu>]

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

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

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

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

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

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

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

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

it would be:

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

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

	Ingo

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