lkml.org 
[lkml]   [2004]   [Sep]   [1]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [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/

\
 
 \ /
  Last update: 2005-03-22 14:05    [W:0.054 / U:1.048 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site