Hello Henning,

Thanks for answering.

> Did you check eventual issues from virtual machine or time sync services?

I haven't noticed anything unsual.

> Is the machine/service under high load?

No

> Do you have many timers running in parallel? You could try playing around with the read_time and timer priority parameters in core.

I'll take a look, thanks.

FYI, I have done a test where I added a log line inside the loop to update the number of ticks (https://github.com/kamailio/kamailio/blob/master/src/core/timer.c#L917-L918). It looks like when the the behavior I'm talking about happens, this loop needs to be run many times because the value was outdated, which means that the timers that were added after the first tick, are going to be fired before they should.

I'm going to test the flags you mentioned and see if the problem still happens.

Thank you

On Wed, Feb 9, 2022 at 10:21 AM Henning Westerholt <hw@gilawa.com> wrote:

Hello Alberto,

 

normally the timer should be stable and not jumping around.

 

Did you check eventual issues from virtual machine or time sync services? The time should not jump around.

Is the machine/service under high load? If yes, you could  consider using dedicated timer processes for some modules.

Do you have many timers running in parallel? You could try playing around with the read_time and timer priority parameters in core.

 

Cheers,

 

Henning

 

--

Henning Westerholt – https://skalatan.de/blog/

Kamailio services – https://gilawa.com

 

From: sr-dev <sr-dev-bounces@lists.kamailio.org> On Behalf Of Alberto Izquierdo
Sent: Tuesday, February 8, 2022 9:04 AM
To: sr-dev@lists.kamailio.org
Subject: [sr-dev] Timers firing too soon

 

Hi all,

 

I'm using Kamailio timers to execute a series of calls with a certain delay. I have found out that from time to time, the timers are triggered too soon, sometimes they are triggered 2/3 seconds before they should.

 

There is nothing significant in the logs, some of the log lines previous to the premature call are:

 

10(16136) DEBUG: tm [timer.c:606]: wait_handler(): WAIT timer hit @1111936903 for 0x7f32cc4eede8 (timer_lm 0x7f32cc4eee70)
10(16136) DEBUG: tm [timer.c:643]: wait_handler(): finished transaction: 0x7f32cc4eede8 (p:0x7f32cc34ee90/n:0x7f32cc34ee90)
10(16136) DEBUG: tm [h_table.c:132]: free_cell_helper(): freeing transaction 0x7f32cc4eede8 from timer.c:652

 

And some other ones after the call are

 

10(16136) DEBUG: tm [timer.c:494]: retr_buf_handler(): timer retr_buf_handler @1111937043 (0x7f32cc4efa18 -> 0x7f32cc4ef9f8 -> 0x7f32cc4ef6d8)
10(16136) DEBUG: tm [timer.c:545]: retr_buf_handler(): new interval 2000 ms / 16 ticks (max 4000 ms)
10(16136) DEBUG: tm [timer.c:329]: retransmission_handler(): request resending (t=0x7f32cc4ef6d8, SUBSCRIBE ... )
10(16136) DEBUG: tm [timer.c:573]: retr_buf_handler(): timer retr_buf_handler @1111937043 (0x7f32cc4efa18 ->0x7f32cc4ef9f8->0x7f32cc4ef6d8) exiting min (16, 24)

 

I have read in the documentation that it is normal to have a bit of delay in some of the timers, but it doesn't mention anything about this behavior. Is this normal?

 

Thank you.