timer - Reliability of Linux kernel add_timer at resolution of one jiffy?

Question

In the code given below, there is a simple Linux kernel module (driver) which calls a function repeatedly 10 times, using add_timer at resolution of 1 jiffy (that is, the timer is scheduled to fire at jiffies + 1). Using the bash script rerun.sh, then I obtain timestamps from printout in syslog, and visualize them using gnuplot.

In most cases, I get a syslog output like this:

[ 7103.055787] Init testjiffy: 0 ; HZ: 250 ; 1/HZ (ms): 4
[ 7103.056044]  testjiffy_timer_function: runcount 1 
[ 7103.060045]  testjiffy_timer_function: runcount 2 
[ 7103.064052]  testjiffy_timer_function: runcount 3 
[ 7103.068050]  testjiffy_timer_function: runcount 4 
[ 7103.072053]  testjiffy_timer_function: runcount 5 
[ 7103.076036]  testjiffy_timer_function: runcount 6 
[ 7103.080044]  testjiffy_timer_function: runcount 7 
[ 7103.084044]  testjiffy_timer_function: runcount 8 
[ 7103.088060]  testjiffy_timer_function: runcount 9 
[ 7103.092059]  testjiffy_timer_function: runcount 10 
[ 7104.095429] Exit testjiffy

... which results with time series and delta histogram plots like these:

This is, essentially, the quality of timing that I'd expect from the code.

However - every once in a while, I get a capture like:

[ 7121.377507] Init testjiffy: 0 ; HZ: 250 ; 1/HZ (ms): 4
[ 7121.380049]  testjiffy_timer_function: runcount 1 
[ 7121.384062]  testjiffy_timer_function: runcount 2 
[ 7121.392053]  testjiffy_timer_function: runcount 3 
[ 7121.396055]  testjiffy_timer_function: runcount 4 
[ 7121.400068]  testjiffy_timer_function: runcount 5 
[ 7121.404085]  testjiffy_timer_function: runcount 6 
[ 7121.408084]  testjiffy_timer_function: runcount 7 
[ 7121.412072]  testjiffy_timer_function: runcount 8 
[ 7121.416083]  testjiffy_timer_function: runcount 9 
[ 7121.420066]  testjiffy_timer_function: runcount 10 
[ 7122.417325] Exit testjiffy

... which results with a rendering like:

... and I'm like: "WHOOOOOAAAAAA ... wait a second..." - isn't there a pulse dropped from the sequence? Meaning that add_timer missed a slot, and then fired up the function in the next 4 ms slot?

The interesting thing is, that in running these tests, I have nothing else but a terminal, web browser and a text editor started up - so I cannot really see anything running, that may hog the OS/kernel; and thus, I really cannot see a reason why the kernel would make such a big miss (of an entire jiffy period). When I read about Linux kernel timing, e.g. "The simplest and least accurate of all timers ... is the timer API", I read that "least accurate" as: "don't expect exactly 4 ms period" (as per this example) - and I don't, I'm fine with the variance shown in the (first) histogram; but I don't expect that a whole period will be missed!?

So my question(s) are:

• Is this expected behavior from add_timer at this resolution (that a period can occasionally be missed)?
• If so, is there a way to "force" add_timer to fire the function at each 4ms slot, as specified by a jiffy on this platform?
• Is it possible that I get a "wrong" timestamp - e.g. the timestamp reflecting when the actual "print" to syslog happened, rather than when the function actually fired?
• Note that I'm not looking for a period resolution below what corresponds to a jiffy (in this case, 4ms); nor am I looking to decrease the delta variance when the code works properly. So as I see it, I don't have "high resolution timer" demands, nor "hard real-time" demands - I just want add_timer to fire reliably. Would that be possible on this platform, without resorting to special "real-time" configurations of the kernel?

_{Bonus question: in rerun.sh below, you'll note two sleeps marked with MUSTHAVE; if either of them is left out/commented, OS/kernel freezes, and requires a hard reboot. And I cannot see why - is it really possible that running rmmod after insmod from bash is so fast, that it will conflict with the normal process of module loading/unloading?}

---

Platform info:

$ cat /proc/cpuinfo | grep "processor|model name|MHz|cores"
processor   : 0       # (same for 1)
model name  : Intel(R) Atom(TM) CPU N450   @ 1.66GHz
cpu MHz             : 1000.000
cpu cores   : 1
$ echo $(cat /etc/issue ; uname -a)
Ubuntu 11.04 
 l Linux mypc 2.6.38-16-generic #67-Ubuntu SMP Thu Sep 6 18:00:43 UTC 2012 i686 i686 i386 GNU/Linux
$ echo $(lsb_release -a 2>/dev/null | tr '
' ' ')
Distributor ID: Ubuntu Description: Ubuntu 11.04 Release: 11.04 Codename: natty

Code:

$ cd /tmp/testjiffy
$ ls
Makefile  rerun.sh  testjiffy.c

Makefile:

obj-m += testjiffy.o

all:
    make -C /lib/modules/$(shell uname -r)/build M=$(PWD) modules

clean:
    make -C /lib/modules/$(shell uname -r)/build M=$(PWD) clean

testjiffy.c:

/*
 *  [http://www.tldp.org/LDP/lkmpg/2.6/html/lkmpg.html#AEN189 The Linux Kernel Module Programming Guide]
 */


#include <linux/module.h>   /* Needed by all modules */
#include <linux/kernel.h>   /* Needed for KERN_INFO */
#include <linux/init.h>     /* Needed for the macros */
#include <linux/jiffies.h>
#include <linux/time.h>
#define MAXRUNS 10

static volatile int runcount = 0;
static struct timer_list my_timer;

static void testjiffy_timer_function(unsigned long data)
{
  int tdelay = 100;

  runcount++;
  if (runcount == 5) {
    while (tdelay > 0) { tdelay--; } // small delay
  }

  printk(KERN_INFO
    " %s: runcount %d 
",
    __func__, runcount);

  if (runcount < MAXRUNS) {
    my_timer.expires = jiffies + 1;
    add_timer(&my_timer);
  }
}


static int __init testjiffy_init(void)
{
    printk(KERN_INFO
    "Init testjiffy: %d ; HZ: %d ; 1/HZ (ms): %d
",
               runcount,      HZ,        1000/HZ);

  init_timer(&my_timer);

    my_timer.function = testjiffy_timer_function;
    //my_timer.data = (unsigned long) runcount;

  my_timer.expires = jiffies + 1;
    add_timer(&my_timer);
    return 0;
}

static void __exit testjiffy_exit(void)
{
    printk(KERN_INFO "Exit testjiffy
");
}

module_init(testjiffy_init);
module_exit(testjiffy_exit);

MODULE_LICENSE("GPL");

rerun.sh:

#!/usr/bin/env bash

set -x
make clean
make
# blank syslog first
sudo bash -c 'echo "0" > /var/log/syslog'
sleep 1   # MUSTHAVE 01!
# reload kernel module/driver
sudo insmod ./testjiffy.ko
sleep 1   # MUSTHAVE 02!
sudo rmmod testjiffy
set +x

# copy & process syslog

max=0;
for ix in _testjiffy_*.syslog; do
  aa=${ix#_testjiffy_};
  ab=${aa%.syslog} ;
  case $ab in
    *[!0-9]*) ab=0;;          # reset if non-digit obtained; else
    *) ab=$(echo $ab | bc);;  # remove leading zeroes (else octal)
  esac
  if (( $ab > $max )) ; then
    max=$((ab));
  fi;
done;
newm=$( printf "%05d" $(($max+1)) );
PLPROC='chomp $_;
if (!$p) {$p=0;}; if (!$f) {$f=$_;} else {
  $a=$_-$f; $d=$a-$p;
  print "$a $d
" ; $p=$a;
};'

set -x
grep "testjiffy" /var/log/syslog | cut -d' ' -f7- > _testjiffy_${newm}.syslog
grep "testjiffy_timer_function" _testjiffy_${newm}.syslog 
  | sed 's/[(.*)].*/1/' 
  | perl -ne "$PLPROC" 
  > _testjiffy_${newm}.dat
set +x

cat > _testjiffy_${newm}.gp <<EOF
set terminal pngcairo font 'Arial,10' size 900,500
set output '_testjiffy_${newm}.png'
set style line 1 linetype 1 linewidth 3 pointtype 3 linecolor rgb "red"
set multiplot layout 1,2 title "_testjiffy_${newm}.syslog"
set xtics rotate by -45
set title "Time positions"
set yrange [0:1.5]
set offsets graph 50e-3, 1e-3, 0, 0
plot '_testjiffy_${newm}.dat' using 1:(1.0):xtic(gprintf("%.3se%S",$1)) notitle with points ls 1, '_testjiffy_${newm}.dat' using 1:(1.0) with impulses ls 1
binwidth=0.05e-3
set boxwidth binwidth
bin(x,width)=width*floor(x/width) + width/2.0
set title "Delta diff histogram"
set style fill solid 0.5
set autoscale xy
set offsets graph 0.1e-3, 0.1e-3, 0.1, 0.1
plot '_testjiffy_${newm}.dat' using (bin($2,binwidth)):(1.0) smooth freq with boxes ls 1
unset multiplot
EOF
set -x; gnuplot _testjiffy_${newm}.gp ; set +x

---

EDIT: Motivated by this comment by @granquet, I tried to obtain scheduler statistics from /proc/schedstat and /proc/sched_debug, by using dd through call_usermodehelper; note that this most of the time "skips" (that is, a file due to the 7th, or 6th, or Xth run of the function would be missing); but I managed to obtain two complete runs, and posted them in https://gist.github.com/anonymous/5709699 (as I noticed gist may be preferred to pastebin on SO), given the output is kinda massive; the *_11* files log a proper run, the *_17* files log a run with a "drop".

Note I also switched to mod_timer_pinned in the module, and it doesn't help much (the gist logs are obtained with the module using this function). These are the changes in testjiffy.c:

#include <linux/kmod.h> // usermode-helper API
...
char fcmd[] = "of=/tmp/testjiffy_sched00";
char *dd1argv[] = { "/bin/dd", "if=/proc/schedstat", "oflag=append", "conv=notrunc", &fcmd[0], NULL };
char *dd2argv[] = { "/bin/dd", "if=/proc/sched_debug", "oflag=append", "conv=notrunc", &fcmd[0], NULL };
static char *envp[] = {
      "HOME=/",
      "TERM=linux",
      "PATH=/sbin:/bin:/usr/sbin:/usr/bin", NULL };

static void testjiffy_timer_function(unsigned long data)
{
  int tdelay = 100;
  unsigned long tjnow;

  runcount++;
  if (runcount == 5) {
    while (tdelay > 0) { tdelay--; } // small delay
  }

  printk(KERN_INFO
    " %s: runcount %d 
",
    __func__, runcount);

  if (runcount < MAXRUNS) {
    mod_timer_pinned(&my_timer, jiffies + 1);
    tjnow = jiffies;
    printk(KERN_INFO
      " testjiffy expires: %lu - jiffies %lu => %lu / %lu
",
      my_timer.expires, tjnow, my_timer.expires-tjnow, jiffies);
    sprintf(fcmd, "of=/tmp/testjiffy_sched%02d", runcount);
    call_usermodehelper( dd1argv[0], dd1argv, envp, UMH_NO_WAIT );
    call_usermodehelper( dd2argv[0], dd2argv, envp, UMH_NO_WAIT );
  }
}

... and this in rerun.sh:

...
set +x

for ix in /tmp/testjiffy_sched*; do
  echo $ix | tee -a _testjiffy_${newm}.sched
  cat $ix >> _testjiffy_${newm}.sched
done
set -x ; sudo rm /tmp/testjiffy_sched* ; set +x

cat > _testjiffy_${newm}.gp <<EOF
...

---

I'll use this post for verbose replying.

@CL.: many thanks for the answer. Good to have i

Answer 1

Many thanks for all the comments and answers; they all pointed to things that must be taken into account - but given I'm somewhat of a forever noob, I still needed to do some more reading, before gaining some understanding (I hope a correct one). Also, I couldn't really find anything specific for periodically "ticking" functions - so I'll post a more verbose answer here.

In brief - for a reliable periodic Linux kernel function at a resolution of a jiffy, do not use add_timer (<linux/time.h>), as it may "drop" an entire period; use high-resolution timers (<linux/hrtimer.h>) instead. In more detail:

Is it possible that I get a "wrong" timestamp - ...?

@CL.: The timestamp in the log is the time when that string was printed to the log.

So, maybe it's possible - but it turns out, that's not the problem here:

Is this expected behavior from add_timer at this resolution (that a period can occasionally be missed)?

I guess, it turns out - yes:

If so, is there a way to "force" add_timer to fire the function at each 4ms slot, as specified by a jiffy on this platform?

... and (I guess again), it turns out - no.

Now, the reasons for this are somewhat subtle - and I hope if I didn't get them right, someone will correct me. First of all, the first misconception that I had, was that "a clock is just a clock" (in the sense of: even if it is implemented as computer code) - but that is not quite correct. The kernel basically has to "queue" an "event" somewhere, each time something like add_timer is used; and this request may come from anything really: from any (and all) sort(s) of driver(s), or even possibly userspace.

The problem is that this "queuing" costs - since in addition to the kernel having to handle (the equivalent of) traversing and inserting (and removing) items in an array, it also has to handle timer delays spanning several orders of magnitude (from say milliseconds to maybe 10s of seconds); and the fact that some drivers (like, apparently, those for network protocols) apparently queue a lot of timer events, which are usually cancelled before running - while other types may require a completely different behavior ^{(like in my case - in a periodic function, you expect that most of the time, the event will usually not be cancelled; and you also queue the events one by one)}. On top of that, the kernel needs to handle this for uniprocessor vs. SMP vs. multiprocessor platforms. Thus, there is a cost-benefit tradeoff involved in implementing timer handling in the kernel.

It turns out, the architecture around jiffies/add_timer is designed to handle the most common devices - and for them, precision at a resolution of a jiffy is not an issue; but this also means that one cannot expect a reliable timer at resolution of a single jiffy with this method. This is also compounded by the fact that the kernel handles these "event queues" by treating them (somewhat) like interrupt service requests (IRQ); and that there are several levels of priority in IRQ handling in the kernel, where higher priority routine can pre-empt a lower priority one (that is: interrupt and suspend a lower priority routine, even if it is being executed at the time - and allow the higher priority routine to go about its business). Or, as previously noted:

@granquet: timers run in soft irq context, which means they have the highest priority and they preempt everything running/runnable on the CPU ... but hardware interrupts which are not disabled when servicing a soft irq. So you might (most probable explanation) get an Hardware interrupt here and there that preempts your timer ... and thus you get an interrupt that is not serviced at the right time.

@CL.: It is indeed possible that your timer function gets called at a later jiffy than what expires what set to. Possible reasons are scheduling delays, other drivers that disable interrupts for too long (graphics and WLAN drivers are usual culprits), or some crappy BIOS executing SMI code.

I now think so, too - I think this could be an illustration of what happens:

• jiffies changes to, say, 10000 (== 40000 ms @250 Hz)
• Let's say the timer function, (queued by add_timer) is about to start running - but hasn't started running yet
• Let's say here, the network card generates (for whatever reason) a hardware interrupt
• The hardware interrupt, having a higher priority, triggers the kernel to pre-empt (stop and suspend) the timer function (possibly started by now, and just few instructions in);
• That means the kernel now has to reschedule the timer function, to run at a later point - and since one only works with integer operations in the kernel, and time resolution for this kind of event is in jiffies - the best it can do is reschedule it for jiffies+1 (10001 == 40004 ms @250 Hz)
• Now the kernel switches the context to the IRQ service routine of the network card driver, and it goes about its business
• Let's say the IRQ service routine completes in 200 μs - that means now we're (in "absolute" terms) at 40000.2 ms - however, we are also still at 10000 jiffies
• If the kernel now switched the context back to the timer function, it would have completed - without me necessarily noticing the delay;
• ... however, that will not happen, because the timer function is scheduled for the next jiffy!
• So kernel goes about its business (possibly sleeping) for the next approx 3.8 ms
• jiffies changes to 10001 (== 40004 ms @250 Hz)
• (the previously rescheduled) timer function runs - and this time completes without interruption

I haven't really done a detailed analysis to see if the sequence of events is exactly as described above; but I'm quite persuaded that it is something close - in other words, a resolution problem - especially since the high-resolution timer approach seems to not show this behavior. It would be great indeed, to obtain a scheduler log, and know exactly what happened to cause a pre-empt - but I doubt the roundtrip to userspace, which I attempted in OP edit, in response to @granquet's comment, is the right thing to do.

In any case, going back to this:

Note that I'm not looking for a period resolution below what corresponds to a jiffy (in this case, 4ms); nor am I looking to decrease the delta variance when the code works properly. So as I see it, I don't have "high resolution timer" demands, nor "hard real-time" demands ...

... here was a bad mistake I made - as the analysis above shows, I did have "high resolution" demands! And had I realized that earlier, I may have found relevant reading sooner. Anyways, some relevant docs - even if they don't discuss specifically periodic functions - for me, were:

• LDD3: 5.3. Semaphores and Mutexes - (in describing a driver with different demands from here): ^{"no accesses will be made from interrupt handlers or other asynchronous contexts. There are no particular latency (response time) requirements; application programmers understand that I/O requests are not usually satisfied immediately"}
• Documentation/timers/hrtimers.txt - ^{"The timers.c code is very "tightly coded" around jiffies and 32-bitness assumptions, and has been honed and micro-optimized for a relatively narrow use case (jiffies in a relatively narrow HZ range) for many years - and thus even small extensions to it easily break the wheel concept"}
• T. Gleixner, D. Niehaus Hrtimers and Beyond: Transforming the Linux Time Subsystems (pdf) - (most detailed, see also diagrams inside) ^{"The Cascading Timer Wheel (CTW), which was implemented in 1997, replaced the original time ordered double linked list to resolve the scalability problem of the linked list's O(N) insertion time... The current approach to timer management in Linux does a good job of satisfying an extremely wide range of requirements, but it cannot provide the quality of service required in some cases precisely because it must satisfy such a wide range of requirements... The timeout related timers are kept in the existing timer wheel and a new subsystem optimized for (high resolution) timer requirements hrtimers was implemented. hrtimers are entirely based on human time (units: nanoseconds)... They are kept in a time sorted, per-CPU list, implemented as a red-black tree."}
• The high-resolution timer API [LWN.net] - ^{"At its core, the hrtimer mechanism remains the same. Rather than using the "timer wheel" data structure, hrtimers live on a time-sorted linked list, with the next timer to expire being at the head of the list. A separate red/black tree is also used to enable the insertion and removal of timer events without scanning through the list. But while the core remains the same, just about everything else has changed, at least superficially."}
• Software interrupts and realtime [LWN.net] - ^{"The softirq mechanism is meant to handle processing that is almost — but not quite — as important as the handling of hardware interrupts. Softirqs run at a high priority (though with an interesting exception, described below), but with hardware interrupts enabled. They thus will normally preempt any work except the response to a "real" hardware interrupt... Starting with the 3.0 realtime patch set, though, that capability went away... In response, in 3.6.1-rt1, the handling of softirqs has changed again."}
• High- (but not too high-) resolution timeouts [LWN.net] - ^{"_poll() and epoll_wait() take an integer number of milliseconds; select() takes a struct timeval with microsecond resolution, and ppoll() and pselect() take a struct timespec with nanosecond resolution. They are all the same, though, in that they convert this timeout value to jiffies, with a maximum resolution between one and ten milliseconds. A programmer might program a pselect() call with a 10 nanosecond timeout, but the call may not return until 10 milliseconds later, even in the absence of contention for the CPU. ... It's a useful feature, but it comes at the cost of some significant API changes._"}

One thing clear from the quotes, is that high-resolution timing facilities are still under active dev