[asterisk-bugs] [Asterisk 0015973]: Huge memory consumption after few hours of load

Asterisk Bug Tracker noreply at bugs.digium.com
Tue Sep 29 16:28:17 CDT 2009


A NOTE has been added to this issue. 
====================================================================== 
https://issues.asterisk.org/view.php?id=15973 
====================================================================== 
Reported By:                atis
Assigned To:                
====================================================================== 
Project:                    Asterisk
Issue ID:                   15973
Category:                   Core/General
Reproducibility:            always
Severity:                   major
Priority:                   normal
Status:                     feedback
Asterisk Version:           1.6.1.5 
JIRA:                        
Regression:                 No 
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!):  
Request Review:              
====================================================================== 
Date Submitted:             2009-09-27 17:14 CDT
Last Modified:              2009-09-29 16:28 CDT
====================================================================== 
Summary:                    Huge memory consumption after few hours of load
Description: 
I'm doing load tests on Asterisk 1.6.1.5 and after few hours of load, it
takes 80% of ram (6GB installed), so it becomes unable to fork itself (when
using System() dialplan app), and creating core dump takes an hour. Core
dumps are in size of 9 Gigabytes.

Memory summary doesn't show anytingh of much usage:

80469516 bytes allocated (8800 in caches) in 71421 allocations

while top shows:

Mem:   6055876k total,  6009316k used,    46560k free,    19220k buffers
Swap:  4096564k total,  4096548k used,       16k free,   249980k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
15870 asterisk  10 -10 9780m 4.8g 3936 S    6 83.1 505:00.32 asterisk

====================================================================== 

---------------------------------------------------------------------- 
 (0111555) atis (reporter) - 2009-09-29 16:28
 https://issues.asterisk.org/view.php?id=15973#c111555 
---------------------------------------------------------------------- 
I have traced this to the following symptoms:

10:00:01.8290 - Asterisk is up for 1 hour, 45 minutes, 14 seconds,
https://issues.asterisk.org/view.php?id=49#c120
concurrent channels, memory footprint from `pmap -d` is:

mapped: 875912K    writeable/private: 199812K    shared: 0K

10:50:01.8108 - normal activiy, full log grows with 6MB/min, Memory
footprint is the same:

mapped: 878420K    writeable/private: 202916K    shared: 0K

10:50:03.3973 - log file starts to grow 250MB/min, with the following
messages:

[2009-09-29 10:50:03.3933] DEBUG[4110] app_queue.c: It's not our turn
(SIP/inbound-test-80-02407420).
[2009-09-29 10:50:03.3966] VERBOSE[20463] asterisk.c:     -- Remote UNIX
connection

[2009-09-29 10:50:03.3972] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'
[2009-09-29 10:50:03.3973] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'
[2009-09-29 10:50:03.3974] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'
[2009-09-29 10:50:03.3974] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'
[2009-09-29 10:50:03.3974] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'
[2009-09-29 10:50:03.3974] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'
[2009-09-29 10:50:03.3975] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'

...snip...

[2009-09-29 10:50:03.4028] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'
[2009-09-29 10:50:03.4028] DEBUG[5676] channel.c: Failure, could not lock
'0x2bee2d8' after 199 retries!
[2009-09-29 10:50:03.4028] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'

...snip...

[2009-09-29 10:50:46.9004] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'
[2009-09-29 10:50:46.9004] DEBUG[6023] res_timing_pthread.c: Reading not
available on timing pipe, quantity: 1
[2009-09-29 10:50:46.9004] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'

...snip...

[2009-09-29 10:50:47.9225] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'
[2009-09-29 10:50:47.9226] DEBUG[6023] res_timing_pthread.c: Reading not
available on timing pipe, quantity: 1
[2009-09-29 10:50:47.9225] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'
[2009-09-29 10:50:47.9227] DEBUG[6023] res_timing_pthread.c: Reading not
available on timing pipe, quantity: 1
[2009-09-29 10:50:47.9227] DEBUG[6023] res_timing_pthread.c: Reading not
available on timing pipe, quantity: 1
[2009-09-29 10:50:47.9228] DEBUG[6023] res_timing_pthread.c: Reading not
available on timing pipe, quantity: 1
[2009-09-29 10:50:47.9228] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'
[2009-09-29 10:50:47.9228] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'
[2009-09-29 10:50:47.9228] DEBUG[6023] res_timing_pthread.c: Reading not
available on timing pipe, quantity: 1
[2009-09-29 10:50:47.9228] DEBUG[5676] channel.c: Avoiding deadlock for
channel '0x2bee2d8'

...

total: 
2166295 lines of Avoiding deadlock
10831 lines of Failure, 199 retries
376843 lines of Reading not available

Dialplan continues to exectue between those messages

2009-09-29 10:51:01.8585 - memory footprint is still similar:

mapped: 878456K    writeable/private: 202952K    shared: 0K

10:52:02.7206 memory footprint starts increasing:

mapped: 1032008K    writeable/private: 395276K    shared: 0K

10:52:17.4263 - last message in log:

[2009-09-29 10:52:17.4263] DEBUG[6023] res_timing_pthread.c: Reading not
available on timing pipe, quantity: 1

10:53:02.1428 - 

mapped: 1599880K    writeable/private: 780584K    shared: 0K

10:54:02.6238 - 

mapped: 1689752K    writeable/private: 1024204K    shared: 0K

10:55:02.6746 - 

mapped: 1841996K    writeable/private: 1253628K    shared: 0K

10:56:02.2236 -

mapped: 2458796K    writeable/private: 1610912K    shared: 0K

After this my script kills asterisk, but from previous tests it would
continue to eat memory.

Missing logging could be unrelated, as for previous cases I remember
seeing some logging, however it was quite unusable, as i did lots of tests
before on that machine. 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2009-09-29 16:28 atis           Note Added: 0111555                          
======================================================================




More information about the asterisk-bugs mailing list