29 Aug
2022
29 Aug
'22
5:30 p.m.
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(a)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(a)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(a)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(a)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(a)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(a)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(a)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
29 Aug
29 Aug
5:43 p.m.
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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
5 Sep
5 Sep
11:11 a.m.
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(a)gmail.com>om>:
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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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
--
BR,
Denys Pozniak
809
days inactive
816
days old
2 comments
2 participants
participants (2)
-
Daniel-Constantin Mierla -
Denys Pozniak