[Freeswitch-users] High cps load causes weird cpu and memory starvation. Need suggestions on how to debug.

Steven Ayre steveayre at gmail.com
Thu Mar 7 18:12:44 MSK 2013


Upgrade to the latest version.

There are some memory leaks that have been found and fixed in 1.2.7.

-Steve




On 7 March 2013 11:09, bratner bratner <ratner2 at gmail.com> wrote:

> Hi!
>
> Please assist me to find a way to get some insight into this problem and
> file a proper bug report. Looks like 2 different problems, one is load
> related (like a race of some sort) the other is a mem leak.
>
>
> I'm running FS debs compiled on ubuntu 12.04 (-n20130227T114536Z-1~presice+
> 1git).
> The machine is ubuntu 12.04 server , CPU: Intel(R) Xeon(R) CPU E5620  @
> 2.40GHz, 4GB RAM and no swap. 3.1G RAM free after FS is started.
> I disabled HT in BIOS to get proper CPU load readings from top and vmstat
> (no HT also allows for higher cps for some reason...).
>
> The FS setup has 2 SIP profiles , internal/external (functioning as
> incoming/outgoing ), XML Dialplan that runs a lua script.
> Calls come in to profile 'internal',  authed by ip acl , go to the
> dialplan and sent through profile 'external' to a uri string generated by
> the lua script.
>
> I bombard the machine with high call rate of short calls ,120-180cps ,
> 5sec.
> Everything stays fine for some time , the higher the load the faster the
> problems appear.
> When i pressure the machine with 150cps and up , it works fine at first
> with 20%-30% idle CPU.
> After some time passes (10-30minutes) system cpu usage jumps from 3%-7% to
> around 50%, CPU is 95% busy and vmstat reports hundereds and sometimes
> thousands of runnable tasks.
> If i stop sending calls at this moment, wait for the CPU load to wind down
> and start calling again then the CPU load saturates right away. Even if i
> lower the CPS rate.
> restarting freeswitch at this point brings the system to the original
> state and it will take some time to get saturated again.
>
> Another symptom is that during the test the available free mem is slowly
> allocated to freeswitch until it reaches 13.1Gb virtual image and then the
> kernel kills it.
>
> Here are some numbers:
>
> Running 120 calls per second , 5second calls:
>
> Starts like this: This is very good from my POV.
>
> procs -----------memory---------- ---swap-- -----io---- -system--
> ----cpu----
>  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id
> wa
>  5  0      0 3255876  35444  96580    0    0     9     2   66   90  1  1
> 98  0
>  4  0      0 3253080  35444  96652    0    0     0     0 16048 20727 36  3
> 61  0
>  4  0      0 3247780  35444  96684    0    0     0     0 16521 21048 36  4
> 60  0
>  4  0      0 3242860  35444  96784    0    0     0     0 15695 19825 36  3
> 62  0
>  1  0      0 3237980  35452  96768    0    0     0    24 16072 19851 36  3
> 60  0
>  4  0      0 3233692  35452  96812    0    0     0     0 16299 20980 35  4
> 61  0
>  8  0      0 3230280  35452  96928    0    0     0     0 15034 18965 36  3
> 61  0
>  2  0      0 3227764  35452  96896    0    0     0     0 13956 20621 37  3
> 60  0
>
> After some (long) time it started having trouble and eat lots of free ram
> (note that the idle cpu% and system cpu%  jumped up but there are still
> over 1G free mem available) :
>
> procs -----------memory---------- ---swap-- -----io---- -system--
> ----cpu----
>  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id
> wa
> 22  0      0 1108588 100304 2034628    0    0     0     0 145350 183629 37
> 53 10  0
>  5  0      0 1108224 100304 2034668    0    0     0     0 151937 167249 38
> 57  5  0
> 11  0      0 1108268 100304 2034904    0    0     0     0 149931 176143 37
> 58  5  0
>  7  0      0 1108244 100312 2034752    0    0     0    32 138612 183583 40
> 47 14  0
>  3  0      0 1108056 100312 2034792    0    0     0     0 111446 162733 42
> 29 29  0
>  4  0      0 1108064 100312 2034836    0    0     0     0 112568 164187 41
> 30 29  0
> 14  0      0 1108040 100312 2034880    0    0     0     0 133372 174676 39
> 45 17  0
> 10  0      0 1107468 100312 2034920    0    0     0     0 157371 184888 37
> 58  5  0
>
> Short time after that is got into really serious trouble (3000 runnable
> tasks!? heading toward memory exhaustion):
>
> procs -----------memory---------- ---swap-- -----io---- -system--
> ----cpu----
>  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id
> wa
>
> 3336  0      0 146580   9248 1457016    0    0     0     0 306642 291819
> 28 67  5  0
> 1180  0      0 145060   9220 1430212    0    0   248   848 294654 285273
> 27 68  5  0
> 1028  0      0 148616   8996 1366844    0    0     0     0 421614 385342
> 32 63  4  0
> 1026  0      0 150964   8880 1298832    0    0     0    28 462825 416480
> 31 65  4  0
> 1338  0      0 146260   8688 1242440    0    0     0     0 442247 391139
> 27 69  5  0
> 1945  0      0 143148   8680 1197180    0    0     0     0 364361 329958
> 24 71  5  0
> 1381  0      0 154668   8596 1137912    0    0     0     0 359982 323543
> 23 72  5  0
>
>
> After UAC completed transactions 5198242/ UAS completed transactions
> 5512619 calls FS crashed and it looked like this:
>
> procs -----------memory---------- ---swap-- -----io---- -system--
> ----cpu----
>  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id
> wa
>
> 3  2      0  92972    568  20492    0    0   156     8 117314 130220  7 40
> 38 15   <-- back in the day i would kill for 92Mb free mem.
> 10  5      0 3473328    208   9848    0    0 24344    48 104557 89011  5
> 62 15 17   <- Now the kernel kills FS for taking the rest of it.
>  8  0      0 3482436    340  14408    0    0  3208     0 2582 2046  0 95
> 4  1
>  9  0      0 3504792    348  14344    0    0     0    48 2312 1836  0 93
> 7  0
> 12  0      0 3532184    348  14348    0    0     0     0 2387 1984  0 94
> 6  0
>  6  0      0 3561792    348  14876    0    0   528     0 2523 2178  0 93
> 6  0
> 11  0      0 3592816    348  14876    0    0     0     0 2684 2248  0 95
> 5  0
>  3  0      0 3615424    348  14876    0    0     0     0 2820 2494  0 95
> 5  0
>  7  0      0 3633488    348  14876    0    0     0     0 2990 2805  0 94
> 6  0
>  7  0      0 3654916    348  14876    0    0     0     0 3350 3222  0 96
> 4  0
> 11  0      0 3680708    348  14876    0    0     0     0 3869 4018  0 94
> 6  0
>  0  0      0 3773532    476  16876    0    0  2344     0 6598 9501  0 74
> 24  2
>  0  0      0 3773836    476  16912    0    0     0     0  191  129  0  0
> 100  0   <- FS is not running any more, 100% idle CPU , lots of free ram
>  0  0      0 3773856    476  17108    0    0     0     0   91   63  0  0
> 100  0
>
>
>
> dmesg of the crash is this:
>
> [48674.576126] Out of memory: Kill process 31552 (freeswitch) score 674 or
> sacrifice child
> [48674.578188] Killed process 31552 (freeswitch) total-vm:10177480kB,
> anon-rss:2710092kB, file-rss:0kB
>
> fs_log switches to the dark side : (there was no disk space problem of
> course, i have no idea at which time point in the spiral down this popped
> on the console )
>
> 2013-03-06 23:27:22.923640 [ERR] switch_core_sqldb.c:579 NATIVE SQL ERR
> [database or disk is full]
> BEGIN EXCLUSIVE
> 2013-03-06 23:27:22.923640 [CRIT] switch_core_sqldb.c:1679 ERROR [database
> or disk is full]
> 2013-03-06 23:27:22.923640 [ERR] switch_core_sqldb.c:579 NATIVE SQL ERR
> [cannot commit - no transaction is active]
> COMMIT
> 2013-03-06 23:27:22.963609 [CRIT] switch_core_session.c:1674 Thread
> Failure!
> 2013-03-06 23:27:22.963609 [CRIT] switch_core_session.c:1634 LUKE: I'm
> hit, but not bad.
> 2013-03-06 23:27:22.963609 [CRIT] switch_core_session.c:1635 LUKE'S VOICE:
> Artoo, see what you can do with it. Hang on back there....
> Green laserfire moves past the beeping little robot as his head turns.
> After a few beeps and a twist of his mechanical arm,
> Artoo reduces the max sessions to 13897 thus, saving the switch from
> certain doom.
>
> and thats all , FS is dead.
>
> Runing the test at 180 cps will significantly hasten the death.
> It starts normal with ~40% idle cpu
> then after circa 160k calls it starts to spiral:
> procs -----------memory---------- ---swap-- -----io---- -system--
> ----cpu----
>  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id
> wa
>  6  0      0 2901484  63204 161132    0    0     0     0 20586 33073 54  5
> 41  0
>  5  0      0 2901468  63212 160988    0    0     0    12 25359 41915 53  6
> 42  0
>  4  0      0 2901220  63212 161064    0    0     0     0 19650 31211 55  5
> 40  0
>  7  0      0 2901080  63212 161124    0    0     0     0 21148 33462 54  5
> 41  0
>  2  0      0 2900676  63212 161188    0    0     0     0 21767 35568 54  5
> 42  0
>  5  0      0 2900468  63212 161256    0    0     0     0 19398 30073 54  5
> 41  0
>  2  0      0 2900088  63220 161304    0    0     0    12 21315 34563 54  5
> 42  0
>  3  0      0 2900180  63220 161484    0    0     0     0 19858 31561 42  4
> 54  0       <-- this should not happen the load is constant and idle cpu%
> should stay at ~40%
>  3  0      0 2899768  63220 161520    0    0     0     0 29907 46883 39  4
> 57  0
> 11  0      0 2900056  63220 161504    0    0     0     0 41730 63440 41  5
> 54  0
>  9  0      0 2899536  63220 161768    0    0     0     0 48876 68159 40  5
> 54  0
>  6  0      0 2899512  63228 161620    0    0     0    12 59988 80421 41  6
> 53  0
> 49  0      0 2876072  63228 162004    0    0     0     0 193384 241453 57
> 23 21  0      <-- here we go,  starting the memory hogging cpu eating spiral
> 40  0      0 2830720  63228 162080    0    0     0     0 308948 356178 51
> 49  0  0
> 156  0      0 2776576  63228 161984    0    0     0     0 301514 325415 48
> 48  5  0
> 178  0      0 2727044  63228 162260    0    0     0     0 290168 306158 44
> 51  5  0
> 70  0      0 2683252  63236 161924    0    0     0    48 291792 302632 37
> 58  5  0
>  5  0      0 2618432  63236 162204    0    0     0     0 316170 302886 35
> 59  7  0
>  2  0      0 2548092  63236 162364    0    0     0     0 340707 319105 38
> 56  5  0
>  2  0      0 2460528  63236 162464    0    0     0  1596 386953 348210 40
> 54  6  0
>
> Nothing on fs warn/err log at this point until memory is all full.
>
>
> Please give me some ideas on how to get some useful info for a bug report.
>
> Kind Regards,
> Boris Ratner.
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
> 
> 
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://wiki.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20130307/3b7ae3e4/attachment-0001.html 


Join us at ClueCon 2011 Aug 9-11, 2011
More information about the FreeSWITCH-users mailing list