[OpenSIPS-Devel] [ opensips-Bugs-3377861 ] fifo dr_reload memory leak

SourceForge.net noreply at sourceforge.net
Fri Aug 5 21:40:22 CEST 2011


Bugs item #3377861, was opened at 2011-07-26 06:20
Message generated for change (Comment added) made by bogdan_iancu
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=3377861&group_id=232389

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: modules
Group: 1.6.x
Status: Open
>Resolution: Fixed
Priority: 5
Private: No
Submitted By: Dave May (davemay99)
Assigned to: Bogdan-Andrei Iancu (bogdan_iancu)
Summary: fifo dr_reload memory leak

Initial Comment:
Using svn8195 of 1.6 branch, a steady memory leak occurs when performing multiple iterations of "opensipsctl fifo dr_reload".  The DR_RULES table is stored in MySQL, and contains just under 32000 entries.  The following script demonstrates the problem, and results in failure after about 519 iterations when OpenSIPS is compiled with 4MB pkg memory.

#!/bin/bash
COUNTER=0
while [ $COUNTER -lt $1 ]; do

        opensipsctl fifo dr_reload
        opensipsctl fifo get_statistics pkmem: | grep pkmem:3-real_used_size

        let COUNTER=COUNTER+1
done

Script output on 519th iteration:
    518: Mon Jul 25 22:54:05 EDT 2011
    
    500 Failed to reload
    pkmem:3-real_used_size = 3876904

output from "opensipsctl fifo get_statistics pkmem: | grep pkmem:3-"
    pkmem:3-total_size = 4194304
    pkmem:3-used_size = 2313144
    pkmem:3-real_used_size = 4182476
    pkmem:3-max_used_size = 4187992
    pkmem:3-free_size = 11828
    pkmem:3-fragments = 74

Failure presents itself with the following in the logs at debug=3

Jul 25 22:54:08 sipdev1 /usr/sbin/opensips[520]: INFO:drouting:dr_reload_cmd: "dr_reload" MI command received!
Jul 25 22:54:08 sipdev1 /usr/sbin/opensips[520]: ERROR:core:db_allocate_rows: no memory left
Jul 25 22:54:08 sipdev1 /usr/sbin/opensips[520]: ERROR:db_mysql:db_mysql_fetch_result: no memory left
Jul 25 22:54:08 sipdev1 /usr/sbin/opensips[520]: ERROR:drouting:dr_load_routing_info: Error fetching rows
Jul 25 22:54:08 sipdev1 /usr/sbin/opensips[520]: CRITICAL:drouting:dr_reload_data: failed to load routing info
Jul 25 22:54:08 sipdev1 /usr/sbin/opensips[520]: CRITICAL:drouting:dr_reload_cmd: failed to load routing data
Jul 25 22:54:08 sipdev1 /usr/sbin/opensips[520]: ERROR:mi_fifo:mi_open_reply_pipe: open error (/tmp/opensips_receiver_17638): No such file or directory
Jul 25 22:54:08 sipdev1 /usr/sbin/opensips[520]: ERROR:mi_fifo:mi_fifo_server: cannot open reply pipe /tmp/opensips_receiver_17638

----------------------------------------------------------------------

>Comment By: Bogdan-Andrei Iancu (bogdan_iancu)
Date: 2011-08-05 22:40

Message:
Hi Dave,

Thanks a lot for the dump - I found the leak and fixed it on SVN (trunk,
1.7 and 1.6)
Please update and test again.

If the problem is solved, please close this report.

Thanks and regards,
Bogdan

----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2011-08-05 21:59

Message:
Here you go Bogdan -- please let me know if you need more information.

    http://dl.dropbox.com/u/37374089/opensips_memory.log.gz

Thanks!

Dave.

----------------------------------------------------------------------

Comment By: Bogdan-Andrei Iancu (bogdan_iancu)
Date: 2011-08-05 11:31

Message:
Dave,

I'm more interested in the part of the dump with the allocated fragments,
which looks like (note example is for shm, but we need pkg):
     0(17665) Memory status (shm):
     0(17665) qm_status (0xb5a7e000):
     0(17665)  heap size= 33554432
     0(17665)  used= 1592952, used+overhead=1811564, free=31742868
     0(17665)  max used (+overhead)= 1811564
     0(17665) dumping all alloc'ed. fragments:
     0(17665)       0. N  address=0xb5ab240c frag=0xb5ab23f4 size=4
used=1
     0(17665)             alloc'd from mem/shm_mem.c:
shm_mem_init_mallocs(199)
     0(17665)         start check=f0f0f0f0, end check= c0c0c0c0, abcdefed
     0(17665)       1. N  address=0xb5ab2440 frag=0xb5ab2428 size=4 used=1

     0(17665)             alloc'd from timer.c: init_timer(52)
     0(17665)         start check=f0f0f0f0, end check= c0c0c0c0, abcdefed

Could you post the file somewhere for download ? and post (or email me)
the link where to get it.

Thanks and Regards,
Bogdan


----------------------------------------------------------------------

Comment By: Dave May (davemay99)
Date: 2011-08-05 06:26

Message:
Bogdan - I've tried attaching the logfile to the bug, but it doesn't seem
to want to take.  It's over 10mb, so perhaps that is part of the issue. 
Here is the contents of the file, with the 32723 fragments snipped.  Please
let me know if you need the remainder of the file, and if so where you
would like me to post.

Aug  4 23:13:00 sipdev1 /usr/sbin/opensips[13783]:
INFO:drouting:dr_reload_cmd: "dr_reload" MI command received!
Aug  4 23:13:00 sipdev1 /usr/sbin/opensips[13783]:
ERROR:core:db_allocate_rows: no memory left
Aug  4 23:13:00 sipdev1 /usr/sbin/opensips[13783]:
ERROR:db_mysql:db_mysql_fetch_result: no memory left
Aug  4 23:13:00 sipdev1 /usr/sbin/opensips[13783]:
ERROR:drouting:dr_load_routing_info: Error fetching rows
Aug  4 23:13:00 sipdev1 /usr/sbin/opensips[13783]:
CRITICAL:drouting:dr_reload_data: failed to load routing info
Aug  4 23:13:00 sipdev1 /usr/sbin/opensips[13783]:
CRITICAL:drouting:dr_reload_cmd: failed to load routing data
Aug  4 23:13:57 sipdev1 /usr/sbin/opensips[13783]: Memory status (pkg):
Aug  4 23:13:57 sipdev1 /usr/sbin/opensips[13783]: qm_status (0x81809a0):
Aug  4 23:13:57 sipdev1 /usr/sbin/opensips[13783]:  heap size= 4194304
Aug  4 23:13:57 sipdev1 /usr/sbin/opensips[13783]:  used= 2168104,
used+overhead=3953916, free=240388
Aug  4 23:13:57 sipdev1 /usr/sbin/opensips[13783]:  max used (+overhead)=
4105260
Aug  4 23:13:57 sipdev1 /usr/sbin/opensips[13783]: dumping all alloc'ed.
fragments:

xxxxxxxx


Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: dumping free list stats
:
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=   1. fragments
no.:     2, unused:     0#012#011#011 bucket size:         4 -         4
(first         4)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=   2. fragments
no.:     2, unused:     0#012#011#011 bucket size:         8 -         8
(first         8)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=   7. fragments
no.:     1, unused:     0#012#011#011 bucket size:        28 -        28
(first        28)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=   8. fragments
no.:     1, unused:     0#012#011#011 bucket size:        32 -        32
(first        32)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=   9. fragments
no.:     1, unused:     0#012#011#011 bucket size:        36 -        36
(first        36)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=  15. fragments
no.:    12, unused:     0#012#011#011 bucket size:        60 -        60
(first        60)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=  16. fragments
no.:    26, unused:     0#012#011#011 bucket size:        64 -        64
(first        64)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=  17. fragments
no.:    24, unused:     0#012#011#011 bucket size:        68 -        68
(first        68)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=  20. fragments
no.:     2, unused:     0#012#011#011 bucket size:        80 -        80
(first        80)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=  35. fragments
no.:     1, unused:     0#012#011#011 bucket size:       140 -       140
(first       140)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=  37. fragments
no.:     9, unused:     0#012#011#011 bucket size:       148 -       148
(first       148)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=  38. fragments
no.:     8, unused:     0#012#011#011 bucket size:       152 -       152
(first       152)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=  39. fragments
no.:     3, unused:     0#012#011#011 bucket size:       156 -       156
(first       156)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash=  41. fragments
no.:     1, unused:     0#012#011#011 bucket size:       164 -       164
(first       164)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash= 473. fragments
no.:     1, unused:     0#012#011#011 bucket size:      1892 -      1892
(first      1892)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash= 4098. fragments
no.:     1, unused:     0#012#011#011 bucket size:     32768 -     65536
(first     63984)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]: hash= 4099. fragments
no.:     2, unused:     0#012#011#011 bucket size:     65536 -    131072
(first     78960)
Aug  4 23:14:01 sipdev1 /usr/sbin/opensips[13783]:
-----------------------------


----------------------------------------------------------------------

Comment By: rrevels (ryanrevels)
Date: 2011-08-04 20:31

Message:
I've run into the same issue & will try to provide a memlog ASAP.

Regards,
Ryan

----------------------------------------------------------------------

Comment By: Bogdan-Andrei Iancu (bogdan_iancu)
Date: 2011-08-04 14:00

Message:
Hi Dave,

Have you tried to compile the memory debugger
(http://www.opensips.org/Resources/DocsTsMem) ? Please do that and set
memlog=6 and memdump=1 in your cfg (in this order). When the mem issue is
reported on the MI process, do the signal stuff on that process, in order
to get a memdump for that proc. Post here is output.

Thanks and regards,
Bogdan

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=3377861&group_id=232389



More information about the Devel mailing list