lkml.org 
[lkml]   [2012]   [Nov]   [12]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: 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 *)&current_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






\
 
 \ /
  Last update: 2012-11-13 01:21    [W:0.067 / U:0.816 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site