ovidiusas
commented
2 years ago Another scenario that is generating bogs warning logs.
The (u)timer_ticker() is dispatching a timer task inside the timer process. Right after the write, the ijiffies are updated by the run_timer_process_jif() in the time_keeper process. After that, the timer task is dequeued by the "Timer handler" proc, the trigger time was set to the value of the ijiffies before the periodic update done by the run_timer_process_jif() and the ijiffies are now updated with a delta that is bigger then the ITIMER_TICK value. As a result, a warning is generated with a reported delay equal to the delta of the last ijiffies update.
github-actions[bot]
volga629-1
OpenSIPS version you are running
All recent versions of opensips.
Describe the bug
The ijiffies are adjusted every 5 min by the run_timer_process_jif() in a dedicated proc named time_keeper.
The timer tasks are dispatched by the run_timer_process() in a dedicated proc named timer. Before dispatching the time jobs, the wait time between each job dispatch is computed via compute_wait_with_drift() and the jobs are dispatched via (u)timer_ticker() procedure. Most of the time (u)timer_ticker() procedure doesn't need to dispatch any jobs (on most deployments it is called every 100ms and for tm-timer is called every 10th iteration and for tm-utimer is called every 2nd iteration).
If the ijiffies are adjusted at the same time when a timer is scheduled for execution, we will have a false warning about the timer being late. This is happening when the ijiffies are adjusted after the trigger_time is set inside the (u)timer_ticker in the timer process and before the timer task is handled by the handle_timerjob() inside the "Timer handled" proc.
This could be avoided by keeping track of the ijiffies drift and tacking that into consideration while evaluating the print of the warning (in addition to the ITIMER_TICK).