High load on Kamailio IMS

[Dgeka25594]

Hi, Herlesupreeth!

The question is not about a problem related to your configuration, so if there is nothing to answer, I will close the ticket, but if you give any advice, I will be grateful.

I set up Kamailio IMS according to your configuration, everything worked out great in the end, and I decided to check how Kamailio copes with the load. I am creating load using sipp application. With a low call generation rate, there are no problems, but if you raise the call generation to more than 20 calls per second, some of the calls fail. I compared the calls and saw that the ICSCF does not send a 180 Ringing message towards the SCSCF.

Below is an example of a successful call.

CPU, MEM indicators are normal. I increased the shr_mem and pkg_mem parameters. Any idea where the bug might be? in the logs, I did not find an explicit WAR or ERR on this problem, in SIP messages I also do not see any difference between a successful and unsuccessful call.

10.21.4.226 external IP P-CSCF 10.10.0.1 IP P-CSCF 10.10.0.2 IP S/I-CSCF

logs.zip dump.zip

[herlesupreeth]

I haven't done load testing so cant say for sure. But from the traces you sent I see the issue in P-CSCF not being able to send out the INVITE to UE. Maybe a TCP issue, not sure

[Dgeka25594]

Oh, that's how. And I was sure that the problem is that ICSCF does not send a 180 Ringing message towards the SCSCF (in the screenshot of an unsuccessful call). I want to send a correction, I shot the trace on the node where the I / S-CSCF is located, and the P-CSCF is located on another server. I'll take a trace there too then. Perhaps this is why you decided that the P-CSCF cannot send an INVITE to UE

[Dgeka25594]

dump.zip In the attachment, the trace from P-CSCF and I / S-CSCF, from P-CSCF IVITE goes towards the UE as far as I can see. But there is no Ringing event.

P-CSCF I/S-CSCF

[Dgeka25594]

I was thinking of trying to switch the transport between I-CSCF and S-CSCF to TCP instead of UDP. In addition to the settings on the DNS server, do you still need to make some changes to Kamailio so that it communicates between modules via UDP? (TCP ports Kamailio is already listening)

[Dgeka25594]

I think I found a message in the log for the problematic call:

Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26162]: DEBUG: ims_icscf [scscf_list.c:431]: take_scscf_entry(): Getting scscf entry from list
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26161]: DEBUG: <core> [core/mem/q_malloc.c:482]: qm_free(): qm_free(0x7fe66d684010, 0x7fe66d737b08), called from core: core/parser/parse_via.c: free_via_param_list(2725)
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26160]: DEBUG: <core> [core/mem/q_malloc.c:416]: qm_malloc(): qm_malloc(0x7fe66d684010, 64) returns address 0x7fe66d782a48 frag. 0x7fe66d782a10 (size=64) on 1 -th hit
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26162]: DEBUG: ims_icscf [scscf_list.c:461]: take_scscf_entry(): scscf has not been set so we just look for first match
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26161]: DEBUG: <core> [core/mem/q_malloc.c:525]: qm_free(): freeing frag. 0x7fe66d737ad0 alloc'ed from core: core/parser/parse_via.c: parse_via(2511)
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26162]: DEBUG: ims_icscf [scscf_list.c:368]: I_scscf_select(): no scscf entry for callid [43-3057631@10.2.16.63]```

[Dgeka25594]

And depend above, apparently due to the fact that the dialogue was deleted ahead of time, it remains to understand why.

Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26057]: DEBUG: ims_usrloc_scscf [contact_dlg_handlers.c:129]: contact_dlg_handler(): no dlg out... ignoring!!! for type [4] - usually happens on failure response in dialog
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26057]: DEBUG: ims_dialog [dlg_hash.c:1066]: unref_dlg(): unref dlg 0x7fc133cb2888 with 1 -> 1
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26057]: DEBUG: ims_dialog [dlg_hash.c:1066]: unref_dlg(): unref dlg 0x7fc133cb2888 with 1 -> 0
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26057]: DEBUG: ims_dialog [dlg_hash.c:1066]: unref_dlg(): ref <=0 for dialog 0x7fc133cb2888
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26057]: DEBUG: ims_dialog [dlg_hash.c:196]: destroy_dlg(): destroying dialog 0x7fc133cb2888
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26057]: DEBUG: ims_dialog [dlg_hash.c:207]: destroy_dlg(): removed timer for dlg 0x7fc133cb2888 [3686:114] with clid '44-3057631@10.2.16.63' and tags '78885556602' 
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26057]: DEBUG: ims_dialog [dlg_hash.c:218]: destroy_dlg(): About to run dlg callback for destroy
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1176]: dlg_onreply(): ONREPLY CALL_BACK from TM received and type is [128] = [TMCB_ON_FAILURE]
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26057]: DEBUG: ims_dialog [dlg_cb.c:277]: run_dlg_callbacks(): dialog=0x7fc133cb2888, type=8192
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:887]: lookup_dlg(): ref dlg 0x7fc133ce61d8 with 1 -> 2
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26057]: DEBUG: ims_usrloc_scscf [contact_dlg_handlers.c:129]: contact_dlg_handler(): no dlg out... ignoring!!! for type [8192] - usually happens on failure response in dialog
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:889]: lookup_dlg(): dialog id=1419 found on entry 3791
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26057]: DEBUG: ims_dialog [dlg_hash.c:220]: destroy_dlg(): DONE: About to run dlg callback for destroy
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1193]: dlg_onreply(): DLG dialogid is entry:id [3791:1419]
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26057]: DEBUG: ims_dialog [dlg_hash.c:156]: destroy_entry_out(): Destroy dialog entry out
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_profile.c:419]: set_current_dialog(): setting current dialog [3791:1419]
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:1066]: unref_dlg(): unref dlg 0x7fc133ce61d8 with 1 -> 1
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1176]: dlg_onreply(): ONREPLY CALL_BACK from TM received and type is [1048576] = [TMCB_RESPONSE_READY]
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:887]: lookup_dlg(): ref dlg 0x7fc133ce61d8 with 1 -> 2
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:889]: lookup_dlg(): dialog id=1419 found on entry 3791
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1193]: dlg_onreply(): DLG dialogid is entry:id [3791:1419]
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1235]: dlg_onreply(): Extracting to-tag from reply
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1255]: dlg_onreply(): Got to-tag from response: 639fc351b82f5e23035169a2e380aa27-f769f1d4 
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1275]: dlg_onreply(): Calling next_state_dlg and event is 4 = DLG_EVENT_RPL3xx
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:1293]: next_state_dlg(): dialog 0x7fc133ce61d8 changed from state 1 to state 6, due event 4
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1279]: dlg_onreply(): Checking if there is an existing dialog_out entry with same to-tag
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1300]: dlg_onreply(): Extracting to-tag from reply
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1331]: dlg_onreply(): Got to-tag from response: 639fc351b82f5e23035169a2e380aa27-f769f1d4 
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1338]: dlg_onreply(): Scanning dlg_entry_out list for dlg_out
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1409]: dlg_onreply(): new state is 6 and old state is 1
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_handlers.c:1489]: dlg_onreply(): dialog 0x7fc133ce61d8 failed (negative reply)
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_cb.c:277]: run_dlg_callbacks(): dialog=0x7fc133ce61d8, type=4
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_usrloc_scscf [contact_dlg_handlers.c:129]: contact_dlg_handler(): no dlg out... ignoring!!! for type [4] - usually happens on failure response in dialog
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:1066]: unref_dlg(): unref dlg 0x7fc133ce61d8 with 1 -> 1
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:1066]: unref_dlg(): unref dlg 0x7fc133ce61d8 with 1 -> 0
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:1066]: unref_dlg(): ref <=0 for dialog 0x7fc133ce61d8
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:196]: destroy_dlg(): destroying dialog 0x7fc133ce61d8
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:207]: destroy_dlg(): removed timer for dlg 0x7fc133ce61d8 [3791:1419] with clid '43-3057631@10.2.16.63' and tags '78885556600' 
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:218]: destroy_dlg(): About to run dlg callback for destroy
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_cb.c:277]: run_dlg_callbacks(): dialog=0x7fc133ce61d8, type=8192
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_usrloc_scscf [contact_dlg_handlers.c:129]: contact_dlg_handler(): no dlg out... ignoring!!! for type [8192] - usually happens on failure response in dialog
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:220]: destroy_dlg(): DONE: About to run dlg callback for destroy
Apr  5 08:24:38 ims-core /usr/local/sbin/kamailio[26056]: DEBUG: ims_dialog [dlg_hash.c:156]: destroy_entry_out(): Destroy dialog entry out

[Dgeka25594]

Can anyone tell me where you can read about the states that Kamailio writes about?

DEBUG: ims_dialog [dlg_hash.c:1293]: next_state_dlg(): dialog 0x7fc133ce61d8 changed from state 1 to state 6, due event 4

[Dgeka25594]

The problem was partially solved by disabling debug redim and disabling logging. performance has increased, but still there are drop calls about high loads. There may be a problem with the database, I will look further. I am closing this thread.