[Bug 224837] Extremly unaccurate nanosleep() called to sleep for 0.6 seconds actually sleeps up to 0.640 seconds

Tue Jan 2 10:56:50 UTC 2018

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=224837

            Bug ID: 224837
           Summary: Extremly unaccurate nanosleep() called to sleep for
                    0.6 seconds actually sleeps up to 0.640 seconds
           Product: Base System
           Version: 11.0-RELEASE
          Hardware: Any
                OS: Any
            Status: New
          Severity: Affects Many People
          Priority: ---
         Component: kern
          Assignee: freebsd-bugs at FreeBSD.org
          Reporter: aeder at list.ru

Extremly unaccurate nanosleep() called to sleep for 0.6 seconds actually sleeps
up to 0.640 seconds. More then 5% error.

This test program:

#include <stdio.h>
#include <time.h>
#include <stdint.h>

double  time_diff(struct timespec * start, struct timespec * stop) // in
millese
conds
{
    struct timespec result;

    if ((stop->tv_nsec - start->tv_nsec) < 0) {
        result.tv_sec = stop->tv_sec - start->tv_sec - 1;
        result.tv_nsec = stop->tv_nsec - start->tv_nsec + 1000000000;
    } else {
        result.tv_sec = stop->tv_sec - start->tv_sec;
        result.tv_nsec = stop->tv_nsec - start->tv_nsec;
    };

   return ((result.tv_sec*1000) + ((double)(result.tv_nsec)/1000000.0));
};

int main(int argc, char * argv[])
{

struct timespec before_sleep, after_sleep, time_for_sleep;

while(1)
{
clock_gettime(CLOCK_MONOTONIC, &before_sleep);

time_for_sleep.tv_sec=0;
time_for_sleep.tv_nsec=600 * 1000 * 1000; //nanoseconds
nanosleep(&time_for_sleep,NULL);

clock_gettime(CLOCK_MONOTONIC, &after_sleep);

printf("Sleeping for %d ms, real sleep is %f\n",
       (int)( time_for_sleep.tv_nsec / (1000*1000)),
       time_diff(&before_sleep, &after_sleep));
};

return 0;
};

produce the following results:

[der at perforce ~/nano]$ ./nano
Sleeping for 600 ms, real sleep is 638.271304
Sleeping for 600 ms, real sleep is 638.468908
Sleeping for 600 ms, real sleep is 638.523862
Sleeping for 600 ms, real sleep is 638.527911
Sleeping for 600 ms, real sleep is 638.523231
Sleeping for 600 ms, real sleep is 638.524958
Sleeping for 600 ms, real sleep is 638.525569
Sleeping for 600 ms, real sleep is 638.574649
Sleeping for 600 ms, real sleep is 638.466486
Sleeping for 600 ms, real sleep is 631.819499
Sleeping for 600 ms, real sleep is 638.328923
Sleeping for 600 ms, real sleep is 638.526769
Sleeping for 600 ms, real sleep is 638.531379
Sleeping for 600 ms, real sleep is 638.539257
Sleeping for 600 ms, real sleep is 638.523906
Sleeping for 600 ms, real sleep is 638.524129
Sleeping for 600 ms, real sleep is 638.523692
^C

[der at perforce ~/nano]$ uname -a
FreeBSD perforce 11.0-RELEASE-p9 FreeBSD 11.0-RELEASE-p9 #0: Tue Apr 11
08:48:40 UTC 2017    
root at amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC  amd64
[der at perforce ~/nano]$
[der at perforce ~/nano]$ sysctl -a | grep kern | grep hz
kern.clockrate: { hz = 1000, tick = 1000, profhz = 8128, stathz = 127 }
kern.hz: 1000

I have tryed to change kern.hz in /boot/loader.conf, both 100 and 10000 values
do not change anything.

I have tested on FreeBSD-10.3 i386 and amd64 - same results.

It seems like on 10-seconds interval it cause error up to 0.17 seconds.

For extremly short intervals, like 1 ms (0.001 seconds) error is still 5-7%.
=============================================

Exactly the same program compiled and running under Linux (CentOS) produce the
following results:

aeder at Moria$ ./nano
Sleeping for 600 ms, real sleep is 600.113074
Sleeping for 600 ms, real sleep is 600.112979
Sleeping for 600 ms, real sleep is 600.128481
Sleeping for 600 ms, real sleep is 600.139906
Sleeping for 600 ms, real sleep is 600.085603
Sleeping for 600 ms, real sleep is 600.123303
Sleeping for 600 ms, real sleep is 600.139970
Sleeping for 600 ms, real sleep is 600.058206
Sleeping for 600 ms, real sleep is 600.139756
Sleeping for 600 ms, real sleep is 600.139840
Sleeping for 600 ms, real sleep is 600.139880
Sleeping for 600 ms, real sleep is 600.068483
Sleeping for 600 ms, real sleep is 600.139898
Sleeping for 600 ms, real sleep is 600.098436
^C
aeder at Moria$ uname -a
Linux Moria 2.6.32-431.el6.i686 #1 SMP Fri Nov 22 00:26:36 UTC 2013 i686 i686
i386 GNU/Linux

==============================================
Really old FreeBSD version (6.3) on old hardware:

fspa2# ./nano
Sleeping for 600 ms, real sleep is 600.631924
Sleeping for 600 ms, real sleep is 600.852902
Sleeping for 600 ms, real sleep is 600.977778
Sleeping for 600 ms, real sleep is 600.978615
Sleeping for 600 ms, real sleep is 600.981130
Sleeping for 600 ms, real sleep is 600.980293
Sleeping for 600 ms, real sleep is 600.981689
Sleeping for 600 ms, real sleep is 600.979454
Sleeping for 600 ms, real sleep is 600.981689
Sleeping for 600 ms, real sleep is 600.979175
Sleeping for 600 ms, real sleep is 600.987276
Sleeping for 600 ms, real sleep is 600.974425
Sleeping for 600 ms, real sleep is 600.982247
Sleeping for 600 ms, real sleep is 600.979734
Sleeping for 600 ms, real sleep is 600.981689
Sleeping for 600 ms, real sleep is 600.980851
^C

fspa2# uname -a
FreeBSD fspa2 6.3-RELEASE FreeBSD 6.3-RELEASE #0: Wed Jan 16 04:45:45 UTC 2008 
   root at dessler.cse.buffalo.edu:/usr/obj/usr/src/sys/SMP  i386
fspa2#
fspa2# sysctl -a | grep kern | grep hz
kern.clockrate: { hz = 1000, tick = 1000, profhz = 666, stathz = 133 }

==============================================

It seems for me that nanosleep() is broken somehow in recent versions of
FreeBSD.
It's really annoing and will cause to write wrappers over nanosleep() in
userland.

-- 
You are receiving this mail because:
You are the assignee for the bug.