[asterisk-bugs] [JIRA] (ASTERISK-21872) RFC2833 DTMF Events received at a very fast interval, ~25ms, results in high CPU and when running in -p results in RTP packet sending delays

[hristo (JIRA)]

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

hristo commented on ASTERISK-21872:
-----------------------------------

I can confirm that by default the call generator sends 260ms long DTMFs with 40ms pauses between two DTMFs. That's roughly a rate of 3 DTMFs per second per call. Indeed, I can see in the captures that there is a 40ms pause between the last 'end' Event and the next Event packet. 40 ms is on the RFC boundary, but still within limits. All of the tests from my previous posts were made with the default setting of 40ms.

As for the possibility to trigger this from an end device - this is indeed possible. I can see that SNOM 370 for example sends the DTMFs with roughly 30ms pause between two digits. Moreover, the DTMFs seem to have a minimum enforced duration of 120 ms, which is about 8 DTMFs per second. Hitting a button 8 times per second is really not that hard.

I couldn't test with exactly 50ms DTMF pauses, because the G711 codec used in the test calls is set to 20ms samples and it seems that this also affects the pause between the DTMFs, which has to be in 20ms steps too. I can reconfigure the codec to use 10ms samples and I should then be able to test with 50ms inter DTMF pauses, but for now I did the tests with 60ms between DTMFs.

When I set the pause to 60ms I get mixed results:
* A single call no longer seems to trigger the problem.
* I am sometimes able to reproduce it with as little as 6 concurrent calls (all sending DTMFs with 60 ms pause and 240ms duration). The more concurrent calls I have, the easier it is to reproduce the problem. It seems that there is no magic number after which I can reproduce this with 100% success rate, but at 30 concurrent calls it happens almost every time.
* If I decrease the DTMF duration to say 80ms and keep the pause at 60 ms, then I am able to send more DTMFs per second per call and in this case I need less concurrent calls to trigger the probelm.
* The problem doesn't appear immediately after all the calls have started sending DTMFs. It takes some time into the test (sometime 1-2 seconds sometimes 5-6) before the CPU usage starts increasing, but once it starts it looks like it will almost always go all the way up to 100%, provided the test doesn't end in the meantime.
* Regardless of what I set for pause and duration, I was never able to load the server at say 60% or 80%. The problem is either there and the CPU goes to 100% or it is only slightly affected, leaving the CPU at around 10-20%, which I would consider normal. It looks like an all-or-nothing case.

I have made the tests both on the Ubuntu and the Debian servers and haven't noticed any major difference.
                
> RFC2833 DTMF Events received at a very fast interval,~25ms, results in high CPU and when running in -p results in RTP packet sending delays
> -------------------------------------------------------------------------------------------------------------------------------------------
>
>                 Key: ASTERISK-21872
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-21872
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Core/General
>    Affects Versions: 1.8.17.0, 1.8.19.1, 1.8.20.0, 1.8.22.0
>         Environment: Debian 6.0 64-bit
>            Reporter: hristo
>            Assignee: hristo
>            Severity: Minor
>         Attachments: 2-calls-one-sending-many-dtmfs-asterisk-debug.txt, forward-stream-first-call-after-asterisk.pcap.txt, forward-stream-first-call-before-asterisk.pcap.txt, sample-config.diff, vmstat.txt
>
>
> If I send several DTMFs to Asterisk, one after the other, fast enough, it blocks other voice RTP packets for as long as several hundred milliseconds. This seems to affects *all* RTP streams on a server.
> I can say for sure, that Asterisk is not dropping the RTP packets, because after a while it sends all of them at once. It seems as if they are being held by something, while the DTMFs are being processed/forwarded.
> This only occurs in non Packet2Packet mode.
> Originally I've seen the problem when several people were connecting to a conference at about the same time and were entering the PIN numbers at about the same time, therefore producing a lot of DTMFs. The conference runs on a dedicate hardware und is unrelated. Asterisk just sits in the middle and bridges the calls. I have managed to reproduce this with only two calls with as little as 10-15 DTMFs, provided they are send fast enough.
> Attaching is a debug console log from the following call scenario. In this case both calls were genereted from a dedicated server and terminated on another dedicated server.
> Call 1:
>  A (IP 1.1.1.1) dials 1000 --> Asterisk (IP 2.2.2.2) ---> B (IP 3.3.3.3)
> Call 2:
>  A' (IP 1.1.1.1) dials 2000 --> Asterisk (IP 2.2.2.2) ---> B' (IP 3.3.3.3)
> Both calls are active at this point. A' on Call 2 starts sending DTMFs (in this case 40 of them). As a result RTP packets from Call *1* in both directions are delayed by 150-160 ms and are being sent in bursts.
> In the logs I often see:
> res_timing_timerfd.c:225 timerfd_timer_ack: Expected to acknowledge 1 ticks but got 5 instead
> and the CPU is close to 100% (caused by the asterisk process). As soon as all DTMFs are sent, the RTP streams return back to normal with asterisk sending one packet every 20 ms on average.
> Attached is also a filtered packet capture that shows only the forward RTP stream on Call 1 from A -> Asterisk and from Asterisk -> B. "Time" represents the delta from the previos packet. Under normal conditions this should be close to 0.020 s (or 20 ms).
> One example of the problem can be seen at line 1235 in 'forward-stream-first-call-after-asterisk.pcap.txt'. The packet there has been held for ~160 ms, then sent together with the next 7 packets all at once.
> The RTP packets from the corresponding call leg (before asterisk) start at line 1244 in 'forward-stream-first-call-before-asterisk.pcap.txt" and are all equally spaced at about 20 ms.
> There are many such examples - simply search for 0.000 (deltas which are less than 1 ms) to identify groups of packets that are sent together. The same problem is present in the backward stream too (not attached).
> How to reproduce - add the following to the dialplan:
> exten => _X.,n,Dial(SIP/B at 3.3.3.3,,t)
> The 't' option is important, because it effectively disables the Packet2Packet mode. Connect 2 calls (2 sets of telephones) and start dialing DTMFs as fast as you can on one of them (or simply generate 2 calls and send the DTMFs as I did). This will disrupt the call between the other set of phones if done fast enough.
> I have tested this on 3 servers (2 physical and one virtual). All of them were running the same OS (Debian 6), so this may end up being an OS or res_timing_timerfd problem after all, but I really cannot test it on a different distribution.
> I tested with the following versions and was able to reproduce the problem with all of them:
> 1.8.22.0
> 1.8.20.0
> 1.8.19.1
> 1.8.17.0

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.asterisk.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira