filesystem nanoseconds reporting incorrectly

[duncanphillips]

Note: I'm not 100% sure if this is xhyve or not, but this about where my debugging abilities ended.

Problem: Nanoseconds given by linux stat command change continuously in what appears to be a pattern. The seconds never change, but the nanoseconds higher order bytes cycle from 0-9999. This results in daemons that watch for modify times to keep triggering.

Reproducing: We're running minikube (part of Kubernetes) which uses the xhyve driver, it also mounts /Users into the VM. I can only get to tools by running a container on the minikube docker instance, but that should just use the system calls from the underlying host afaik.

So in an ubuntu image I wrote the following C script:

#include <sys/types.h>
#include <sys/stat.h>
#include <unistd.h>
#include <stdlib.h>
#include <stdio.h>

int main(int argc, char * argv[])
{
    struct stat s;
    if (-1 == stat("__init__.py", &s))
        return EXIT_FAILURE;

    printf("st_mtime st_mtim:%ld, st_mtim.tv_nsec:%ld \n", s.st_mtime, s.st_mtim.tv_nsec);
    return EXIT_SUCCESS;
}

It looks at the init.py file and prints out the second and nanosecond part of the modification time.

The output is as follow:

root@dashboard-321412304-ndvvr:/usr/local/tal/tal/tal/services/dashboard# (while true; do ./stat; done)

st_mtime st_mtim:1479791497, st_mtim.tv_nsec:982915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:987915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:994915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:999915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:4915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:11915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:16915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:22915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:27915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:32915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:37915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:43915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:48915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:55915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:62915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:74915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:94915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:104915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:113915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:127915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:135915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:142915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:154915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:161915037
...
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:985915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:991915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:995915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:1915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:6915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:12915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:16915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:21915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:25915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:30915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:34915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:39915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:45915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:50915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:54915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:59915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:63915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:67915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:71915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:76915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:81915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:85915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:90915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:96915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:102915037
st_mtime st_mtim:1479791497, st_mtim.tv_nsec:108915037

Note how the lower order digits stay at 15037, and the higher order wraps around somewhere around 9999.

I don't know these systems particularly well, but perhaps something to do with one of the functions such as https://github.com/mist64/xhyve/blob/master/src/vmm/vmm_callout.c#L88?

Extra info:

repeated with stat command

(while true; do stat __init__.py | grep Modify; done)
Modify: 2016-11-22 05:11:37.350915037 +0000
Modify: 2016-11-22 05:11:37.366915037 +0000
Modify: 2016-11-22 05:11:37.381915037 +0000
Modify: 2016-11-22 05:11:37.394915037 +0000
Modify: 2016-11-22 05:11:37.406915037 +0000
Modify: 2016-11-22 05:11:37.415915037 +0000
Modify: 2016-11-22 05:11:37.425915037 +0000
Modify: 2016-11-22 05:11:37.436915037 +0000
Modify: 2016-11-22 05:11:37.446915037 +0000
Modify: 2016-11-22 05:11:37.461915037 +0000
...
Modify: 2016-11-22 05:11:37.979915037 +0000
Modify: 2016-11-22 05:11:37.985915037 +0000
Modify: 2016-11-22 05:11:37.992915037 +0000
Modify: 2016-11-22 05:11:37.997915037 +0000
Modify: 2016-11-22 05:11:37.003915037 +0000
Modify: 2016-11-22 05:11:37.009915037 +0000
Modify: 2016-11-22 05:11:37.015915037 +0000
Modify: 2016-11-22 05:11:37.021915037 +0000
Modify: 2016-11-22 05:11:37.026915037 +0000
Modify: 2016-11-22 05:11:37.033915037 +0000
Modify: 2016-11-22 05:11:37.038915037 +0000

Happy to add any more debugging to the issue