Re: HRTimer causing rtctest to fail

[Felipe Balbi]

Thomas Gleixner <tglx@xxxxxxxxxxxxx> writes:

> On Wed, 28 Feb 2018, Felipe Balbi wrote:
>> Thomas Gleixner <tglx@xxxxxxxxxxxxx> writes:
>> > Enable the hrtimer and scheduling tracepoints. That should give you a hint
>> > what's going on.
>> 
>> Thanks, that does give me a lot more information. So here you go:
>> 
>>          rtctest-1348  [003] d..2   313.766141: hrtimer_start: hrtimer=00000000667ce595 function=rtc_pie_update_irq expires=313573983010 softexpires=313573983010 mode=REL
>>           <idle>-0     [003] d.h1   313.767189: hrtimer_expire_entry: hrtimer=00000000667ce595 function=rtc_pie_update_irq now=313574053764
>> 
>> We still have a 70754 nS deviation. After changing to absolute time,
>> the deviation remains:
>>
>>           <idle>-0     [000] dNh2    29.303251: hrtimer_start: hrtimer=000000006858b496 function=rtc_pie_update_irq expires=28765551360 softexpires=28765551360 mode=ABS
>>           <idle>-0     [000] d.h1    29.303565: hrtimer_expire_entry: hrtimer=000000006858b496 function=rtc_pie_update_irq now=28765621916
>
> Changing REL/ABS in the kernel does not make a difference because periodic
> mode just forwards by period so even if the first timer is started with REL
> it results in a absolute timeline. What I meant is the user space
> measurement as it cannot figure out when the first event was supposed to
> happen so it's hard to calculate latency information.
>
> The interesting information is that the timer fires late and the system is
> idle. Now the question is in which idle state did the machine go?
>
> Wake up from deeper C-states can be slow. On my laptop the wakeup latencies
> are:
>
> POLL	   0
> C1	   2
> C1E	  10
> C3	  33
> C6	 133
> C7S	 166
> C8	 300
> C9	 600
> C10	2600
>
> All numbers in micro seconds! What happens if you load the system or
> restrict C-States?

added intel_idle.max_cstate=0 to cmdline. Still see some failures,
albeit a lot more rare, for example, caught one on iteration 8 of
8192Hz:

8192Hz:	 1 2 3 4 5 6 7
PIE delta error: 0.000135 should be close to 0.000122

That is, however, only 13 uS late. Is that within the limits of "we
don't quite care"? BTW, it took some effort to get that one
failure. I'll leave rtctest running in a long loop and try to figure out
approximately how frequently it fails, but it seems like it's within the
realm of "don't care", would you agree?

cheers

-- 
balbi

Attachment: signature.asc
Description: PGP signature