timerfd waking up before timer really expires

timerfd waking up before timer really expires

[Lucas De Marchi]

Hi,

I was debugging my application and noticed that a timerfd event was being
triggered *before* the timer expires. I'd like to know if this behavior is
expected. More details below.


I reduced the scope of the program to test a single timerfd and measure the
difference in the result of clock_gettime() between two reads. Helper functions
are elsewhere, but the loop is very simple:

    loop_time_fd = setup_timerfd(interval, 0);
    iter = 0;
    old = curr = now_usec();
    do {
            if (iter > iterations)
                    break;

            r = read(loop_time_fd, &events, sizeof(events));
            if (r < 0) {
                    if (errno == EINTR)
                            continue;
                    return log_error_errno(errno, "Error reading timerfd: %m");
            }

            curr = now_usec();

            /* mark as USEC_INFINITY those events we missed, the real wait
             * time is nonetheless in the next position */
            for (; events > 1; events--)
                    elapsed[iter++] = USEC_INFINITY;

            elapsed[iter++] = curr - old;
            old = curr;
    } while (1);


Here we have:
  - now_usec() simply calls clock_gettime() with CLOCK_MONOTONIC as clockid and
    converts to usec.
  - setup_timerfd() creates the timerfd with CLOCK_MONOTONIC and let it
    in blocking mode  (there's another version of the test with poll()
and non-block fd,
    but it shows the same behavior)

First I thought it could be because of the timerslack. I disabled it with
prctl(). I'm also running the process with RT priority so AFAIK there shouldn't
be a problem with timerslack. In order to reduce the overhead for the process I
also tried to isolate it alone on a single cpu by booting with isolcpus and
then setting the affinity accordingly.

For whatever interval I configure and 10000 iterations, what I'm seeing in the
elapsed vector are values like

    interval +- 70usec

Due to the wakeup overhead, I understand the +70usec, but I'm not getting why
there are elapsed values shorter than the configured interval.

Tracing for wakeup events with ftrace[1] I also get the same results... the time
difference between 2 wakeup events for ~30% of events are shorter the
configured interval.

I'm currently running with kernel version 3.18.6. Is there anything I'm
missing?

thanks

-- 
Lucas De Marchi

[1] trace-cmd record -F -e sched:sched_wakeup ./test-timer 1000 10000

Re: timerfd waking up before timer really expires

[Clemens Ladisch]

Lucas De Marchi wrote:
> I was debugging my application and noticed that a timerfd event was being
> triggered *before* the timer expires.
>
> I reduced the scope of the program to test a single timerfd and measure the
> difference in the result of clock_gettime() between two reads.
>
>     loop_time_fd = setup_timerfd(interval, 0);
>     do {
>             read(loop_time_fd, &events, sizeof(events));
>             ... = now_usec();
>     } while (1);
>
> For whatever interval I configure and 10000 iterations, what I'm seeing in the
> elapsed vector are values like
>
>     interval +- 70usec

Let us assume that the timer itself is perfectly accurate, and that all
wakeups of your program are immediately when the timerfd becomes ready,
except for one iteration, where there is a scheduling delay.  Then the
measured interval before this delayed wakeup is longer, while the
measured interval after this wakeup is shorter by the same amount.

To detect early wakeups, you must not check whether the interval between
two consecutive wakeups is too short, but whether the interval between
a wakeup and the time when the timerfd was actually started is shorter
than N × the timer interval.


Regards,
Clemens

Re: timerfd waking up before timer really expires

[Lucas De Marchi]

On Wed, Mar 4, 2015 at 5:06 AM, Clemens Ladisch <clemens@ladisch.de> wrote:
> Lucas De Marchi wrote:
>> I was debugging my application and noticed that a timerfd event was being
>> triggered *before* the timer expires.
>>
>> I reduced the scope of the program to test a single timerfd and measure the
>> difference in the result of clock_gettime() between two reads.
>>
>>     loop_time_fd = setup_timerfd(interval, 0);
>>     do {
>>             read(loop_time_fd, &events, sizeof(events));
>>             ... = now_usec();
>>     } while (1);
>>
>> For whatever interval I configure and 10000 iterations, what I'm seeing in the
>> elapsed vector are values like
>>
>>     interval +- 70usec
>
> Let us assume that the timer itself is perfectly accurate, and that all
> wakeups of your program are immediately when the timerfd becomes ready,
> except for one iteration, where there is a scheduling delay.  Then the
> measured interval before this delayed wakeup is longer, while the
> measured interval after this wakeup is shorter by the same amount.
>
> To detect early wakeups, you must not check whether the interval between
> two consecutive wakeups is too short, but whether the interval between
> a wakeup and the time when the timerfd was actually started is shorter
> than N × the timer interval.

oohh, /me blushes...

That makes perfect sense since I'm not re-arming the timer for another
period and instead timerfd is doing it for me. If fixed it in my code
and then for 10k iterations and an interval of 1ms I have
(number-of-occurrences   time):
   9959 1000
      9 1001
     12 1002
      5 1003
      5 1004
      2 1005
      1 1009
      2 1010
      1 1012
      1 1016
      1 1018
      1 1024
      1 1027

None with < 1ms and max latency of 27us.

Thanks

-- 
Lucas De Marchi