Re: getnstimeofday stuck for several milliseconds?

[John Stultz <johnstul@us.ibm.com>]

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
>
Its been awhile since I looked at wakeup_rt trace output, but that looks 
more like ~6.7ms and ~1.2ms latencies, not 9ms (are you adding these 
together?).

> It seems to me that sometimes we get stuck for several milliseconds 
> inside the getnstimeofday function - this was seen on both the 9 ms 
> and the 20 ms trace. This looks like a bug to me, and as I'm not sure 
> on how to best debug it further, and therefore I'm asking for help (or 
> a bug fix!) here.
>
> For reference, the 9 ms trace was from a ~2 year old laptop (core i3 
> cpu) running 3.7rc2 vanilla/mainline kernel, and the 20 ms trace was 
> from an ~1 year old Atom-based machine running the 3.2-ubuntu kernel. 
> While tracing was enabled, I was running a libSDL game for a minute or 
> two.
>
> Thanks in advance for looking into this, and let me know if you need 
> further information, or anything else I can do to help sorting this 
> one out.

Hrmm.. So 6.7ms is still a long time.

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)?

Because unless the timekeeping lock is getting held for a long time, I 
don't know why else you'd see such long delays at getnstimeofday().

Cc'ing Steven to see if he can't help understand whats going on here.

thanks
-john