[asterisk-bugs] [JIRA] (ASTERISK-27987) AGI() call causes RTP to briefly freeze under certain circumstances

[xrobau (JIRA)]

    [ https://issues.asterisk.org/jira/browse/ASTERISK-27987?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=244311#comment-244311 ] 

xrobau commented on ASTERISK-27987:
-----------------------------------

Now that you guys managed to help me nail it down to being inside fork(), that let me write some test code to validate the problem, which is attached as forktest.c (MIT Licence).  This let me confirm that it only happens on RHEL7 machines:

{code}
[root at freepbx g]# gcc -v
Using built-in specs.
COLLECT_GCC=/usr/bin/gcc
COLLECT_LTO_WRAPPER=/usr/libexec/gcc/x86_64-redhat-linux/4.8.5/lto-wrapper
Target: x86_64-redhat-linux
Configured with: ../configure --prefix=/usr --mandir=/usr/share/man --infodir=/usr/share/info --with-bugurl=http://bugzilla.redhat.com/bugzilla --enable-bootstrap --enable-shared --enable-threads=posix --enable-checking=release --with-system-zlib --enable-__cxa_atexit --disable-libunwind-exceptions --enable-gnu-unique-object --enable-linker-build-id --with-linker-hash-style=gnu --enable-languages=c,c++,objc,obj-c++,java,fortran,ada,go,lto --enable-plugin --enable-initfini-array --disable-libgcj --with-isl=/builddir/build/BUILD/gcc-4.8.5-20150702/obj-x86_64-redhat-linux/isl-install --with-cloog=/builddir/build/BUILD/gcc-4.8.5-20150702/obj-x86_64-redhat-linux/cloog-install --enable-gnu-indirect-function --with-tune=generic --with-arch_32=x86-64 --build=x86_64-redhat-linux
Thread model: posix
gcc version 4.8.5 20150623 (Red Hat 4.8.5-28) (GCC)
[root at freepbx g]# gcc -O2 -o f forktest.c
[root at freepbx g]# time ./f
Time taken per fork:            0.000257
Time taken with 500MB:          0.001201
Time taken with 1GB:            0.002084
Time taken with 2GB:            0.003870
Time taken with 4GB:            0.007358

real    0m3.324s
user    0m0.362s
sys     0m2.957s
[root at freepbx g]#
{code}

This does NOT happen on newer machines.  This left (what I thought) was two variables, the kernel - which I had already crossed off - and glibc.  I tried installing a secondary glibc, and that did NOT speed up the fork()'s.  However, as part of building a new glibc, I needed to install a new gcc as well.

{code}
[root at freepbx g]# gcc -v
Using built-in specs.
COLLECT_GCC=gcc
COLLECT_LTO_WRAPPER=/opt/rh/devtoolset-7/root/usr/libexec/gcc/x86_64-redhat-linux/7/lto-wrapper
Target: x86_64-redhat-linux
Configured with: ../configure --enable-bootstrap --enable-languages=c,c++,fortran,lto --prefix=/opt/rh/devtoolset-7/root/usr --mandir=/opt/rh/devtoolset-7/root/usr/share/man --infodir=/opt/rh/devtoolset-7/root/usr/share/info --with-bugurl=http://bugzilla.redhat.com/bugzilla --enable-shared --enable-threads=posix --enable-checking=release --enable-multilib --with-system-zlib --enable-__cxa_atexit --disable-libunwind-exceptions --enable-gnu-unique-object --enable-linker-build-id --with-gcc-major-version-only --enable-plugin --with-linker-hash-style=gnu --enable-initfini-array --with-default-libstdcxx-abi=gcc4-compatible --with-isl=/builddir/build/BUILD/gcc-7.3.1-20180303/obj-x86_64-redhat-linux/isl-install --enable-libmpx --enable-gnu-indirect-function --with-tune=generic --with-arch_32=i686 --build=x86_64-redhat-linux
Thread model: posix
gcc version 7.3.1 20180303 (Red Hat 7.3.1-5) (GCC)
[root at freepbx g]# gcc -O2 -o f forktest.c
[root at freepbx g]# time ./f
Time taken per fork:            0.000250
Time taken with 500MB:          0.000248
Time taken with 1GB:            0.000248
Time taken with 2GB:            0.000247
Time taken with 4GB:            0.000245

real    0m0.125s
user    0m0.074s
sys     0m0.063s
[root at freepbx g]#
{code}

This is still using the older glibc, which confirms it is a compiler issue, not a glibc issue:

{code}
[root at freepbx g]# ldd -v ./f
        linux-vdso.so.1 =>  (0x00007ffc4f32a000)
        libc.so.6 => /lib64/libc.so.6 (0x00007fcc1f5a8000)
        /lib64/ld-linux-x86-64.so.2 (0x00007fcc1f975000)

        Version information:
        ./f:
                libc.so.6 (GLIBC_2.2.5) => /lib64/libc.so.6
        /lib64/libc.so.6:
                ld-linux-x86-64.so.2 (GLIBC_2.3) => /lib64/ld-linux-x86-64.so.2
                ld-linux-x86-64.so.2 (GLIBC_PRIVATE) => /lib64/ld-linux-x86-64.so.2
[root at freepbx g]#
{code}




> AGI() call causes RTP to briefly freeze under certain circumstances
> -------------------------------------------------------------------
>
>                 Key: ASTERISK-27987
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-27987
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Core/Bridging
>    Affects Versions: 15.5.0
>            Reporter: xrobau
>            Assignee: Unassigned
>              Labels: patch, pjsip
>         Attachments: agi-time.diff, broken.pcap, debug-server.txt, fdlist.txt, forktest.c, pcap1.png, pcap2.png, timer_list.txt
>
>
> "Something" causes Asterisk to get into a state where launching an AGI causes the entire process to freeze briefly.
> The symptoms are identical to ASTERISK-26257, but that is inaccurate as to the number of services that are impacted.
> Currently I am unable to create an artificial reproduction of the CAUSE, but the symptoms are extremely obvious.
> When Asterisk gets into this state (however it may occur) anything that is reading audio from the filesystem (MoH, Playback()/Background(), or Voicemail) OR confbridge conferences (not meetme) will briefly pause while an AGI is launched.
> We have numerous wireshark captures that show this happening (which we can attach if required), and the timestamps as generated by Asterisk are correct for when the packet WAS sent, not for when it SHOULD have been sent.
> This is triggered by AGI calls in dialplan.  Our test dialplan to determine if Asterisk is in this state is as follows:
> {code}
> exten => 998,1,Answer
>  same => n,Dial(Local/999 at from-internal-custom/n,300,gm(default))
>  same => n,Playback(beep)
>  same => n,Goto(1)
> exten => 999,1,Set(COUNT=0)
>  same => n(loop),GotoIf($[ ${COUNT} > 1000 ]?toomany)
>  same => n,Gosub(testtrigger)
>  same => n,Set(COUNT=$[ ${COUNT} + 1 ])
>  same => n,Goto(loop)
>  same => n(toomany),Hangup
>  same => n(testtrigger),AGI(/bin/true)
>  same => n,Return
> {code}
> If Asterisk is in this broken state, the MoH will be extremely choppy.  After a restart of Asterisk, the MoH is not interrupted.
> We've also noticed that the loop runs MUCH slower when Asterisk is in this state. 
> My random, and probably incorrect, hypothesis is that there's a core lock somewhere that is being grabbed by res_agi which is appending to a gradually growing list, or SOMETHING, that takes a longer and longer time, until it's locking up for longer than 20msec and blocking things that are reading from files (and whatever confbridge is doing)
> I ran that dialplan on a test machine, and was unable to get Asterisk into that state after 250,000 AGI calls. However, our (Sangoma)'s main PBX does randomly and sporadically experience this problem, and we've just got into the habit of restarting asterisk whenever we notice it, which has never been below 30,000 calls (calls as reported by 'core show calls'), and is almost certain to be in that state over 50,000 calls.
> The only common factor that is visible, so far, is that this only happens on Hardware, not in VMs (which may be a red herring), and that all the machines have a lot of listeners to AMI Events.
> Unfortunately, without any way to reproduce this, I'm aware that it's hard to proceed further. However, if there's any more information I can provide when a machine IS in this state, as to what may be causing it, please feel free to ask. 
> Fixing it, as above, is as simple as 'core restart now'. The AGI loops runs fast, and the audio glitch vanishes.



--
This message was sent by Atlassian JIRA
(v6.2#6252)