Messages in this thread | | | Date | Wed, 1 Sep 2004 19:09:05 +0200 | From | Ingo Molnar <> | Subject | Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5 |
| |
* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:
> >since the latency tracer does not trigger, we need a modified tracer to > >find out what's happening during such long delays. I've attached the > >'user-latency-tracer' patch ontop of -Q5, which is a modification of the > >latency tracer. > > The attached file has a set of user latency traces taken about 1 second > apart at the start of running "latencytest" (a tracing version of it). > > The first few show the "fast path" result of calling write. The remaining > ones vary with three different symptoms: > - the fast path > - a "long" delay (about 1000 traces)
lt.03 shows this long delay. Here are the relevant sections, the delay seems to be triggered by the ALSA driver, by scheduling away intentionally, in snd_pcn_lib_write1():
00000002 0.023ms (+0.001ms): snd_pcm_update_hw_ptr (snd_pcm_lib_write1) 00000002 0.023ms (+0.000ms): snd_ensoniq_playback1_pointer (snd_pcm_update_hw_ptr) 00000002 0.025ms (+0.002ms): snd_pcm_playback_silence (snd_pcm_update_hw_ptr) 00000002 0.026ms (+0.000ms): add_wait_queue (snd_pcm_lib_write1) 00000000 0.027ms (+0.000ms): schedule_timeout (snd_pcm_lib_write1) 00000000 0.027ms (+0.000ms): __mod_timer (schedule_timeout)
then it sleeps 700 usecs and is woken up by the soundcard's IRQ via snd_pcm_period_elapsed():
00010000 0.771ms (+0.000ms): snd_audiopci_interrupt (generic_handle_IRQ_event) 00010000 0.774ms (+0.002ms): snd_pcm_period_elapsed (snd_audiopci_interrupt) 00010002 0.775ms (+0.001ms): snd_ensoniq_playback1_pointer (snd_pcm_period_elapsed) 00010002 0.779ms (+0.003ms): snd_pcm_playback_silence (snd_pcm_period_elapsed) 00010002 0.780ms (+0.001ms): __wake_up (snd_pcm_period_elapsed) 00010003 0.780ms (+0.000ms): __wake_up_common (__wake_up) 00010003 0.780ms (+0.000ms): default_wake_function (__wake_up_common) 00010003 0.781ms (+0.000ms): try_to_wake_up (__wake_up_common) 00010003 0.782ms (+0.000ms): task_rq_lock (try_to_wake_up) 00010004 0.783ms (+0.001ms): activate_task (try_to_wake_up)
and returns to userspace shortly afterwards. So the question is, why does snd_pcm_lib_write1() cause the latencytest task to sleep (while latencytest clearly doesnt expect this to happen and reports this as a latency) - is this by design?
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/
| |