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.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda


--

BR,
Denys Pozniak