Hello, I've recently setup a small load test against an instance of Asterisks. I've tested on asterisk 13.5 and 14.6 with the same results. I am using PJSIP. My dial plan is, [test] exten => 1001,1,Answer exten => 1001,n,MusicOnHold(15) exten => 1001,n,Hangup I am using SIPP to test. I can share XML if desired but it simply waits on the line while music plays for 8 seconds. I used sippycup to generate it with the following steps in the yaml file. steps: - invite - wait_for_answer - ack_answer - sleep 8 - send_bye At around 500 calls per second I begin to see the following ERRORs, [Aug 28 17:46:14] ERROR[26150][C-00005594]: frame.c:343 ast_frdup: Excessive refcount 100000 reached on ao2 object 0x26bffc0 [Aug 28 17:46:14] ERROR[26150][C-00005594]: frame.c:343 ast_frdup: FRACK!, Failed assertion Excessive refcount 100000 reached on ao2 object 0x26bffc0 (0) Got 19 backtrace records #0: [0x45d229] /usr/sbin/asterisk(__ao2_ref+0x1a9) [0x45d229] #1: [0x526ce6] /usr/sbin/asterisk(ast_frdup+0x116) [0x526ce6] #2: [0x5fa616] /usr/sbin/asterisk(ast_translate+0x306) [0x5fa616] #3: [0x4bf16b] /usr/sbin/asterisk(ast_write+0x104b) [0x4bf16b] #4: [0x7efeb578230b] /usr/lib/asterisk/modules/res_musiconhold.so(+0x430b) [0x7efeb578230b] #5: [0x4b5b52] /usr/sbin/asterisk() [0x4b5b52] #6: [0x4c259c] /usr/sbin/asterisk() [0x4c259c] #7: [0x4c4a45] /usr/sbin/asterisk() [0x4c4a45] #8: [0x7efeb578478d] /usr/lib/asterisk/modules/res_musiconhold.so(+0x678d) [0x7efeb578478d] #9: [0x58ec79] /usr/sbin/asterisk(pbx_exec+0xb9) [0x58ec79] #10: [0x582e84] /usr/sbin/asterisk() [0x582e84] #11: [0x584e7c] /usr/sbin/asterisk() [0x584e7c] #12: [0x5863fb] /usr/sbin/asterisk() [0x5863fb] #13: [0x60002a] /usr/sbin/asterisk() [0x60002a] I've also seen similar behavior when using playback instead of MusicOnHold. CPU usage gets around 50%. Can anyone enlighten me on the meaning and cause of the error? Is there some steps (config etc) that can be taken to alleviate the issue? Thanks Joseph -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20170828/c6c356d3/attachment.html>
Richard Mudgett
2017-Aug-28 19:17 UTC
[asterisk-users] ERROR during high volume MoH dialplan
On Mon, Aug 28, 2017 at 1:04 PM, Joseph Smith <warlock1999 at hotmail.com> wrote:> Hello, > > I've recently setup a small load test against an instance of Asterisks. > I've tested on asterisk 13.5 and 14.6 with the same results. >I think you mean 13.15.0 as the excessive ref count trap is not in 13.5.0.> I am using PJSIP. My dial plan is, > > [test] > > exten => 1001,1,Answer > > exten => 1001,n,MusicOnHold(15) > > exten => 1001,n,Hangup > > > I am using SIPP to test. I can share XML if desired but it simply waits > on the line while music plays for 8 seconds. I used sippycup to generate > it with the following steps in the yaml file. > > > steps: > > - invite > > - wait_for_answer > > - ack_answer > > - sleep 8 > > - send_bye > > > At around 500 calls per second I begin to see the following ERRORs, > > > [Aug 28 17:46:14] ERROR[26150][C-00005594]: frame.c:343 ast_frdup: > Excessive refcount 100000 reached on ao2 object 0x26bffc0 > > [Aug 28 17:46:14] ERROR[26150][C-00005594]: frame.c:343 ast_frdup: FRACK!, > Failed assertion Excessive refcount 100000 reached on ao2 object 0x26bffc0 > (0) > > Got 19 backtrace records > > #0: [0x45d229] /usr/sbin/asterisk(__ao2_ref+0x1a9) [0x45d229] > > #1: [0x526ce6] /usr/sbin/asterisk(ast_frdup+0x116) [0x526ce6] > > #2: [0x5fa616] /usr/sbin/asterisk(ast_translate+0x306) [0x5fa616] > > #3: [0x4bf16b] /usr/sbin/asterisk(ast_write+0x104b) [0x4bf16b] > > #4: [0x7efeb578230b] /usr/lib/asterisk/modules/res_musiconhold.so(+0x430b) > [0x7efeb578230b] > > #5: [0x4b5b52] /usr/sbin/asterisk() [0x4b5b52] > > #6: [0x4c259c] /usr/sbin/asterisk() [0x4c259c] > > #7: [0x4c4a45] /usr/sbin/asterisk() [0x4c4a45] > > #8: [0x7efeb578478d] /usr/lib/asterisk/modules/res_musiconhold.so(+0x678d) > [0x7efeb578478d] > > #9: [0x58ec79] /usr/sbin/asterisk(pbx_exec+0xb9) [0x58ec79] > > #10: [0x582e84] /usr/sbin/asterisk() [0x582e84] > > #11: [0x584e7c] /usr/sbin/asterisk() [0x584e7c] > > #12: [0x5863fb] /usr/sbin/asterisk() [0x5863fb] > > #13: [0x60002a] /usr/sbin/asterisk() [0x60002a] > >This inline backtrace would be more useful if you had BETTER_BACKTRACES enabled.> > I've also seen similar behavior when using playback instead of > MusicOnHold. CPU usage gets around 50%. Can anyone enlighten me on the > meaning and cause of the error? Is there some steps (config etc) that can > be taken to alleviate the issue? >This particular FRACK is meant to help find ao2 object reference leaks. It acts as an early warning for excessive references to any particular ao2 object used in the code. The FRACK itself is benign. Based upon the inline backtrace the ao2 object is likely to be a codec format. * What codecs are you using in this setup? * With 500 calls/sec and the calls lasting 8 seconds that comes to 4000 active channels. Hitting the FRACK would result in an average of 25 references to the format per channel. This is a simplistic calculation as there are going to be some references that have nothing to do with a call. The number of base references would depend upon which codec is involved. * There is no user configurable option to change the excessive ref count trigger value. However, you could change the EXCESSIVE_REF_COUNT define value in the main/astobj2.c file and recompile. Richard -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20170828/1304a594/attachment.html>
Hi Richard, Thank you for the reply Correct, I did mean 13.15. I set no optimize and better backtrace through "make menuselect" and the output is now [Aug 28 21:41:16] ERROR[17171][C-0000392d]: frame.c:343 ast_frdup: FRACK!, Failed assertion Excessive refcount 100000 reached on ao2 object 0x21962b0 (0) Got 26 backtrace records #0: [0x61923f] main/utils.c:2475 __ast_assert_failed() (0x6191bb+84) #1: [0x45ffc9] main/astobj2.c:543 __ao2_ref() (0x45fc3d+38C) #2: [0x5320ce] main/frame.c:345 ast_frdup() (0x531e4c+282) #3: [0x531a99] main/frame.c:196 ast_frisolate() (0x531a76+23) #4: [0x60be51] main/translate.c:459 ast_trans_frameout() (0x60bd6e+E3) #5: [0x60be75] main/translate.c:464 default_frameout() #6: [0x60c46a] main/translate.c:579 ast_translate() (0x60c192+2D8) #7: [0x4c0bf1] main/channel.c:5290 ast_write() (0x4bfb3e+10B3) #8: [0x7fdef8345486] res/res_musiconhold.c:455 moh_files_generator() #9: [0x4ba212] main/channel.c:3014 generator_force() #10: [0x4bc23d] main/channel.c:3872 __ast_read() #11: [0x4be29b] main/channel.c:4399 ast_read() (0x4be27e+1D) #12: [0x4b6312] main/channel.c:1568 ast_safe_sleep_conditional() (0x4b6229+E9) #13: [0x4b64c9] main/channel.c:1613 ast_safe_sleep() (0x4b64a1+28) #14: [0x7fdef8346caa] res/res_musiconhold.c:834 play_moh_exec() #15: [0x5970a3] main/pbx_app.c:491 pbx_exec() (0x596f87+11C) #16: [0x582edf] main/pbx.c:2923 pbx_extension_helper() #17: [0x586c30] main/pbx.c:4155 ast_spawn_extension() (0x586bcc+64) #18: [0x5878bb] main/pbx.c:4328 __ast_pbx_run() #19: [0x589061] main/pbx.c:4651 pbx_thread() #20: [0x61624e] main/utils.c:1233 dummy_start() * What codecs are you using in this setup? In pjsip.conf I have disallow=all and allow=ulaw. If I can provide more information or a better response to this question please guide me on how to do that. Thanks Joseph ________________________________ From: asterisk-users-bounces at lists.digium.com <asterisk-users-bounces at lists.digium.com> on behalf of Richard Mudgett <rmudgett at digium.com> Sent: Monday, August 28, 2017 2:17 PM To: Asterisk Users Mailing List - Non-Commercial Discussion Subject: Re: [asterisk-users] ERROR during high volume MoH dialplan On Mon, Aug 28, 2017 at 1:04 PM, Joseph Smith <warlock1999 at hotmail.com<mailto:warlock1999 at hotmail.com>> wrote: Hello, I've recently setup a small load test against an instance of Asterisks. I've tested on asterisk 13.5 and 14.6 with the same results. I think you mean 13.15.0 as the excessive ref count trap is not in 13.5.0. I am using PJSIP. My dial plan is, [test] exten => 1001,1,Answer exten => 1001,n,MusicOnHold(15) exten => 1001,n,Hangup I am using SIPP to test. I can share XML if desired but it simply waits on the line while music plays for 8 seconds. I used sippycup to generate it with the following steps in the yaml file. steps: - invite - wait_for_answer - ack_answer - sleep 8 - send_bye At around 500 calls per second I begin to see the following ERRORs, [Aug 28 17:46:14] ERROR[26150][C-00005594]: frame.c:343 ast_frdup: Excessive refcount 100000 reached on ao2 object 0x26bffc0 [Aug 28 17:46:14] ERROR[26150][C-00005594]: frame.c:343 ast_frdup: FRACK!, Failed assertion Excessive refcount 100000 reached on ao2 object 0x26bffc0 (0) Got 19 backtrace records #0: [0x45d229] /usr/sbin/asterisk(__ao2_ref+0x1a9) [0x45d229] #1: [0x526ce6] /usr/sbin/asterisk(ast_frdup+0x116) [0x526ce6] #2: [0x5fa616] /usr/sbin/asterisk(ast_translate+0x306) [0x5fa616] #3: [0x4bf16b] /usr/sbin/asterisk(ast_write+0x104b) [0x4bf16b] #4: [0x7efeb578230b] /usr/lib/asterisk/modules/res_musiconhold.so(+0x430b) [0x7efeb578230b] #5: [0x4b5b52] /usr/sbin/asterisk() [0x4b5b52] #6: [0x4c259c] /usr/sbin/asterisk() [0x4c259c] #7: [0x4c4a45] /usr/sbin/asterisk() [0x4c4a45] #8: [0x7efeb578478d] /usr/lib/asterisk/modules/res_musiconhold.so(+0x678d) [0x7efeb578478d] #9: [0x58ec79] /usr/sbin/asterisk(pbx_exec+0xb9) [0x58ec79] #10: [0x582e84] /usr/sbin/asterisk() [0x582e84] #11: [0x584e7c] /usr/sbin/asterisk() [0x584e7c] #12: [0x5863fb] /usr/sbin/asterisk() [0x5863fb] #13: [0x60002a] /usr/sbin/asterisk() [0x60002a] This inline backtrace would be more useful if you had BETTER_BACKTRACES enabled. I've also seen similar behavior when using playback instead of MusicOnHold. CPU usage gets around 50%. Can anyone enlighten me on the meaning and cause of the error? Is there some steps (config etc) that can be taken to alleviate the issue? This particular FRACK is meant to help find ao2 object reference leaks. It acts as an early warning for excessive references to any particular ao2 object used in the code. The FRACK itself is benign. Based upon the inline backtrace the ao2 object is likely to be a codec format. * What codecs are you using in this setup? * With 500 calls/sec and the calls lasting 8 seconds that comes to 4000 active channels. Hitting the FRACK would result in an average of 25 references to the format per channel. This is a simplistic calculation as there are going to be some references that have nothing to do with a call. The number of base references would depend upon which codec is involved. * There is no user configurable option to change the excessive ref count trigger value. However, you could change the EXCESSIVE_REF_COUNT define value in the main/astobj2.c file and recompile. Richard -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20170828/38925ba0/attachment.html>