sleep() is too unprecise

[toncho11]

sleep() takes microseconds as argument, but it can be as unprecise as 20ms?

I have tried 1ms, so sleep(1000), but I get more. It seems a 10 ms timer quantum plus one extra 10 ms tick for every positive usleep() call.

Also gettimeofday() is a bit better, but also in the 10ms range of error.

So there is actually no way to have a 1-2 ms sleep on ELKS?

[ghaerr]

sleep() takes microseconds as argument

usleep takes microseconds, sleep takes seconds.

So there is actually no way to have a 1-2 ms sleep on ELKS?

Not by actually sleeping, since the IBM PC hardware clock interrupt fires only once every 10ms.

If busy-looping is an option, your application can try using the same technique as the ELKS precision library timer uses - actually reading the hardware Programmable Interval Timer countdown register, which ticks every 0.838 microseconds. This is a little complicated, see libc/debug/prectimer.c for details. Basically, you would compile your program setup for precision timer, then busy loop the CPU until the PIT countdown elapsed. It's all complicated since the PIT countdown wraps, but the upper-level get_ptime handles that.

Note that busy-looping still isn't guaranteed, since your application may get pre-empted in the next 10ms timer interval (or not).

[toncho11]

I was using only usleep.

Consider exposing the precision timer from libc/debug/prectimer.c as a small public libc API, for example:

int ptime_init(void);
unsigned long ptime_us(void);

ptime_us() would return a monotonic microsecond timestamp and handle PIT wrap internally.

I need it for:

• calculate accurate dt in a callback loop
• implement short 1–4 ms busy-wait pacing
• use absolute frame deadlines to avoid timing drift

[ghaerr]

exposing the precision timer from libc/debug/prectimer.c as a small public libc API, for example:

The precision timer is already a public API, no need for a separate ptime_us, you can write that using a three-line while loop using get_ptime for however you need it. For your own uses, just get the initial ptick count with get_ptime, then loop calling get_time gain until ptick > "the delay you're looking for". Its no big deal for your own application programs to use it, but would not be a great idea to add a busy-loop to a library, as users may not realize they're grabbing the CPU, and it isn't guaranteed to be accurate.

[toncho11]

OK, but it is not exposed for OWC libc and I am using OWC to compile LuaGFX.
Also rectimer.c uses IA16 GCC inline assembly.

[ghaerr]

it is not exposed for OWC libc and I am using OWC to compile LuaGFX.

Oh, I see. I'll take another look at that: there were initial problems with getting this compiled on OWC the first time around, it could take some rework.

[toncho11]

Maybe another problem using gcc-ia16: In copy.86, get_ptime() appears to advance about twice as fast as gettimeofday() during busy-wait loops, even though its short-term resolution is good at roughly 4–10 µs. The likely cause is the case where the PIT counter wraps before the timer interrupt updates jiffies, while get_ptime() assumes that jdiff is already nonzero and executes jdiff--. This can cause a full PIT period to be counted again on the next call, producing occasional deltas around 12,000 ticks and the observed factor-of-two timing error.

[toncho11]

#include <stdio.h>
#include <unistd.h>
#include <sys/time.h>
#include <linuxmt/prectimer.h>


#define PTICKS_PER_10_MS 11932UL


struct precise_sleep_info {
    unsigned long target_ticks;
    unsigned long elapsed_ticks;
    unsigned long maximum_delta;
    unsigned long polls;
};


static unsigned long elapsed_us(const struct timeval *start,
                                const struct timeval *end)
{
    long sec;
    long usec;

    sec = end->tv_sec - start->tv_sec;
    usec = end->tv_usec - start->tv_usec;

    if (usec < 0) {
        usec += 1000000L;
        --sec;
    }

    return (unsigned long)sec * 1000000UL
         + (unsigned long)usec;
}


/*
 * Convert milliseconds to precision-timer ticks.
 *
 * Round upward so integer truncation cannot shorten the requested delay.
 */
static unsigned long ms_to_pticks(unsigned int ms)
{
    return ((unsigned long)ms * PTICKS_PER_10_MS + 9UL) / 10UL;
}


/*
 * Convert precision-timer ticks to microseconds without overflowing
 * a 32-bit unsigned long for reasonably long test intervals.
 */
static unsigned long pticks_to_us(unsigned long ticks)
{
    unsigned long whole;
    unsigned long remainder;

    whole = ticks / PTICKS_PER_10_MS;
    remainder = ticks % PTICKS_PER_10_MS;

    return whole * 10000UL
         + (remainder * 10000UL + PTICKS_PER_10_MS / 2UL)
         / PTICKS_PER_10_MS;
}


/*
 * LuaGFX-local busy delay.
 *
 * get_ptime() returns elapsed pticks since its preceding invocation.
 * Consequently, each returned interval must be accumulated.
 *
 * This function consumes the CPU and does not yield.
 */
static int precise_sleep(unsigned int ms,
                         struct precise_sleep_info *info)
{
    unsigned long target;
    unsigned long elapsed;
    unsigned long delta;
    unsigned long maximum;
    unsigned long polls;

    if (info != NULL) {
        info->target_ticks = 0;
        info->elapsed_ticks = 0;
        info->maximum_delta = 0;
        info->polls = 0;
    }

    if (ms == 0)
        return 0;

    target = ms_to_pticks(ms);
    elapsed = 0;
    maximum = 0;
    polls = 0;

    /*
     * Establish the starting point. The first returned interval belongs
     * to the time before this sleep and is intentionally discarded.
     */
    (void)get_ptime();

    while (elapsed < target) {
        delta = get_ptime();

        if (delta > maximum)
            maximum = delta;

        elapsed += delta;
        ++polls;
    }

    if (info != NULL) {
        info->target_ticks = target;
        info->elapsed_ticks = elapsed;
        info->maximum_delta = maximum;
        info->polls = polls;
    }

    return 0;
}


/*
 * Estimate the smallest nonzero gettimeofday() change.
 */
static void test_clock_resolution(unsigned int changes)
{
    struct timeval previous;
    struct timeval current;
    unsigned long delta;
    unsigned long minimum;
    unsigned long maximum;
    unsigned long total;
    unsigned int found;

    if (changes == 0)
        return;

    if (gettimeofday(&previous, NULL) != 0) {
        printf("gettimeofday failed\n");
        return;
    }

    minimum = 0;
    maximum = 0;
    total = 0;
    found = 0;

    while (found < changes) {
        if (gettimeofday(&current, NULL) != 0) {
            printf("gettimeofday failed\n");
            return;
        }

        delta = elapsed_us(&previous, &current);

        if (delta != 0) {
            if (minimum == 0 || delta < minimum)
                minimum = delta;

            if (delta > maximum)
                maximum = delta;

            total += delta;
            ++found;
            previous = current;
        }
    }

    printf("gettimeofday resolution:\n");
    printf("  min=%lu us avg=%lu us max=%lu us\n",
           minimum,
           total / (unsigned long)changes,
           maximum);
}


/*
 * Measure intervals returned by consecutive get_ptime() calls.
 */
static void test_ptime_resolution(unsigned int changes)
{
    unsigned long delta;
    unsigned long minimum;
    unsigned long maximum;
    unsigned long total;
    unsigned long calls;
    unsigned int found;

    if (changes == 0)
        return;

    minimum = 0;
    maximum = 0;
    total = 0;
    calls = 0;
    found = 0;

    /* Establish the initial precision-timer state. */
    (void)get_ptime();

    while (found < changes) {
        delta = get_ptime();
        ++calls;

        if (delta != 0) {
            if (minimum == 0 || delta < minimum)
                minimum = delta;

            if (delta > maximum)
                maximum = delta;

            total += delta;
            ++found;
        }
    }

    printf("get_ptime resolution:\n");
    printf("  min=%lu ticks, avg=%lu ticks, max=%lu ticks\n",
           minimum,
           total / (unsigned long)changes,
           maximum);

    printf("  min~%lu us, avg~%lu us, max~%lu us\n",
           pticks_to_us(minimum),
           pticks_to_us(total / (unsigned long)changes),
           pticks_to_us(maximum));

    printf("  calls=%lu\n", calls);
}


static void test_precise_sleep(unsigned int ms, unsigned int count)
{
    struct timeval start;
    struct timeval end;
    struct precise_sleep_info info;

    unsigned long requested_us;
    unsigned long wall_us;
    unsigned long wall_average_us;

    unsigned long total_pticks;
    unsigned long total_polls;
    unsigned long maximum_delta;
    unsigned long ptime_us;
    unsigned long ptime_average_us;

    long wall_error_us;
    long ptime_error_us;

    unsigned int errors;
    unsigned int i;

    if (count == 0)
        return;

    total_pticks = 0;
    total_polls = 0;
    maximum_delta = 0;
    errors = 0;

    if (gettimeofday(&start, NULL) != 0) {
        printf("gettimeofday(start) failed\n");
        return;
    }

    for (i = 0; i < count; ++i) {
        if (precise_sleep(ms, &info) != 0) {
            ++errors;
            continue;
        }

        total_pticks += info.elapsed_ticks;
        total_polls += info.polls;

        if (info.maximum_delta > maximum_delta)
            maximum_delta = info.maximum_delta;
    }

    if (gettimeofday(&end, NULL) != 0) {
        printf("gettimeofday(end) failed\n");
        return;
    }

    requested_us = (unsigned long)ms
                 * 1000UL
                 * (unsigned long)count;

    wall_us = elapsed_us(&start, &end);
    wall_average_us = wall_us / (unsigned long)count;

    ptime_us = pticks_to_us(total_pticks);
    ptime_average_us = ptime_us / (unsigned long)count;

    wall_error_us = (long)wall_us - (long)requested_us;
    ptime_error_us = (long)ptime_us - (long)requested_us;

    printf("precise %u ms x %u:\n", ms, count);

    printf("  requested=%lu us wall=%lu us avg=%lu us\n",
           requested_us,
           wall_us,
           wall_average_us);

    printf("  wall error=%ld us\n", wall_error_us);

    printf("  ptime=%lu us avg=%lu us error=%ld us\n",
           ptime_us,
           ptime_average_us,
           ptime_error_us);

    printf("  target=%lu ticks max_delta=%lu polls=%lu errors=%u\n",
           ms_to_pticks(ms),
           maximum_delta,
           total_polls,
           errors);
}


static void test_usleep(unsigned int ms, unsigned int count)
{
    struct timeval start;
    struct timeval end;

    unsigned long requested_us;
    unsigned long actual_us;
    unsigned long average_us;

    long error_us;

    unsigned int errors;
    unsigned int i;

    if (count == 0)
        return;

    errors = 0;

    if (gettimeofday(&start, NULL) != 0) {
        printf("gettimeofday(start) failed\n");
        return;
    }

    for (i = 0; i < count; ++i) {
        if (usleep((unsigned long)ms * 1000UL) != 0)
            ++errors;
    }

    if (gettimeofday(&end, NULL) != 0) {
        printf("gettimeofday(end) failed\n");
        return;
    }

    requested_us = (unsigned long)ms
                 * 1000UL
                 * (unsigned long)count;

    actual_us = elapsed_us(&start, &end);
    average_us = actual_us / (unsigned long)count;
    error_us = (long)actual_us - (long)requested_us;

    printf("usleep %u ms x %u:\n", ms, count);

    printf("  requested=%lu us wall=%lu us avg=%lu us\n",
           requested_us,
           actual_us,
           average_us);

    printf("  wall error=%ld us errors=%u\n",
           error_us,
           errors);
}


static void run_precise_sleep_tests(void)
{
    test_precise_sleep(1, 20);
    test_precise_sleep(2, 20);
    test_precise_sleep(5, 20);
    test_precise_sleep(7, 20);
    test_precise_sleep(9, 20);
    test_precise_sleep(10, 20);
    test_precise_sleep(11, 20);
    test_precise_sleep(15, 20);
    test_precise_sleep(20, 20);
    test_precise_sleep(30, 20);

    /*
     * Longer single tests make coarse gettimeofday() resolution less
     * important.
     */
    test_precise_sleep(100, 1);
    test_precise_sleep(250, 1);
    test_precise_sleep(500, 1);
    test_precise_sleep(1000, 1);
}


static void run_usleep_tests(void)
{
    test_usleep(1, 20);
    test_usleep(2, 20);
    test_usleep(5, 20);
    test_usleep(7, 20);
    test_usleep(9, 20);
    test_usleep(10, 20);
    test_usleep(11, 20);
    test_usleep(15, 20);
    test_usleep(20, 20);
    test_usleep(30, 20);

    test_usleep(100, 1);
    test_usleep(250, 1);
    test_usleep(500, 1);
    test_usleep(1000, 1);
}


int main(void)
{
    printf("ELKS sleep comparison\n");
    printf("=====================\n\n");

    /*
     * init_ptime() locates the kernel jiffies value through /dev/kmem.
     */
    if (!init_ptime()) {
        printf("init_ptime failed\n");
        return 1;
    }

    printf("Timer resolution\n");
    printf("----------------\n");
    test_clock_resolution(20);
    test_ptime_resolution(20);

    printf("\nBusy-wait precise_sleep()\n");
    printf("-------------------------\n");
    run_precise_sleep_tests();

    printf("\nStandard usleep()\n");
    printf("-----------------\n");
    run_usleep_tests();

    return 0;
}

[toncho11]

I just wanted a few ms delay.

[ghaerr]

The likely cause is the case where the PIT counter wraps before the timer interrupt updates jiffies, while get_ptime() assumes that jdiff is already nonzero and executes jdiff--.

Oh my gosh, not another precision timer bug!! I'll take a look further into this. Thanks for the test program.

[ghaerr]

The likely cause is the case where the PIT counter wraps before the timer interrupt updates jiffies, while get_ptime() assumes that jdiff is already nonzero and executes jdiff--.

Can you show how that might happen? The code in get_ptime disables interrupts while accessing both jiffies as well as the PIT counter, so I'm not seeing where they can get out of sync:

unsigned long get_ptime(void)
{
    unsigned int pticks, jdiff;
    unsigned int lo, hi, count;
    flag_t flags;
    static unsigned int lastcount;

    save_flags(flags);
    clr_irq();                      /* synchronize countdown and jiffies */
    outb(0, TIMER_CMDS_PORT);       /* latch timer value */
    /* 16-bit subtract handles low word wrap automatically */
    jdiff = (unsigned)jiffies - (unsigned)lastjiffies;
    lastjiffies = (unsigned)jiffies; /* 16 bit save works for ~10.9 mins */
    lo = inb(TIMER_DATA_PORT);
    hi = inb(TIMER_DATA_PORT) << 8;
    restore_flags(flags);

    count = lo | hi;
    pticks = lastcount - count;
    lastcount = count;
    if ((int)pticks < 0) {          /* wrapped, jiffies is higher */
        pticks += MAX_PTICK;        /* = MAX_PTICK - count + lastcount */
        jdiff--;                    /* adjust jiffies for wrap, won't ever be negative */
    }

[ghaerr]

the PIT counter wraps before the timer interrupt updates jiffies,

Oh, you're saying that the PIT counter wraps, which immediately raises the HW clock interrupt, which then takes a hundred more instructions in the _irqit interrupt handler before jiffies is actually incremented?

I can see how that could seem like a problem, but the above code still grabs both the timer count as well as the associated jiffies with interrupts disabled, so that should not be a problem. Also, if we're only talking about a race condition that only happens during the above-described countdown -> jiffies increment delay, this should not affect measured results anywhere near the frequency which you're seeing it. This issue only happens once every 10ms, not every PIT clock countdown.

Still trying to understand what might be causing the issue you're seeing.

[toncho11]

I do not understand the subject very well. Main issue is that:

get_ptime() accumulated time is wrong in the test:

500 ms requested → get_ptime() says 500 ms, but wall time is 250 ms.
1000 ms requested → get_ptime() says 1000 ms, but wall time is 500 ms.

So it advances roughly twice as fast as ELKS system time.

But then we are measuring one thing with another that can also be unprecise so where exactly is the ground truth?

Here is a problematic result:

precise 121 ms x 1:                                                             
  requested=121000 us wall=60000 us avg=60000 us                                
  wall error=-61000 us                                                          
  ptime=121002 us avg=121002 us error=2 us                                      
  target=144378 ticks max_delta=12212 polls=50007 errors=0                      
precise 345 ms x 1:                                                             
  requested=345000 us wall=170000 us avg=170000 us                              
  wall error=-175000 us                                                         
  ptime=345003 us avg=345003 us error=3 us                                      
  target=411654 ticks max_delta=12188 polls=143361 errors=0                     
precise 546 ms x 1:                                                             
  requested=546000 us wall=280000 us avg=280000 us                              
  wall error=-266000 us                                                         
  ptime=547989 us avg=547989 us error=1989 us                                   
  target=651488 ticks max_delta=17295 polls=208982 errors=0                     
precise 1034 ms x 1:                                                            
  requested=1034000 us wall=520000 us avg=520000 us                             
  wall error=-514000 us                                                         
  ptime=1034004 us avg=1034004 us error=4 us  

[toncho11]

I am using https://copy.sh/v86/.
It can be an emulator problem: get_ptime() is approximately correct; v86 is delivering IRQ0/jiffies at about 50 Hz instead of the configured 100 Hz???

Actually 86box gives different result:

So v86 likely under-delivers PIT IRQ0 interrupts, making ELKS jiffies/gettimeofday() advance at about half speed while get_ptime() still reads the PIT counter directly.

[toncho11]

So I need a correct emulator and an export for OWC.

static void precise_sleep_ms(unsigned int ms)
{
    unsigned long remaining;
    unsigned long delta;

    remaining = ((unsigned long)ms * 11932UL + 9UL) / 10UL;

    (void)get_ptime();          /* establish start */

    while (remaining) {
        delta = get_ptime();

        if (delta >= remaining)
            break;

        remaining -= delta;
    }
}

The above is best for short waits, such as 1–20 ms. Longer waits should use normal usleep() first, then busy-wait for the final few milliseconds.