Messages in this thread | | | Date | Mon, 12 Nov 2012 16:09:26 -0800 | From | John Stultz <> | Subject | Re: getnstimeofday stuck for several milliseconds? |
| |
On 11/12/2012 03:53 PM, John Stultz wrote: > On 11/05/2012 12:51 AM, David Henningsson wrote: >> Hi LKML, >> >> I'm trying to make audio more useful in everyday low-latency >> scenarios such as gaming or VOIP. >> >> While doing so, I ran the wakeup_rt tracer, to track the time from >> PulseAudio requesting wakeup (through hrtimers), to the thread >> actually running. >> >> I'm not sure how much overhead added by the wakeup_rt tracer itself, >> but I got 9 ms on one machine and 20 ms on another, which I consider >> to be quite a lot even for a standard kernel (i e without RT or other >> special configuration). >> >> The 9 ms example is pastebinned at [1], and here's where we get stuck >> for most of the time: >> >> <idle>-0 3d... 1105us : ktime_get_real <-intel_idle >> <idle>-0 3d... 1106us!: getnstimeofday <-ktime_get_real >> <idle>-0 3d... 7823us : ktime_get_real <-intel_idle >> >> <idle>-0 3d... 7890us : ktime_get_real <-intel_idle >> <idle>-0 3d... 7891us!: getnstimeofday <-ktime_get_real >> <idle>-0 3d... 9023us : ktime_get_real <-intel_idle >> > > Looking at the trace you posted here: http://pastebin.se/6iMRdDfR > > The trace also looks like its the cpuidle to interrupt transition > where you're seeing this. I sort of wonder if its mis-attributing the > idle time to the getnstimeofday()? Mainly because you don't seem to > spend much time in intel_idle() otherwise. > > Or maybe we're both misreading it and its saying there's a delay > between the first ktime_get_real() from intel_idle() to the second > call of ktime_get_real(), between which we're in deep idle (which > would make sense)? > The more I think about it, I'm pretty sure this is the case: The full context you need is: <idle>-0 3d... 7890us : ktime_get_real <-intel_idle <idle>-0 3d... 7891us!: getnstimeofday <-ktime_get_real <idle>-0 3d... 9023us : ktime_get_real <-intel_idle <idle>-0 3d... 9024us : getnstimeofday <-ktime_get_real
Where intel_idle() is calling ktime_get_real twice in a row, and inbetween we see a large latency. Looking at intel_idle() the code in question is:
kt_before = ktime_get_real();
stop_critical_timings(); if (!need_resched()) {
__monitor((void *)¤t_thread_info()->flags, 0, 0); smp_mb(); if (!need_resched()) __mwait(eax, ecx); }
start_critical_timings();
kt_after = ktime_get_real();
Where we're basically timing how long we were in idle for.
So I think the problem is just misreading the trace output.
thanks -john
| |