Hello!

*Sep 5 08:07:59 kamailio[1603]: 12(1603) WARNING: <core> [core/timer.c:936]: timer_handler(): slow timer too slow: overflow (0 - 64673 = -64673)*

I caught the problem again, here is the output of the commands that you recommended to check:

root@kamailio:/home/azureuser# kamctl ps { "jsonrpc": "2.0", "result": [ { "IDX": 0, "PID": 1574, "DSC": "main process - attendant" }, { "IDX": 1, "PID": 1592, "DSC": "udp receiver child=0 sock=192.168.20.20:5060 ( 20.20.20.20:5060)" }, { "IDX": 2, "PID": 1593, "DSC": "udp receiver child=1 sock=192.168.20.20:5060 ( 20.20.20.20:5060)" }, { "IDX": 3, "PID": 1594, "DSC": "udp receiver child=0 sock=192.168.20.20:5080" }, { "IDX": 4, "PID": 1595, "DSC": "udp receiver child=1 sock=192.168.20.20:5080" }, { "IDX": 5, "PID": 1596, "DSC": "udp receiver child=2 sock=192.168.20.20:5080" }, { "IDX": 6, "PID": 1597, "DSC": "udp receiver child=3 sock=192.168.20.20:5080" }, { "IDX": 7, "PID": 1598, "DSC": "udp receiver child=4 sock=192.168.20.20:5080" }, { "IDX": 8, "PID": 1599, "DSC": "udp receiver child=5 sock=192.168.20.20:5080" }, { "IDX": 9, "PID": 1600, "DSC": "udp receiver child=6 sock=192.168.20.20:5080" }, { "IDX": 10, "PID": 1601, "DSC": "udp receiver child=7 sock=192.168.20.20:5080" }, { "IDX": 11, "PID": 1602, "DSC": "slow timer" }, { "IDX": 12, "PID": 1603, "DSC": "timer" }, { "IDX": 13, "PID": 1604, "DSC": "secondary timer" }, { "IDX": 14, "PID": 1605, "DSC": "JSONRPCS FIFO" }, { "IDX": 15, "PID": 1606, "DSC": "JSONRPCS DATAGRAM" }, { "IDX": 16, "PID": 1607, "DSC": "USRLOC Timer" }, { "IDX": 17, "PID": 1608, "DSC": "ctl handler" }, { "IDX": 18, "PID": 1609, "DSC": "DMQ WORKER" }, { "IDX": 19, "PID": 1610, "DSC": "DMQ WORKER" }, { "IDX": 20, "PID": 1611, "DSC": "DMQ WORKER" }, { "IDX": 21, "PID": 1612, "DSC": "DMQ WORKER" }, { "IDX": 22, "PID": 1613, "DSC": "TIMER NH" }, { "IDX": 23, "PID": 1614, "DSC": "Dialog Clean Timer" }, { "IDX": 24, "PID": 1615, "DSC": "TIMER UAC REG" }, { "IDX": 25, "PID": 1616, "DSC": "RTIMER EXEC child=0 timer=uac" }, { "IDX": 26, "PID": 1617, "DSC": "RTIMER EXEC child=0 timer=cluster" }, { "IDX": 27, "PID": 1618, "DSC": "RTIMER EXEC child=0 timer=apiban" }, { "IDX": 28, "PID": 1619, "DSC": "tcp receiver (generic) child=0" }, { "IDX": 29, "PID": 1620, "DSC": "tcp receiver (generic) child=1" }, { "IDX": 30, "PID": 1621, "DSC": "tcp receiver (generic) child=2" }, { "IDX": 31, "PID": 1622, "DSC": "tcp receiver (generic) child=3" }, { "IDX": 32, "PID": 1623, "DSC": "tcp receiver (generic) child=4" }, { "IDX": 33, "PID": 1624, "DSC": "tcp receiver (generic) child=5" }, { "IDX": 34, "PID": 1625, "DSC": "tcp receiver (generic) child=6" }, { "IDX": 35, "PID": 1626, "DSC": "tcp receiver (generic) child=7" }, { "IDX": 36, "PID": 1627, "DSC": "tcp main process" } ], "id": 33990 }

root@kamailio:/home/azureuser# kamctl rpc pkg.stats { "jsonrpc": "2.0", "result": [ { "entry": 0, "pid": 1574, "rank": 0, "used": 1797960, "free": 14249896, "real_used": 2527320, "total_size": 16777216, "total_frags": 27, "desc": "main process - attendant" }, { "entry": 1, "pid": 1592, "rank": 1, "used": 14690568, "free": 49800, "real_used": 16727416, "total_size": 16777216, "total_frags": 7, "desc": "udp receiver child=0 sock=192.168.20.20:5060 ( 20.20.20.20:5060)" }, { "entry": 2, "pid": 1593, "rank": 2, "used": 14734792, "free": 1208, "real_used": 16776008, "total_size": 16777216, "total_frags": 8, "desc": "udp receiver child=1 sock=192.168.20.20:5060 ( 20.20.20.20:5060)" }, { "entry": 3, "pid": 1594, "rank": 3, "used": 1798184, "free": 14249256, "real_used": 2527960, "total_size": 16777216, "total_frags": 27, "desc": "udp receiver child=0 sock=192.168.20.20:5080" }, { "entry": 4, "pid": 1595, "rank": 4, "used": 1798184, "free": 14249256, "real_used": 2527960, "total_size": 16777216, "total_frags": 27, "desc": "udp receiver child=1 sock=192.168.20.20:5080" }, { "entry": 5, "pid": 1596, "rank": 5, "used": 1798184, "free": 14249256, "real_used": 2527960, "total_size": 16777216, "total_frags": 27, "desc": "udp receiver child=2 sock=192.168.20.20:5080" }, { "entry": 6, "pid": 1597, "rank": 6, "used": 1798184, "free": 14249256, "real_used": 2527960, "total_size": 16777216, "total_frags": 27, "desc": "udp receiver child=3 sock=192.168.20.20:5080" }, { "entry": 7, "pid": 1598, "rank": 7, "used": 1798184, "free": 14249256, "real_used": 2527960, "total_size": 16777216, "total_frags": 27, "desc": "udp receiver child=4 sock=192.168.20.20:5080" }, { "entry": 8, "pid": 1599, "rank": 8, "used": 1798184, "free": 14249256, "real_used": 2527960, "total_size": 16777216, "total_frags": 27, "desc": "udp receiver child=5 sock=192.168.20.20:5080" }, { "entry": 9, "pid": 1600, "rank": 9, "used": 1798184, "free": 14249256, "real_used": 2527960, "total_size": 16777216, "total_frags": 27, "desc": "udp receiver child=6 sock=192.168.20.20:5080" }, { "entry": 10, "pid": 1601, "rank": 10, "used": 1798184, "free": 14249256, "real_used": 2527960, "total_size": 16777216, "total_frags": 27, "desc": "udp receiver child=7 sock=192.168.20.20:5080" }, { "entry": 11, "pid": 1602, "rank": -1, "used": 1799296, "free": 14248040, "real_used": 2529176, "total_size": 16777216, "total_frags": 26, "desc": "slow timer" }, { "entry": 12, "pid": 1603, "rank": -1, "used": 1798160, "free": 14249280, "real_used": 2527936, "total_size": 16777216, "total_frags": 27, "desc": "timer" }, { "entry": 13, "pid": 1604, "rank": -1, "used": 1798160, "free": 14249280, "real_used": 2527936, "total_size": 16777216, "total_frags": 27, "desc": "secondary timer" }, { "entry": 14, "pid": 1605, "rank": -2, "used": 1798056, "free": 14249488, "real_used": 2527728, "total_size": 16777216, "total_frags": 27, "desc": "JSONRPCS FIFO" }, { "entry": 15, "pid": 1606, "rank": -2, "used": 1863512, "free": 14183928, "real_used": 2593288, "total_size": 16777216, "total_frags": 27, "desc": "JSONRPCS DATAGRAM" }, { "entry": 16, "pid": 1607, "rank": -1, "used": 1798160, "free": 14249280, "real_used": 2527936, "total_size": 16777216, "total_frags": 27, "desc": "USRLOC Timer" }, { "entry": 17, "pid": 1608, "rank": -2, "used": 1808104, "free": 14239232, "real_used": 2537984, "total_size": 16777216, "total_frags": 27, "desc": "ctl handler" }, { "entry": 18, "pid": 1609, "rank": -2, "used": 1798056, "free": 14249488, "real_used": 2527728, "total_size": 16777216, "total_frags": 27, "desc": "DMQ WORKER" }, { "entry": 19, "pid": 1610, "rank": -2, "used": 1798056, "free": 14249488, "real_used": 2527728, "total_size": 16777216, "total_frags": 27, "desc": "DMQ WORKER" }, { "entry": 20, "pid": 1611, "rank": -2, "used": 1798056, "free": 14249488, "real_used": 2527728, "total_size": 16777216, "total_frags": 27, "desc": "DMQ WORKER" }, { "entry": 21, "pid": 1612, "rank": -2, "used": 1798056, "free": 14249488, "real_used": 2527728, "total_size": 16777216, "total_frags": 27, "desc": "DMQ WORKER" }, { "entry": 22, "pid": 1613, "rank": -1, "used": 1798160, "free": 14249280, "real_used": 2527936, "total_size": 16777216, "total_frags": 27, "desc": "TIMER NH" }, { "entry": 23, "pid": 1614, "rank": -1, "used": 1798160, "free": 14249280, "real_used": 2527936, "total_size": 16777216, "total_frags": 27, "desc": "Dialog Clean Timer" }, { "entry": 24, "pid": 1615, "rank": -1, "used": 1798744, "free": 14246720, "real_used": 2530496, "total_size": 16777216, "total_frags": 26, "desc": "TIMER UAC REG" }, { "entry": 25, "pid": 1616, "rank": -1, "used": 1798272, "free": 14248960, "real_used": 2528256, "total_size": 16777216, "total_frags": 28, "desc": "RTIMER EXEC child=0 timer=uac" }, { "entry": 26, "pid": 1617, "rank": -1, "used": 1799344, "free": 14247888, "real_used": 2529328, "total_size": 16777216, "total_frags": 27, "desc": "RTIMER EXEC child=0 timer=cluster" }, { "entry": 27, "pid": 1618, "rank": -1, "used": 1794504, "free": 14252728, "real_used": 2524488, "total_size": 16777216, "total_frags": 28, "desc": "RTIMER EXEC child=0 timer=apiban" }, { "entry": 28, "pid": 1619, "rank": 11, "used": 1878904, "free": 14168328, "real_used": 2608888, "total_size": 16777216, "total_frags": 27, "desc": "tcp receiver (generic) child=0" }, { "entry": 29, "pid": 1620, "rank": 12, "used": 1878904, "free": 14168328, "real_used": 2608888, "total_size": 16777216, "total_frags": 27, "desc": "tcp receiver (generic) child=1" }, { "entry": 30, "pid": 1621, "rank": 13, "used": 1878904, "free": 14168328, "real_used": 2608888, "total_size": 16777216, "total_frags": 27, "desc": "tcp receiver (generic) child=2" }, { "entry": 31, "pid": 1622, "rank": 14, "used": 1878904, "free": 14168328, "real_used": 2608888, "total_size": 16777216, "total_frags": 27, "desc": "tcp receiver (generic) child=3" }, { "entry": 32, "pid": 1623, "rank": 15, "used": 1878904, "free": 14168328, "real_used": 2608888, "total_size": 16777216, "total_frags": 27, "desc": "tcp receiver (generic) child=4" }, { "entry": 33, "pid": 1624, "rank": 16, "used": 1878904, "free": 14168328, "real_used": 2608888, "total_size": 16777216, "total_frags": 27, "desc": "tcp receiver (generic) child=5" }, { "entry": 34, "pid": 1625, "rank": 17, "used": 1878904, "free": 14168328, "real_used": 2608888, "total_size": 16777216, "total_frags": 27, "desc": "tcp receiver (generic) child=6" }, { "entry": 35, "pid": 1626, "rank": 18, "used": 1878992, "free": 14168032, "real_used": 2609184, "total_size": 16777216, "total_frags": 28, "desc": "tcp receiver (generic) child=7" }, { "entry": 36, "pid": 1627, "rank": -4, "used": 1880080, "free": 14167776, "real_used": 2609440, "total_size": 16777216, "total_frags": 31, "desc": "tcp main process" } ], "id": 34083 }

пн, 29 авг. 2022 г. в 17:43, Daniel-Constantin Mierla miconda@gmail.com:

Hello,

I would also worry about the out of memory logs. For troubleshooting in such case, you need to get:

kamctl ps

kamctl rpc pkg.stats

Maybe also you set latency limits via core parameter to see if some operations are slow in the config.

If there are slow C functions run internally on timer, then maybe you can troubleshoot with debug=3.

Cheers, Daniel On 29.08.22 16:30, Denys Pozniak wrote:

Hello!

After some time, Kamailio stops processing incoming messages. slow timer too slow: overflow messages appear in the log (I suspect that the problem is related to the rtimer module)

Aug 29 14:19:17 kamailio[11320]: 2(11320) ERROR: {1 10 OPTIONS 2b45547f33f5203f-4091@10.10.10.10} <core> [core/mem/q_malloc.c:430]: qm_malloc(): qm_malloc(0x7f163b9f9010, 960) called from core: core/rvalue.c: rval_new_empty(246), module: core; Free fragment> Aug 29 14:19:17 kamailio[11320]: 2(11320) ERROR: {1 10 OPTIONS 2b45547f33f5203f-4091@10.10.10.10} <core> [core/rvalue.c:253]: rval_new_empty(): could not allocate private memory from pkg pool Aug 29 14:19:17 kamailio[11330]: 12(11330) WARNING: <core> [ core/timer.c:936]: timer_handler(): slow timer too slow: overflow (62671

• 61648 = 1023)

Aug 29 14:19:17 kamailio[11320]: 2(11320) ERROR: {1 10 OPTIONS 34618af41c3866bc-16408@10.10.10.20} <core> [core/mem/q_malloc.c:297]: qm_find_free(): qm_find_free(0x7f163b9f9010, 960); Free fragment not found! Aug 29 14:19:17 kamailio[11320]: 2(11320) ERROR: {1 10 OPTIONS 34618af41c3866bc-16408@10.10.10.20} <core> [core/mem/q_malloc.c:430]: qm_malloc(): qm_malloc(0x7f163b9f9010, 960) called from core: core/rvalue.c: rval_new_empty(246), module: core; Free fragment no> Aug 29 14:19:17 kamailio[11320]: 2(11320) ERROR: {1 10 OPTIONS 34618af41c3866bc-16408@10.10.10.20} <core> [core/rvalue.c:253]: rval_new_empty(): could not allocate private memory from pkg pool Aug 29 14:19:17 kamailio[11330]: 12(11330) WARNING: <core> [ core/timer.c:936]: timer_handler(): slow timer too slow: overflow (62671

• 61648 = 1023)

Aug 29 14:19:18 kamailio[11320]: 2(11320) ERROR: {1 10 KDMQ 1c18959d07113951-203309@10.10.10.30} <core> [core/mem/q_malloc.c:297]: qm_find_free(): qm_find_free(0x7f163b9f9010, 960); Free fragment not found! Aug 29 14:19:18 kamailio[11320]: 2(11320) ERROR: {1 10 KDMQ 1c18959d07113951-203309@10.10.10.30} <core> [core/mem/q_malloc.c:430]: qm_malloc(): qm_malloc(0x7f163b9f9010, 960) called from core: core/rvalue.c: rval_new_empty(246), module: core; Free fragment no>

Please point me out where the source of the problem could be.

version: kamailio 5.6.1 (x86_64/linux)

BR, Denys Pozniak

---

Kamailio - Users Mailing List - Non Commercial Discussions

• sr-users@lists.kamailio.org

Important: keep the mailing list in the recipients, do not reply only to the sender! Edit mailing list options or unsubscribe:

• https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users

-- Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- www.linkedin.com/in/miconda