Long delay in dialing

FreePBX Providers
1

Hi everyone, I’m having a problem with long delay in dialing for 3 days now, still no solution so I’m hoping someone knows how to fix it.
So i had this problem on freepbx 13 so i installed it on a new VM with latest freepbx 15 the VM have 32 GB ram and 32 CPUs. mostly i use PJSIP also Ichecked DNS and tried to another provider same issue with the delay

Here’s a call trace if anyone can help much appreciated.

Line 1131347: [2020-07-21 16:58:39] VERBOSE[644][C-00000b9f] pbx.c: Executing [0141361268@from-internal:1] Macro(“PJSIP/3003-00000a54”, “user-callerid,LIMIT,EXTERNAL,”) in new stack
Line 1132084: [2020-07-21 16:59:02] VERBOSE[644][C-00000b9f] pbx.c: Executing [0141361268@from-internal:2] Gosub(“PJSIP/3003-00000a54”, “sub-record-check,s,1(out,0141361268,force)”) in new stack
Line 1132084: [2020-07-21 16:59:02] VERBOSE[644][C-00000b9f] pbx.c: Executing [0141361268@from-internal:2] Gosub(“PJSIP/3003-00000a54”, “sub-record-check,s,1(out,0141361268,force)”) in new stack
Line 1132135: [2020-07-21 16:59:02] VERBOSE[644][C-00000b9f] pbx.c: Executing [out@sub-record-check:1] NoOp(“PJSIP/3003-00000a54”, “Outbound Recording Check from 3003 to 0141361268”) in new stack
Line 1132167: [2020-07-21 16:59:02] VERBOSE[644][C-00000b9f] pbx.c: Executing [out@sub-record-check:7] Gosub(“PJSIP/3003-00000a54”, “recordcheck,1(force,out,0141361268)”) in new stack
Line 1132273: [2020-07-21 16:59:02] VERBOSE[644][C-00000b9f] pbx.c: Executing [recordcheck@sub-record-check:16] NoOp(“PJSIP/3003-00000a54”, “Starting recording: out, 0141361268”) in new stack
Line 1132276: [2020-07-21 16:59:02] VERBOSE[644][C-00000b9f] pbx.c: Executing [recordcheck@sub-record-check:17] Set(“PJSIP/3003-00000a54”, “__CALLFILENAME=out-0141361268-3003-20200721-165902-1595343519.5579”) in new stack
Line 1132284: [2020-07-21 16:59:02] VERBOSE[644][C-00000b9f] pbx.c: Executing [recordcheck@sub-record-check:18] MixMonitor(“PJSIP/3003-00000a54”, “2020/07/21/out-0141361268-3003-20200721-165902-1595343519.5579.wav,abi(LOCAL_MIXMON_ID),”) in new stack
Line 1132771: [2020-07-21 16:59:02] VERBOSE[644][C-00000b9f] pbx.c: Executing [recordcheck@sub-record-check:22] Set(“PJSIP/3003-00000a54”, “CDR(recordingfile)=out-0141361268-3003-20200721-165902-1595343519.5579.wav”) in new stack
Line 1134017: [2020-07-21 16:59:54] VERBOSE[644][C-00000b9f] pbx.c: Executing [0141361268@from-internal:3] ExecIf(“PJSIP/3003-00000a54”, “0 ?Set(CDR(accountcode)=)”) in new stack
Line 1134019: [2020-07-21 16:59:54] VERBOSE[644][C-00000b9f] pbx.c: Executing [0141361268@from-internal:4] Set(“PJSIP/3003-00000a54”, “_ROUTEID=1”) in new stack
Line 1134022: [2020-07-21 16:59:54] VERBOSE[644][C-00000b9f] pbx.c: Executing [0141361268@from-internal:5] Set(“PJSIP/3003-00000a54”, “_ROUTENAME=fixes”) in new stack
Line 1134025: [2020-07-21 16:59:54] VERBOSE[644][C-00000b9f] pbx.c: Executing [0141361268@from-internal:6] Set(“PJSIP/3003-00000a54”, “MOHCLASS=default”) in new stack
Line 1134027: [2020-07-21 16:59:54] VERBOSE[644][C-00000b9f] pbx.c: Executing [0141361268@from-internal:7] Set(“PJSIP/3003-00000a54”, “_CALLERIDNAMEINTERNAL=Hotline Mobile”) in new stack
Line 1134029: [2020-07-21 16:59:54] VERBOSE[644][C-00000b9f] pbx.c: Executing [0141361268@from-internal:8] Set(“PJSIP/3003-00000a54”, “_CALLERIDNUMINTERNAL=3003”) in new stack
Line 1134043: [2020-07-21 16:59:54] VERBOSE[644][C-00000b9f] pbx.c: Executing [0141361268@from-internal:9] Set(“PJSIP/3003-00000a54”, “_EMAILNOTIFICATION=FALSE”) in new stack
Line 1134085: [2020-07-21 16:59:54] VERBOSE[644][C-00000b9f] pbx.c: Executing [0141361268@from-internal:10] Set(“PJSIP/3003-00000a54”, “_NODEST=”) in new stack
Line 1134089: [2020-07-21 16:59:54] VERBOSE[644][C-00000b9f] pbx.c: Executing [0141361268@from-internal:11] Macro(“PJSIP/3003-00000a54”, “dialout-trunk,6,0033141361268,on”) in new stack
Line 1137112: [2020-07-21 17:01:01] VERBOSE[644][C-00000b9f] pbx.c: Executing [s@macro-dialout-trunk:34] Dial(“PJSIP/3003-00000a54”, “SIP/TRUNK-/0033141361268,300,Tb(func-apply-sipheaders^s^1,(6))U(sub-send-obroute-email^0033141361268^0141361268^6^1595343542^^0980090414)”) in new stack
Line 1137209: [2020-07-21 17:01:01] VERBOSE[644][C-00000b9f] app_stack.c: Spawn extension (from-trunk-sip-TRUNKSod488116334-, 0141361268, 1) exited non-zero on ‘SIP/TRUNK–00000b08’
Line 1138795: [2020-07-21 17:01:06] VERBOSE[644][C-00000b9f] pbx.c: Spawn extension (from-internal, 0141361268, 11) exited non-zero on ‘PJSIP/3003-00000a54’
Line 1138800: [2020-07-21 17:01:06] VERBOSE[644][C-00000b9f] pbx.c: Executing [s@macro-hangupcall:4] NoOp(“PJSIP/3003-00000a54”, “SIP/TRUNK–00000b08 montior file= /var/spool/asterisk/monitor/2020/07/21/out-0141361268-3003-20200721-165902-1595343519.5579.wav”) in new stack
Line 1138802: [2020-07-21 17:01:06] VERBOSE[644][C-00000b9f] pbx.c: Executing [s@macro-hangupcall:6] AGI(“PJSIP/3003-00000a54”, “agi://127.0.0.1/attendedtransfer-rec-restart.php,SIP/TRUNK–00000b08,/var/spool/asterisk/monitor/2020/07/21/out-0141361268-3003-20200721-165902-1595343519.5579.wav”) in new stack

2

There’s a 30-second pause here, and the only thing I can think of that might do that is a bad disk or a bad DNS setting. There are a couple other pauses like this when the system goes to talk to the disk, so I’d start there.

3

Thanks for your input, I’m using a VM, disk bus SCSI you think changing the bus type to SATA or IDE it would work normally? also the recording are been saved into a mounted NAS with ssh disk. as for dns setting 127.0.0.1 and 8.8.4.4.

4

Hi, so I checked what you said Dave, so I installed freepbx on another server which is on a different datacenter, as soon as i get more then 20 simultaneous calls on the system the delay starts again, same problem on the main server which is very weird since the system used to work fine even with more then 100 simultaneous calls and no changes were made.

5

Please post a pastebin link with a full call trace

https://wiki.freepbx.org/display/SUP/Providing+Great+Debug#ProvidingGreatDebug-AsteriskLogs-PartII

6

Hi , here’s the call trace as requested.
https://pastebin.freepbx.org/view/5838405a

Thanks

7

Hi,

No one has an idea about this kind of problem?

8

Delays appear to immediately follow a line that writes to the CDR. I would guess there is a problem with that sql resource that’s delaying writes or possibly some other low level problem that interferes with the CDR writes. Noting I’ve ever seen before.

9

Is it every number or only some numbers that have delay. Ive seen a lot more delay with certain carrier routes lately of major carriers.

10

When I have more then 20 simultaneous calls the delay starts happening for all numbers, Same problem even with a different carriers

11

What do your server resources look like at 20 concurrent calls? Are you getting close to maxing out CPU/Ram? Is your swap engaging?

12

I believe that @lgaetz diagnosed your problem correctly. Where are the CDRs stored (SSD, hard drive, network drive)? Any heavy usage from other VMs on the host?

Possibly, the recordings are interfering with CDR writes. Can you test (with an artificial load when the business is closed) whether turning off recording eliminates the delay?

13

load average didn’t even reach 0.6 as for RAM less then 3gb, I have a vm 32 cores,and 32 gb RAM

14

when the problem occurred I turned off recordings nothing changed as for the CDRs are stored on a remote DB with SSD. I’ll try CDRs on local DB maybe the problem is coming from there

15

This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.