[Home]

Summary:ASTERISK-08422: Possible memory leak doing only inbound SIP handling
Reporter:Andre Courchesne (acourchesne)Labels:
Date Opened:2006-12-22 09:55:26.000-0600Date Closed:2011-06-07 14:03:26
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) memory_summary.pdf
( 1) Memory_debug.rar
( 2) SIP_test_results.pdf
( 3) SIP_test_results_-_Update_1.pdf
( 4) SIP_test_results_-_Update_2.pdf
Description:When trying to profile our Asterisk distribution, we ran test where a server would initiate SIP calls to a test server (UIT) running our distribution and the latest Asterisk packages. We found that doing only inbound SIP calls handling, the UIT free memory would slowly get lower and lower.

We performed the test against an earlier version of our distribution running Asterisk 1.0x as well as on Trixbox 2.0Beta2 and found similar results.

The attached PDF document outlines the test method as well as the test results.
Comments:By: Serge Vecher (serge-v) 2006-12-27 09:48:00.000-0600

did you try to profile the l.4.0 release?
By: Andre Courchesne (acourchesne) 2006-12-27 09:54:37.000-0600

I'm trying to install AsteriskNow 1.4.0b2 to perform the same tests, but the install crashes.

I will download the live CD in order to perform the exact same tests.
By: Andre Courchesne (acourchesne) 2006-12-27 14:27:49.000-0600

Ok, I have performed the same test on AsteriskNOW 1.4.0 Beta 2.

Unfortunately I had to change the UIT server as my Dual Xeon was not available... The test should still be valid and shows that with this install the memory also goes down as the time under test goes by.

See attached file "SIP test results - Update 1.pdf" for the AsteriskNOW results.
By: Olle Johansson (oej) 2007-01-08 05:38:07.000-0600

This might not have to do with the SIP channel, but the way you set up the calls with the call file.
By: Andre Courchesne (acourchesne) 2007-01-08 07:06:03.000-0600

Do you suggest that I should that I should use the API ?

But the call is initiates with a call file on a separate server... The memory loss is happening on the server receiving the call, not the one initiating it.

I am setting myself up to repeat the test with the memory allocation debugging support enabled. I should have result on this by Tuesday.
By: Olle Johansson (oej) 2007-01-08 07:11:36.000-0600

Ah. I misunderstood. Then it's a SIP 2 SIP issue. Thanks for testing, looking forward to your results.
By: Olle Johansson (oej) 2007-01-08 07:16:27.000-0600

Seems like you're generating errors, since you only have "s" in your dialplan. Is that true, please check the log files?
By: Andre Courchesne (acourchesne) 2007-01-09 13:33:06.000-0600

Ok, here is the output of "tail -f /var/log/asterisk/full" on the target (UIT) when it receives a SIP call:

Jan  9 14:32:17 DEBUG[1694] chan_sip.c: Checking SIP call limits for device
Jan  9 14:32:17 DEBUG[1694] chan_sip.c: build_route: Contact hop: <sip:Unknown@192.168.2.152>
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Executing NoOp("SIP/192.168.2.152-0823148c", "Received incoming SIP connection from unknown peer to 5145551212") in new stack
Jan  9 14:32:17 DEBUG[2317] pbx.c: Expression result is '0'
Jan  9 14:32:17 DEBUG[2317] pbx.c: Function result is '5145551212'
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Executing Set("SIP/192.168.2.152-0823148c", "DID=5145551212") in new stack
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Executing Goto("SIP/192.168.2.152-0823148c", "s|1") in new stack
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Goto (from-sip-external,s,1)
Jan  9 14:32:17 DEBUG[2317] pbx.c: Expression result is '1'
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Executing GotoIf("SIP/192.168.2.152-0823148c", "1?from-trunk|5145551212|1") in new stack
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Goto (from-trunk,5145551212,1)
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Executing NoOp("SIP/192.168.2.152-0823148c", "Catch-All DID Match - Found 5145551212 - You probably want a DID for this.") in new stack
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Executing Goto("SIP/192.168.2.152-0823148c", "ext-did|s|1") in new stack
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Goto (ext-did,s,1)
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Executing Set("SIP/192.168.2.152-0823148c", "FROM_DID=s") in new stack
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Executing Goto("SIP/192.168.2.152-0823148c", "custom-sip-test|s|1") in new stack
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Goto (custom-sip-test,s,1)
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Executing Answer("SIP/192.168.2.152-0823148c", "") in new stack
Jan  9 14:32:17 DEBUG[1684] channel.c: Avoiding initial deadlock for 'SIP/192.168.2.152-0823148c'
Jan  9 14:32:17 VERBOSE[2317] logger.c:     -- Executing Wait("SIP/192.168.2.152-0823148c", "1") in new stack
Jan  9 14:32:17 DEBUG[1694] chan_sip.c: Stopping retransmission on '4693d6f84b111d915d412567171460c6@192.168.2.152' of Response 102: Match Found
Jan  9 14:32:18 VERBOSE[2317] logger.c:     -- Executing Playback("SIP/192.168.2.152-0823148c", "why-no-answer-mystery") in new stack
Jan  9 14:32:18 DEBUG[2317] channel.c: Scheduling timer at 160 sample intervals
Jan  9 14:32:18 VERBOSE[2317] logger.c:     -- Playing 'why-no-answer-mystery' (language 'en')
Jan  9 14:32:24 DEBUG[2317] channel.c: Scheduling timer at 0 sample intervals
Jan  9 14:32:24 DEBUG[2317] channel.c: Scheduling timer at 0 sample intervals
Jan  9 14:32:24 VERBOSE[2317] logger.c:     -- Executing Playback("SIP/192.168.2.152-0823148c", "goodbye") in new stack
Jan  9 14:32:24 DEBUG[2317] channel.c: Scheduling timer at 160 sample intervals
Jan  9 14:32:24 VERBOSE[2317] logger.c:     -- Playing 'goodbye' (language 'en')
Jan  9 14:32:25 DEBUG[2317] channel.c: Scheduling timer at 0 sample intervals
Jan  9 14:32:25 DEBUG[2317] channel.c: Scheduling timer at 0 sample intervals
Jan  9 14:32:25 VERBOSE[2317] logger.c:     -- Executing Hangup("SIP/192.168.2.152-0823148c", "") in new stack
Jan  9 14:32:25 VERBOSE[2317] logger.c:   == Spawn extension (custom-sip-test, s, 5) exited non-zero on 'SIP/192.168.2.152-0823148c'
Jan  9 14:32:25 DEBUG[2317] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jan  9 14:32:25 DEBUG[2317] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2007-01-09 14:32:17','\"Unknown\" <Unknown>','Unknown','s','custom-sip-test', 'SIP/192.168.2.152-0823148c','','Hangup','',8,8,'ANSWERED',3,'','1168371137.6')
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is '"Unknown" <Unknown>'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is 'Unknown'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is 's'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is 'custom-sip-test'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is 'SIP/192.168.2.152-0823148c'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is '(null)'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is 'Hangup'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is '(null)'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is '2007-01-09 14:32:17'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is '2007-01-09 14:32:17'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is '2007-01-09 14:32:25'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is '8'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is '8'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is 'ANSWERED'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is 'DOCUMENTATION'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is '(null)'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is '1168371137.6'
Jan  9 14:32:25 DEBUG[2317] pbx.c: Function result is '(null)'
Jan  9 14:32:25 ERROR[2317] cdr_custom.c: Unable to re-open master file /var/log/asterisk/cdr-custom/Master.csv : No such file or directory
Jan  9 14:32:25 DEBUG[2317] chan_sip.c: update_call_counter() - decrement call limit counter
Jan  9 14:32:25 DEBUG[1694] chan_sip.c: Stopping retransmission on '4693d6f84b111d915d412567171460c6@192.168.2.152' of Request 102: Match Found
By: Andre Courchesne (acourchesne) 2007-01-09 13:35:18.000-0600

Also I found something interesting when performing 3 "show memory summary" (1 after reboot, 1 after 1 SIP call and 1 after 2 SIP calls).

The attached file memory_summary.pdf shows the 3 tables.

Looks like logger.c might be responsible...
By: Clod Patry (junky) 2007-01-15 11:08:44.000-0600

just 2 sip calls isnt really revelant.
Could ya paste same stuff after, like 2000 calls?
By: Joshua C. Colp (jcolp) 2007-02-08 20:15:26.000-0600

Have you tried it with a larger channel count yet?
By: Clod Patry (junky) 2007-02-09 09:25:47.000-0600

i may have found a small mem leak in rtp.c
will post the patch tonight.

acourchene: we need feedback here.
By: Andre Courchesne (acourchesne) 2007-02-09 09:28:37.000-0600

Sorry for the lack of feedback. I an in the process of rebuilding my test setup and will provide feedback during tests conducted next week.
By: Joshua C. Colp (jcolp) 2007-02-09 11:08:28.000-0600

Removed naughty attached patch.
By: Andre Courchesne (acourchesne) 2007-02-15 14:40:50.000-0600

Ok, just uploaded "Memory_debug.rar" which contains an excel file.

This excel gives the memory summary and memory allocations before and after 241 loops of 100 SIP calls.

Unfortunately I did not have good hardware available so I had to perform this test on 2 vmware session. But the values should be indicative anyway.

Looks like logger.c and sched.c do not release all their allocated memory...
By: Olle Johansson (oej) 2007-02-15 15:08:03.000-0600

logger.c and sched.c - cool :-) Chan_sip is free to leave the court then.
By: Joshua C. Colp (jcolp) 2007-02-16 15:07:33.000-0600

Okay here it goes...

I looked into the logger for potential leaks and it uses a message list queue which can grow and occupy more memory, so it might seem as though it's leaking memory when it's not.

As for the scheduler there may be scheduled items not yet run which caused it to grow some.
By: Andre Courchesne (acourchesne) 2007-02-19 09:07:09.000-0600

So what you are saying is that if I repeat the same test and when I stop the calls and let the UIT server stand still for a while, I should see the memory levels go back to "normal" levels?
By: Joshua C. Colp (jcolp) 2007-02-19 09:24:21.000-0600

Yes, and the actual difference of memory is minimal.
By: Andre Courchesne (acourchesne) 2007-02-19 09:35:43.000-0600

Ok, I'll schedule an other round of test this week hopefully using real hardware servers and will post the findings as soon as they are available (probably at the end of the week.
By: Serge Vecher (serge-v) 2007-03-06 09:53:02.000-0600

acourchesne: what't the status here with 1.4.1?
By: Andre Courchesne (acourchesne) 2007-03-13 07:10:40

I have scheduled tests using 1.4.1 for next week. Will post results as soon as they are available.
By: Serge Vecher (serge-v) 2007-03-26 12:59:34

what are the test results?
By: Andre Courchesne (acourchesne) 2007-03-26 13:09:16

Strange that you ask, I am setting up the equipment to perform the test right now.
By: Andre Courchesne (acourchesne) 2007-03-27 08:30:19

Same results with asterisk 1.4.2

See attached file "SIP test results - Update 2.pdf"

After 1056 loops of 100 calls, 95620Kb of memory was consumed (started with 99380Kb). This test was performed in a VMWare session with 256Mb of memory allocated.

I did not have memory debug enabled. If needed, I can recompile and restart the test later this week.
By: Serge Vecher (serge-v) 2007-03-27 09:18:55

I think this is related to 9235. According to the notes in that bug, one of the revision between 1.2.13 and 1.2.14 have introduced a bug when a sip sessions are left hanging. You can confirm if that is the case by issuing "sip show channels". While we are waiting for a developer to pick this case up, the best thing to do is to examine specific revisions and narrow down the one that introduces the problem.

Thanks.
By: cmaj (cmaj) 2007-04-16 14:30:32

There are patches in 9235 ready for more testing.
By: Olle Johansson (oej) 2007-05-15 15:30:41

Any updates?
By: Joshua C. Colp (jcolp) 2007-07-30 10:04:49

Suspending this for now due to lack of feedback.