zsock_select/zsock_poll API timeout overrun uncertainty

[bob2oneil]

While my testing was using the zsock_select() API, since it appears to be a wrapper on the zsock_poll() API, I believe this issue applies to both APIs (z_impl_zsock_select calls zsock_poll_internal).

I have used this statement in both desktop and embedded Linux for multiplexed i/o with sockets, but it also to provide a high precision timer mechanism for epoch based activities. The specification for the Linux "select" statement indicates that when the thread pending on this statement is awaken due to a timeout condition, "that the blocking interval may overrun by a small amount", where this amount is not specified in the function definition - but in my experience was measured in single and double digit microseconds.

https://man7.org/linux/man-pages/man2/select.2.html

In my current Zephyr experience, I am finding this small amount to be measured in 2 to 6 milliseconds with some operational frequency as many times per second.

An example log is show as follows, where the conditions for zsock_select() are logged as "select IN" where for testing, I am using a fixed timeout of 500 usec only. Nominally, the timeout value used would be the time until the start of the next 10 ms epoch.

The "select OUT" statement is written only when the elapsed time that the thread was pending in the zsock_select() statement measured exceeds the 500 used timeout. I am using the system time at a 10 ms epoch rate, where I need to hit the epoch boundary with an accuracy to hundreds of microseconds. This sample shows an elapsed time of almost 3 ms whereas the timeout value into the API is 500 microseconds, a six fold "overrun".

I am trying to understand why this thread wake up on timeout condition has significant "overrun" relative to my embedded Linux experiences - and if there is anything that I can do about it to be able to used this statement for high precision timing.

If this is simply the way it behaves, and that behavior is well understood, perhaps a suggestion on an implementation using a Zephyr timer would be appreciated.

select() IN [epoch 17]: now (17882/177879), timeout (0/500), m_tvNextEpoch (17882/180000)
select() IN [epoch 17]: now (17882/177909), timeout (0/500), m_tvNextEpoch (17882/180000)
select() IN [epoch 17]: now (17882/177995), timeout (0/500), m_tvNextEpoch (17882/180000)
select() IN [epoch 17]: now (17882/178511), timeout (0/500), m_tvNextEpoch (17882/180000)
select() IN [epoch 17]: now (17882/178929), timeout (0/500), m_tvNextEpoch (17882/180000)
select() IN [epoch 17]: now (17882/179438), timeout (0/500), m_tvNextEpoch (17882/180000)
select() IN [epoch 17]: now (17882/179865), timeout (0/500), m_tvNextEpoch (17882/180000)
select() IN [epoch 18]: now (17882/180038), timeout (0/500), m_tvNextEpoch (17882/190000)
select() IN [epoch 18]: now (17882/180169), timeout (0/500), m_tvNextEpoch (17882/190000)
select() OUT[epoch 18]: now (17882/181122), timeout (0/500), tvNextEpoch (17882/190000), elapsed (0/953), count 0
select() IN [epoch 18]: now (17882/181138), timeout (0/500), m_tvNextEpoch (17882/190000)
select() IN [epoch 18]: now (17882/181354), timeout (0/500), m_tvNextEpoch (17882/190000)
select() OUT[epoch 18]: now (17882/184346), timeout (0/500), tvNextEpoch (17882/190000), elapsed (0/2992), count 0
select() IN [epoch 18]: now (17882/184375), timeout (0/500), m_tvNextEpoch (17882/190000)
select() IN [epoch 18]: now (17882/184659), timeout (0/500), m_tvNextEpoch (17882/190000)
select() IN [epoch 18]: now (17882/184850), timeout (0/500), m_tvNextEpoch (17882/190000)
select() IN [epoch 18]: now (17882/184879), timeout (0/500), m_tvNextEpoch (17882/190000)
select() IN [epoch 18]: now (17882/184967), timeout (0/500), m_tvNextEpoch (17882/190000)
select() IN [epoch 18]: now (17882/185049), timeout (0/500), m_tvNextEpoch (17882/190000)
select() IN [epoch 18]: now (17882/185189), timeout (0/500), m_tvNextEpoch (17882/190000)
select() IN [epoch 18]: now (17882/185443), timeout (0/500), m_tvNextEpoch (17882/190000)
select() OUT[epoch 18]: now (17882/186033), timeout (0/500), tvNextEpoch (17882/190000), elapsed (0/590), count 0
select() IN [epoch 18]: now (17882/186045), timeout (0/500), m_tvNextEpoch (17882/190000)
select() IN [epoch 18]: now (17882/186370), timeout (0/500), m_tvNextEpoch (17882/190000)
select() IN [epoch 18]: now (17882/186482), timeout (0/500), m_tvNextEpoch (17882/190000)

[jukkar]

According to the code, the poll should give slightly better results as select does a bit more processing, but that does not explain the several millisecond delay.

What hw this is?

Note that for offloaded drivers, the resolution is milliseconds (instead of microseconds) for the poll/select API.

zephyr/subsys/net/lib/sockets/sockets.c

Lines 1594 to 1606 in 868b180

	if (offload) {
	int poll_timeout;
	if (K_TIMEOUT_EQ(timeout, K_FOREVER)) {
	poll_timeout = SYS_FOREVER_MS;
	} else {
	poll_timeout = k_ticks_to_ms_floor32(timeout.ticks);
	}
	return z_fdtable_call_ioctl(offl_vtable, offl_ctx,
	ZFD_IOCTL_POLL_OFFLOAD,
	fds, nfds, poll_timeout);
	}

[bob2oneil]

Hi Jukka, I did some rework using zsock_poll() instead, which longer term is a problem because it uses a timeout in milliseconds (whereas I need microseconds). The zsock_poll_internal fails to link so I could not use that directly as it does support microsecond precision timeouts. I would prefer to use zsock_poll(), but consistent with the POSIX API, the timeout specified is in milliseconds, which internally get coverted into microseconds. If zsock_poll_internal were to be externally exposed for linking (or you have ideas on how to do that), then I could test out microsecond timing. The efficiency of zsock_poll over zsock_select is desirably for me should the higher precision timeout be exposed -- but I understand that would deviate from the POSIX spec.

The board target for my current testing is Native-POSIX, that is, a Linux desktop, a high powered Intel NUC with 8 cores. I run HTOP in the background to see if the slipping seems to correspond to an overloaded processor, and nothing seems to correlate and the CPUs are not railed.

I assume that this will represent the actual hardware - but that could be a failed assumption and something specific to this emulation board target. Using zsock_poll() instead of zsock_select(), and rounding down my higher precision microsecond timeout values into milliseconds, I still encounter the problem, that is the return from zsock_poll() can greatly exceed the timeout value specified - in some cases by many milliseconds. It does not happen all the time, but using a 10 ms epoch, or 100 epochs in a second, I often get around 5 percent missed epochs relative to timeout values which are correct going into zsock_poll/zsock_select to cause thread wakeup at the epoch boundary (determined from system clock reads).

t could be that this is an issue with Native-POSIX only - I have no way of knowing until we get a hardware board to test with.

If so, is there some logic using Native-POSIX emulation that might explain it (maybe something like under Native-POSIX, the OS performs some form of background activity in one of the Zephyr higher priority threads that causes this thread to suspend occasionally for several milliseconds).

The list of the application threads and priorities are as follows. The thread that handles the socket is the Zephyr main thread with a priority of 0.

~$ kernel threads

Scheduler: 0 since last call
Threads:
 0x140d8c0 ddlt_udp_server
	options: 0x0, priority: 20 timeout: 0
	state: pending, entry: 0x424fde
	stack size 2048, unused 2008, usage 40 / 2048 (1 %)

*0x14a0f40 shell_telnet
	options: 0x0, priority: 14 timeout: 0
	state: queued, entry: 0x437ec3
	stack size 4096, unused 4056, usage 40 / 4096 (0 %)

 0x1570a98 rx_q[0]   
	options: 0x0, priority: -1 timeout: 0
	state: pending, entry: 0x44d5d4
	stack size 1504, unused 1464, usage 40 / 1504 (2 %)

 0x1571ac0 eth_native_posix_rx-zeth1.1
	options: 0x0, priority: -2 timeout: 4
	state: suspended, entry: 0x458aa9
	stack size 40, unused 0, usage 40 / 40 (100 %)

 0x1571bc0 eth_native_posix_rx-zeth1.0
	options: 0x0, priority: -2 timeout: 0
	state: suspended, entry: 0x458aa9
	stack size 40, unused 0, usage 40 / 40 (100 %)

 0x1570bd8 tx_q[0]   
	options: 0x0, priority: -1 timeout: 0
	state: queued, entry: 0x44d4fc
	stack size 1200, unused 1160, usage 40 / 1200 (3 %)

 0x14a4c80 net_mgmt  
	options: 0x0, priority: -1 timeout: 0
	state: pending, entry: 0x449a99
	stack size 768, unused 728, usage 40 / 768 (5 %)

 0x1571000 tcp_work  
	options: 0x0, priority: -16 timeout: 0
	state: pending, entry: 0x461edc
	stack size 1024, unused 984, usage 40 / 1024 (3 %)

 0x1571f20 sysworkq  
	options: 0x0, priority: -1 timeout: 0
	state: pending, entry: 0x461edc
	stack size 1024, unused 984, usage 40 / 1024 (3 %)

 0x14a09a0 shell_uart
	options: 0x0, priority: 14 timeout: 0
	state: pending, entry: 0x437ec3
	stack size 4096, unused 4056, usage 40 / 4096 (0 %)

 0x1571cc0 idle      
	options: 0x1, priority: 15 timeout: 0
	state: , entry: 0x461431
	stack size 256, unused 216, usage 40 / 256 (15 %)

 0x1571dc0 main      
	options: 0x1, priority: 0 timeout: 1
	state: pending, entry: 0x460a32
	stack size 2048, unused 2008, usage 40 / 2048 (1 %)

[jukkar]

In my experience, all performance numbers are unreliable if you are using native-posix board. So I would suggest you try your tests with real hw to get meaningful numbers.

[bob2oneil]

Thanks, that will be my next step. Another thought I had was to determine if my reference clock was entirely reliable. and not subject to any skips that would convey a larger time when the select()/poll() yielded back to the OS under Native-POSIX. The clock if I understand correctly should be monotonic and not subject to any form of adjustment, but maybe you have some opinion. Elapsed time is measured as the difference between 2 timeval values both using the same function to obtain wall clock time.

What would it take to make the zsock_poll_internal, which uses microsecond timeouts, publicly available with changing the Zephyr source code?

Here is my get wall clock time (in standard timeval):

int TimeUtils::getTime(timeval *time, bool getTimeOfDay)
{
    // Zephyr POSIX implementation, equivalent to k_uptime_ticks().
    // https://docs.zephyrproject.org/latest/reference/kernel/timing/clocks.html#kernel-timing-uptime
    struct timespec ts = {0, 0};

    /*
     * `k_uptime_get` returns a timestamp based on an always increasing
     * value from the system start.  To support the `CLOCK_REALTIME`
     * clock, this `rt_clock_base` records the time that the system was
     * started.  This can either be set via 'clock_settime', or could be
     * set from a real time clock, if such hardware is present.
     */
    clockid_t clockId = getTimeOfDay ? CLOCK_REALTIME : CLOCK_MONOTONIC;

    int rc = clock_gettime(clockId, &ts);
    if (rc != 0)
    {
        LOG_ERR("clock_gettime(): clock returns error return code %d - %s", rc, strerror(errno));
    }

    if (!ts.tv_sec)
    {
        LOG_ERR("clock_gettime(): clock returns zero value for seconds");
    }

    // Convert timespec into timeval
    time->tv_sec = ts.tv_sec;
    time->tv_usec = ts.tv_nsec / 1000;

#ifdef LOG_GETTIME
    LOG_DBG("clock_gettime(): returns timeval: sec=%ld, usec=%ld", time->tv_sec, time->tv_usec);
#endif

    return rc;
}