Re: [OpenSIPS-Users] Debugging memory leaks
Hi Liviu, - Ursprüngliche Mail - > Von: "Liviu Chircu" > > * what kind of traffic is hitting your server when you reach this > state? Is it just during normal operation, or are you passing through > some kind of peak hour or maybe you are performing a sipp-based stress test? This was just in normal operation. Memory goes up during daytime and does not reduce at night with much much less traffic. > * do you have (or can you create) a quiet window, with less traffic? If > yes, do these transactions get cleaned up properly within a minute, or > are we dealing with some kind of transaction referencing bug (unlikely)? This was a quiet window with ~ 700 devices registered and less than 10 running calls (if at all) at the time right before the dump. > * can you reproduce this in a lab environment? If yes, please share how! :) Never tried this outside our platform, but i might check our test environment. Thanks for your help! Fabian ___ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Re: [OpenSIPS-Users] Debugging memory leaks
On 11.03.2020 13:08, Fabian Gast wrote: This was a quiet window with ~ 700 devices registered and less than 10 running calls (if at all) at the time right before the dump. Then one additional tip would be to also monitor the "inuse_transactions" statistic [1], which tells you how many transactions are currently allocated and either waiting for a SIP reply or have completed and are simply waiting to be freed by tm's timer cleanup routine. [1]: https://opensips.org/docs/modules/3.1.x/tm.html#stat_inuse_transactions -- Liviu Chircu www.twitter.com/liviuchircu | www.opensips-solutions.com OpenSIPS Summit, Amsterdam, May 2020 www.opensips.org/events ___ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Re: [OpenSIPS-Users] Debugging memory leaks
Hi Liviu, - Ursprüngliche Mail - > Von: "Liviu Chircu" > > * what kind of traffic is hitting your server when you reach this > state? Is it just during normal operation, or are you passing through > some kind of peak hour or maybe you are performing a sipp-based stress test? This was just in normal operation. Memory goes up during daytime and does not reduce at night with much much less traffic. > * do you have (or can you create) a quiet window, with less traffic? If > yes, do these transactions get cleaned up properly within a minute, or > are we dealing with some kind of transaction referencing bug (unlikely)? This was a quiet window with ~ 700 devices registered and less than 10 running calls (if at all) at the time right before the dump. > * can you reproduce this in a lab environment? If yes, please share how! :) Never tried this outside our platform, but i might check our test environment. Thanks for your help! Fabian ___ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Re: [OpenSIPS-Users] Debugging memory leaks
On 11.03.2020 12:21, Fabian Gast wrote: Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]:33428816 : 3893 x [h_table.c: build_cell, line 244] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 72 : 3 x [evi/event_interface.c: evi_event_subscribe, line 334] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 176 : 1 x [event_route.c: scriptroute_parse, line 306] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 616 : 12 x [ucontact.c: mem_update_ucontact, line 255] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [dlg_timer.c: init_dlg_reinvite_ping_timer, line 192] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [sl_funcs.c: sl_startup, line 80] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]:37022512 : 3893 x [sip_msg.c: sip_msg_cloner, line 534] It seems most of your shared memory usage (33MB + 37MB, which equates to ~80% of total usage) consists of ... unreleased "tm" module transactions! Some questions going forward: * what kind of traffic is hitting your server when you reach this state? Is it just during normal operation, or are you passing through some kind of peak hour or maybe you are performing a sipp-based stress test? * do you have (or can you create) a quiet window, with less traffic? If yes, do these transactions get cleaned up properly within a minute, or are we dealing with some kind of transaction referencing bug (unlikely)? * can you reproduce this in a lab environment? If yes, please share how! :) Regards, -- Liviu Chircu www.twitter.com/liviuchircu | www.opensips-solutions.com OpenSIPS Summit, Amsterdam, May 2020 www.opensips.org/events ___ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Re: [OpenSIPS-Users] Debugging memory leaks
00:03 ireg02 /usr/sbin/opensips[42351]: 80 : 10 x [evi/event_interface.c: evi_publish_event, line 75] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]:3368 : 38 x [timer.c: new_os_timer, line 146] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 40 : 1 x [cachedb_local.c: parse_collections, line 608] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 136 : 1 x [event_route.c: fixup_scriptroute_fetch, line 564] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [usr_avp.c: init_extra_avps, line 74] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 984 : 1 x [core_stats.c: init_pkg_stats, line 174] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]:4120 : 1 x [statistics.c: init_stats_collector, line 223] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 696 : 19 x [ucontact.c: mem_update_ucontact, line 250] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 565800 : 1 x [pt.c: init_multi_proc_support, line 70] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [timer.c: init_timer, line 83] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 400 : 1 x [evi/event_interface.c: evi_publish_event, line 61] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]:8208 : 1 x [../../evi/../lock_alloc.h: lock_set_alloc, line 66] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 79464 : 826 x [urecord.c: new_urecord, line 70] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 464 : 2 x [event_routing.c: ebr_parse, line 380] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 384 : 16 x [../../rw_locking.h: lock_init_rw, line 40] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 32 : 2 x [evi/evi_transport.c: register_event_mod, line 84] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [dlg_timer.c: init_dlg_ping_timer, line 162] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 262144 : 32 x [net/net_tcp.c: tcp_init, line 1741] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 24 : 1 x [ul_callback.c: init_ulcb_list, line 44] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 56 : 1 x [udomain.c: new_udomain, line 81] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 81792 : 1167 x [statistics.c: register_stat2, line 388] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 2253944 : 3893 x [mem/shm_mem.c: _shm_resize, line 226] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [rw_locking.h: lock_init_rw, line 45] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 16 : 1 x [daemonize.c: set_osips_state, line 576] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 40 : 1 x [t_hooks.c: insert_tmcb, line 92] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 2621448 : 1 x [h_table.c: init_hash_table, line 372] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 262144 : 32 x [net/net_tcp.c: tcp_init, line 1747] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 251864 : 3287 x [../../ut.h: shm_str_dup, line 692] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]:33428816 : 3893 x [h_table.c: build_cell, line 244] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 72 : 3 x [evi/event_interface.c: evi_event_subscribe, line 334] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 176 : 1 x [event_route.c: scriptroute_parse, line 306] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 616 : 12 x [ucontact.c: mem_update_ucontact, line 255] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [dlg_timer.c: init_dlg_reinvite_ping_timer, line 192] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [sl_funcs.c: sl_startup, line 80] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]:37022512 : 3893 x [sip_msg.c: sip_msg_cloner, line 534] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]:1824 : 12 x [ucontact.c: mem_update_ucontact, line 271] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 55816 : 840 x [map.c: map_get, line 139] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [daemonize.c: create_status_pipe, line 92] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]:2064 : 1 x [../../lock_alloc.h: lock_set_alloc, line 66] Mar 10 23:00:03 ireg02 /usr/sbin/opensips[42351]: - Ursprüngliche Mail - Von: "Liviu Chircu" An: "OpenSIPS users mailling list" Gesendet: Mittwoch, 11. März 2020 11:03:16 Betreff: Re: [OpenSIPS-Users] Debugging memory leaks On 11.03.2020 11:06, Fabian Gast wrote: > How can we continue from the memory status on hunting down the problems? Is > there any advice on this? Hey Fabian, When you ran the "shm_mem_dump" which produced the pasted output, what values did the "shmem:" statistics group hold? Based on the output, you were barely using 1 MB o
Re: [OpenSIPS-Users] Debugging memory leaks
Hi Liviu, get_statistics shmem: from a few seconds before the dump was shmem:total_size:: 4294967296 shmem:used_size:: 88427200 shmem:real_used_size:: 95189880 shmem:max_used_size:: 119231640 shmem:free_size:: 4199777416 shmem:fragments:: 66733 All the best, Fabian - Ursprüngliche Mail - Von: "Liviu Chircu" An: "OpenSIPS users mailling list" Gesendet: Mittwoch, 11. März 2020 11:03:16 Betreff: Re: [OpenSIPS-Users] Debugging memory leaks On 11.03.2020 11:06, Fabian Gast wrote: > How can we continue from the memory status on hunting down the problems? Is > there any advice on this? Hey Fabian, When you ran the "shm_mem_dump" which produced the pasted output, what values did the "shmem:" statistics group hold? Based on the output, you were barely using 1 MB of shared memory, which is a bit strange. The table head tells exactly what the numbers represent: total bytes, number of allocations and the file/func/line which allocated them. Regards, -- Liviu Chircu www.twitter.com/liviuchircu | www.opensips-solutions.com OpenSIPS Summit, Amsterdam, May 2020 www.opensips.org/events ___ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users ___ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users
Re: [OpenSIPS-Users] Debugging memory leaks
On 11.03.2020 11:06, Fabian Gast wrote: How can we continue from the memory status on hunting down the problems? Is there any advice on this? Hey Fabian, When you ran the "shm_mem_dump" which produced the pasted output, what values did the "shmem:" statistics group hold? Based on the output, you were barely using 1 MB of shared memory, which is a bit strange. The table head tells exactly what the numbers represent: total bytes, number of allocations and the file/func/line which allocated them. Regards, -- Liviu Chircu www.twitter.com/liviuchircu | www.opensips-solutions.com OpenSIPS Summit, Amsterdam, May 2020 www.opensips.org/events ___ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users
[OpenSIPS-Users] Debugging memory leaks
Hi @all, according to our graphs [1] and some recent crashes it looks like we have some memory leaks in our opensips processes. We now have the memory status from one of our staging environments with about 2k devices. (The impact on our live machines is even more severe, but we can not enable memory debugging on these systems for $reasons.) How can we continue from the memory status on hunting down the problems? Is there any advice on this? snipped from the memory status dump - full trace available upon request... Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: Memory status (shm): Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: qm_status (0x7ff2182ea000): Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: heap size= 4294967296 Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: used= 19440, used+overhead=325640, free=4294641656 Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: max used (+overhead)= 119231640 Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: dumping summary of all alloc'ed. fragments: Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: total_bytes | num_allocations x [file: func, line] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]:6040 : 366 x [statistics.c: build_stat_name, line 122] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 32 : 1 x [dlg_timer.c: init_dlg_reinvite_ping_timer, line 185] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 408 : 48 x [mi/mi.c: register_mi_cmd, line 174] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 128 : 2 x [ebr_data.c: add_ebr_event, line 79] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 168 : 14 x [map.c: map_get, line 150] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 32 : 1 x [map.c: map_create, line 79] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]:5904 : 1 x [core_stats.c: init_pkg_stats, line 173] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [usr_avp.c: init_extra_avps, line 83] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [mem/shm_mem.c: shm_mem_init_mallocs, line 390] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 80 : 10 x [evi/event_interface.c: evi_publish_event, line 75] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]:3368 : 38 x [timer.c: new_os_timer, line 146] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 40 : 1 x [cachedb_local.c: parse_collections, line 608] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 136 : 1 x [event_route.c: fixup_scriptroute_fetch, line 564] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [usr_avp.c: init_extra_avps, line 74] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 984 : 1 x [core_stats.c: init_pkg_stats, line 174] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [timer.c: init_timer, line 83] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 400 : 1 x [evi/event_interface.c: evi_publish_event, line 61] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 464 : 2 x [event_routing.c: ebr_parse, line 380] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 32 : 2 x [evi/evi_transport.c: register_event_mod, line 84] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 16 : 1 x [daemonize.c: set_osips_state, line 576] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 72 : 3 x [evi/event_interface.c: evi_event_subscribe, line 334] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 176 : 1 x [event_route.c: scriptroute_parse, line 306] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [dlg_timer.c: init_dlg_reinvite_ping_timer, line 192] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 912 : 14 x [map.c: map_get, line 139] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: 8 : 1 x [daemonize.c: create_status_pipe, line 92] Mar 10 23:00:39 ireg02 /usr/sbin/opensips[42351]: version: opensips 2.4.6 (x86_64/linux) flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, PKG_MALLOC, QM_MALLOC, DBG_MALLOC, FAST_LOCK-ADAPTIVE_WAIT ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535 poll method support: poll, epoll, sigio_rt, select. git revision: edef893 main.c compiled on with gcc 4.9.2 Thanks, Fabian [1] https://imgur.com/a/9drmJHR ___ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users
