xtimer: add's items to the wrong list if the timer overflows between _xtimer_now() and irq_disable()

[DipSwitch]

I have a problem where xtimer_usleep thinks that it should place the timer into the timers long list while (timer->long_target > _long_cnt) are both 0 but || !_this_high_period(target) says it's not this period. But when the timer is added to the long list. It doesn't trigger for aprox 1,5 hour instead of in 69uS.

Below the log and possible solution to fix.

11:58:43:726	COM9	8	_xtimer_set64() offset=207 long_offset=0
11:58:43:726	COM9	8	timer_set(): offset=207 now=1524772 (17446)
11:58:43:726	COM9	8	timer_set_absolute(): now=1525813 target=1526018
11:58:43:726	COM9	8	timer_set_absolute(): timer will expire in this timer period.
11:58:43:726	COM9	8	timer_set_absolute(): timer is new list head. updating lltimer.
11:58:43:774	COM9	8	_xtimer_set64() offset=69 long_offset=0
11:58:43:793	COM9	8	timer_set(): offset=69 now=1526992 (19666)
11:58:43:793	COM9	8	timer_set_absolute(): now=1528012 target=1528079
11:58:43:793	COM9	8	timer_set_absolute(): timer will expire in this timer period.
11:58:43:794	COM9	8	timer_set_absolute(): timer is new list head. updating lltimer.
11:58:43:861	COM9	8	_xtimer_set64() offset=207 long_offset=0
11:58:43:861	COM9	8	timer_set(): offset=207 now=1529335 (22008)
11:58:43:861	COM9	8	timer_set_absolute(): now=1530376 target=1530581
11:58:43:861	COM9	8	timer_set_absolute(): timer will expire in this timer period.
11:58:43:861	COM9	8	timer_set_absolute(): timer is new list head. updating lltimer.
11:58:43:909	COM9	8	INF: irq: clear
11:58:43:909	COM9	8	INF: mode: command
11:58:43:936	COM9	9	INF: data recv: < 8
11:58:43:936	COM9	9	INF: irq: set
11:58:43:936	COM9	9	INF: data recv: < 8
11:58:43:936	COM9	9	INF: cmd proc: AT+HDL=1
11:58:43:937	COM9	9	INF: cmd resp: OK
11:58:43:937	COM9	9	INF: mode data: start write
11:58:43:937	COM9	9	_xtimer_set64() offset=207 long_offset=0
11:58:43:937	COM9	9	timer_set(): offset=207 now=1540075 (32748)
11:58:43:937	COM9	9	timer_set_absolute(): now=1541116 target=1541321
11:58:43:937	COM9	9	timer_set_absolute(): timer will expire in this timer period.
11:58:43:937	COM9	9	timer_set_absolute(): timer is new list head. updating lltimer.
11:58:44:008	COM9	9	_xtimer_set64() offset=207 long_offset=0
11:58:44:008	COM9	9	timer_set(): offset=207 now=1546722 (39395)
11:58:44:008	COM9	9	timer_set_absolute(): now=1547762 target=1547968
11:58:44:008	COM9	9	timer_set_absolute(): timer will expire in this timer period.
11:58:44:008	COM9	9	timer_set_absolute(): timer is new list head. updating lltimer.
11:58:44:056	COM9	9	INF: mode data: write 3 bytes
11:58:44:056	COM9	9	INF: data send: > 9
11:58:44:073	COM9	9	INF: mode: command
11:58:44:073	COM9	9	INF: cmd proc: AT+IRQ?1
11:58:44:073	COM9	9	INF: cmd resp: OK
11:58:44:095	COM9	9	INF: cmd proc: AT+IRQ=23
11:58:44:095	COM9	9	INF: cmd resp: OK
11:58:44:095	COM9	9	INF: mode data: send 3
11:58:44:095	COM9	9	_xtimer_set64() offset=207 long_offset=0
11:58:44:095	COM9	9	timer_set(): offset=207 now=1568667 (61340)
11:58:44:095	COM9	9	timer_set_absolute(): now=1569708 target=1569913
11:58:44:095	COM9	9	timer_set_absolute(): timer will expire in this timer period.
11:58:44:095	COM9	9	timer_set_absolute(): timer is new list head. updating lltimer.
11:58:44:162	COM9	9	_xtimer_set64() offset=69 long_offset=0
>> line of interrest 11:58:44:162	COM9	9	timer_set(): offset=69 now=1570886 (63559)
11:58:44:162	COM9	9	timer_set_absolute(): now=1571905 target=1571972
11:58:44:162	COM9	9	xtimer_set_absolute(): the timer doesn't fit into the low-level timer's mask.
11:58:45:106	COM9	9	Master error (IOException): No data received from the modem

To solve this problem xtimer_set_absolute should be changed to something like this:

int _xtimer_set_absolute_dbg(xtimer_t *timer, uint32_t target)
{
>>	/* move IRQ disable to top */
	unsigned state = irq_disable();
	if (_is_set(timer)) {
		_remove(timer);
	}

	uint32_t now = _xtimer_now();
>>	/* to avoid a race condition through printing or other interrupts interrupting the process and make less than 32 bit timers miss there overflow interrupt */
	int res = 0;

	printf("timer_set_absolute(): now=%" PRIu32 " target=%" PRIu32 "\n", now, target);

	timer->next = NULL;
	if ((target >= now) && ((target - XTIMER_BACKOFF) < now)) {
		/* backoff */
		irq_restore(state);
		xtimer_spin_until(target + XTIMER_BACKOFF);
		_shoot(timer);
		return 0;
	}

	timer->target = target;
	timer->long_target = _long_cnt;
	if (target < now) {
		timer->long_target++;
	}

	if ( (timer->long_target > _long_cnt) || !_this_high_period(target)) {
		if (timer->long_target == _long_cnt) {
			printf("xtimer_set_absolute(): increasing long count.\n");
	>> /* tried fix but didn't work */		//++timer->long_target;
		}
		else
			printf("xtimer_set_absolute(): the timer doesn't fit into the low-level timer's mask.\n");
		_add_timer_to_long_list(&long_list_head, timer);
	}
	else {
		if (_xtimer_lltimer_mask(now) >= target) {
			printf("xtimer_set_absolute(): the timer will expire in the next timer period\n");
			_add_timer_to_list(&overflow_list_head, timer);
		}
		else {
			printf("timer_set_absolute(): timer will expire in this timer period.\n");
			_add_timer_to_list(&timer_list_head, timer);

			if (timer_list_head == timer) {
				printf("timer_set_absolute(): timer is new list head. updating lltimer.\n");
				_lltimer_set(target - XTIMER_OVERHEAD);
			}
		}
	}

	irq_restore(state);

	return res;
}

[DipSwitch]

Possible related:

• tests: xtimer_drift gets stuck on native #6052
• xtimer: weird behavior of tests/xtimer_drift, bug? #5103

[DipSwitch]

Closed in favor of #7116

[kYc0o]

Why did you close it? is not an issue anymore?

[DipSwitch]

Closed in favor of PR #7116 ;)

[kYc0o]

Yes I see, but usually we keep issues open until the PR is merged...

[DipSwitch]

Fixed by: #7053

[jnohlgard]

I think I may be hitting this issue when I use a 32 kHz xtimer, I will report back once I have had time to run some tests.

[jnohlgard]

It seems my issue was fixed by relaxing the xtimer backoff timings, I don't think this issue was related.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. If you want me to ignore this issue, please mark it with the "State: don't stale" label. Thank you for your contributions.

[miri64]

@MichelRottleuthner is this still the case after the xtimer overhaul?

[maribu]

With xtimer on its way out and ztimer being used instead now every, I'd say this is a wontfix.

If anyone disagrees, please reopen.