[HELP] Unexpected result of scheduling testing.

[wangtao13]

Description

I want to compare the scheduler of Nuttx with other RTOS, so I wrote a simple test and run it in hello.c

static pthread_mutex_t g_mutex;
static volatile uint32_t g_count1 = 0;
static volatile uint32_t g_count2 = 0;
static volatile int isexit = 0;

static void *low_task1(char *argv)
{
    while (!isexit) {
        pthread_mutex_lock(&g_mutex);
        g_count1++;
        pthread_mutex_unlock(&g_mutex);
    }
    return 0;
}

static void * low_task2(char *arg)
{
    while (!isexit) {
        pthread_mutex_lock(&g_mutex);
        g_count2++;
        pthread_mutex_unlock(&g_mutex);
    }
    return 0;
}

static void *hi_task(char *argv)
{
    struct timespec start, end;
    uint32_t total_ops;
    double elapsed_ms;

    pthread_mutex_init(&g_mutex, NULL);

    clock_gettime(CLOCK_MONOTONIC, &start);

    sleep(5);

    clock_gettime(CLOCK_MONOTONIC, &end);

    total_ops = g_count1 + g_count2;
    elapsed_ms = (end.tv_sec - start.tv_sec) * 1000.0 +
                 (end.tv_nsec - start.tv_nsec) / 1000000.0;

    printf("Low task 1 count: %" PRIu32 "\n", g_count1);
    printf("Low task 2 count: %" PRIu32 "\n", g_count2);
    printf("Total operations: %" PRIu32 "\n", total_ops);
    printf("Elapsed time: %.2f ms\n", elapsed_ms);
    if (total_ops > 0) {
        printf("Average time per operation: %.3f us\n",
               (elapsed_ms * 1000.0) / total_ops);
    }

    pthread_mutex_destroy(&g_mutex);
    isexit = 1;

    return 0;
}

int cs_test_main(int argc, char *argv[])
{
    pthread_t hi, low1, low2;
    pthread_attr_t attr_hi, attr_low;
    struct sched_param param_hi, param_low;

    pthread_attr_init(&attr_hi);
    pthread_attr_init(&attr_low);

    param_hi.sched_priority = 200;
    pthread_attr_setschedpolicy(&attr_hi, SCHED_RR);
    pthread_attr_setschedparam(&attr_hi, &param_hi);
    pthread_attr_setinheritsched(&attr_low, PTHREAD_EXPLICIT_SCHED);

    if (pthread_create(&hi, &attr_hi, hi_task, NULL) != 0) {
        perror("pthread_create hi");
        return 1;
    }

    if (pthread_create(&low1, &attr_low, low_task1, NULL) != 0) {
        perror("pthread_create low1");
        return 1;
    }
    if (pthread_create(&low2, &attr_low, low_task2, NULL) != 0) {
        perror("pthread_create low2");
        return 1;
    }

    pthread_attr_destroy(&attr_hi);
    pthread_attr_destroy(&attr_low);

    pthread_join(hi, NULL);
    pthread_join(low1, NULL);
    pthread_join(low2, NULL);

    return 0;
}

A high prio task sleeps 5 seconds, then 2 lower tasks runs in ping-pong way be getting/putting mutex. After 5 seconds, high task shows the results.

Here is my testing results.

Low task 1 count: 1828625
Low task 2 count: 1716974
Total operations: 3545599
Elapsed time: *float* ms
Average time per operation: *float* us

In the same hardware, another RTOS got followings.

Low task 1 count: 1519473
Low task 2 count: 1519472
Total operations: 3038945

The Nuttx's configuration of scheduler is

CONFIG_RR_INTERVAL=200
# CONFIG_SCHED_SPORADIC is not set

I tested in qemu-arma7 with SCHED configurations,

cat .config | grep SCHED
# CONFIG_DEBUG_SCHED is not set
# CONFIG_SCHED_TICKLESS is not set
# CONFIG_SCHED_SPORADIC is not set
CONFIG_SCHED_HAVE_PARENT=y
# CONFIG_SCHED_CHILD_STATUS is not set
CONFIG_SCHED_WAITPID=y
# CONFIG_SCHED_DUMP_LEAK is not set
# CONFIG_SCHED_DUMP_ON_EXIT is not set
# CONFIG_SCHED_USER_IDENTITY is not set
# CONFIG_SCHED_THREAD_LOCAL is not set
# CONFIG_SCHED_IRQMONITOR is not set
# CONFIG_SCHED_CRITMONITOR is not set
CONFIG_SCHED_CPULOAD_NONE=y
# CONFIG_SCHED_CPULOAD_SYSCLK is not set
# CONFIG_SCHED_CPULOAD_EXTCLK is not set
CONFIG_SCHED_CPULOAD_TICKSPERSEC=100
CONFIG_SCHED_PROFILE_TICKSPERSEC=1000
# CONFIG_SCHED_INSTRUMENTATION is not set
CONFIG_SCHED_STACK_RECORD=0
CONFIG_SCHED_WORKQUEUE=y
CONFIG_SCHED_HPWORK=y
CONFIG_SCHED_HPNTHREADS=1
CONFIG_SCHED_HPWORKPRIORITY=192
CONFIG_SCHED_HPWORKSTACKSIZE=4096
CONFIG_SCHED_HPWORKSTACKSECTION=""
# CONFIG_SCHED_LPWORK is not set
# CONFIG_SCHED_BACKTRACE is not set
# CONFIG_SCHED_EVENTS is not set

and got this,

nsh> hello
Low task 1 count: 4312752
Low task 2 count: 3142026
Total operations: 7454778
Elapsed time: 5001.00 ms

My question is: Why counts of 2 two lower prio tasks are different too much, while in another RTOS, the two counts are very close?

Verification

• I have verified before submitting the report.

[hitHuang]

Two mechanisms combine to produce the imbalance — this is a statistical effect, not a scheduler bias toward either thread.

First, the mutex's fast path is scheduler-transparent. With pthread_mutex_init(&g_mutex, NULL), the protocol is SEM_PRIO_NONE, so nxsem_wait()/nxsem_post() (sem_wait.c:170-199, sem_post.c:147-176) use atomic_try_cmpxchg when uncontended — plain
atomic ops, no interrupt masking, no preemption disable. The scheduler cannot tell whether a thread is inside the critical section or not, so a timer tick can land there just as easily as anywhere else.

Second, nxsched_process_roundrobin() (sched_roundrobin.c) always resets the expiring thread's timeslice back to full before checking whether the next same-priority thread should actually get the CPU. Refilling the timeslice and switching are
separate steps; the first always happens, the second is conditional.

Combined: if a timeslice expiry lands exactly while the running thread holds the mutex, the scheduler still switches — it has no visibility into lock state. The incoming thread immediately fails the mutex fast path, falls into the slow path, and
blocks. The CPU falls straight back to the thread that was just switched out — which already got its timeslice reset to full. It effectively gets a whole extra timeslice for free, while the other thread contributes nothing this round and must
requeue for the next expiry.

Since the loop body is just lock/increment/unlock with no other work, the critical section occupies a non-trivial fraction of each iteration, so this collision isn't rare. With CONFIG_RR_INTERVAL=200 over 5 seconds there are only ~25 expiry checks
total; a handful of collisions favoring the same thread is enough to snowball into the reported 10%-37% gap. Shortening the timeslice increases the sample count and narrows the skew statistically, but doesn't remove the mechanism.

Worked example

CONFIG_RR_INTERVAL=200, 1ms tick. A = low_task1, B = low_task2, equal priority.

t=0: A runs, B queued behind it, A's timeslice = 200.

t=200: A's timeslice expires. Scheduler resets it to 200, sees B is next with equal priority, switches to B. A requeues behind B.

t=200~400: B runs exclusively. Just before t=400, B has just acquired the lock but hasn't unlocked yet — mutex holder is B.

t=400: B's timeslice expires (lock state isn't checked). Scheduler resets B's timeslice to 200, sees A is next, switches to A.

t=400+ε: A resumes, immediately calls lock. Fast path sees B as holder, CAS fails, A falls to the slow path, blocks, and is removed from the ready queue. B is now the only runnable thread, so the CPU switches straight back to B.

t=400+ε~600+ε: B finishes its count2++/unlock, hands the mutex to A and requeues A (no preemption on equal priority — A doesn't get the CPU yet), then keeps running lock/count2++/unlock until its timeslice (reset at t=400) runs out again, around
t=600.

t≈600+ε: Scheduler switches to A, which finally runs a clean full timeslice.

Net effect: B runs continuously from t=200 to ~t=600 — almost 400ms, two timeslices back to back — while A is skipped for a full round, only touching the CPU long enough to fail one lock attempt. One such collision hands B a full extra timeslice
at A's expense; a few of these across ~25 expiry checks in 5 seconds account for the observed imbalance.

[wangtao13]

Thanks for sharing the scheduler internal, it really helps me understanding the Nuttx scheduling.

I changed the RR interval to 20 mseconds (the HZ is 100), and I got a littler better result as follows,

Low task 1 count: 1743344
Low task 2 count: 1801614
Total operations: 3544958

Then I configured the HZ to 1000 (1ms per tick), I got following result.

Low task 1 count: 1261959
Low task 2 count: 1204638
Total operations: 2466597

Then I re-ran the test with HZ of 1000, RR interval of 100, and got following result.

Low task 1 count: 1573778
Low task 2 count: 1364891
Total operations: 2938669

The other RTOS has the HZ of 1000, and its result is as follows (and almost constant).

Low task 1 count: 1519473
Low task 2 count: 1519472
Total operations: 3038945

With the 1000Hz, it seemd that Nuttx scheduling performance is almost the same as the other RTOS with the same 1000Hz.

Here comes several questions:

1. It seemed the overhead of 1000Hz is big, which causes the counting has 30% off than 100Hz, is it expected?
2. Is there benchmark of Nuttx scheduler (and comparison with other RTOS, e.g. FreeRTOS, Zephyr, RT-Thread and etc)?
3. Is there any other right and precise way to test OS scheduler?

Thanks,