latency - is there a fix? (3cx v7, spa942 Grandstream 4104

[dbergsma]

Hi folks,
Environment: 3cx v7, spa942 and Grandstream 4104 fxo to pstn.

General question: I am having problems with 'delay' which is noticable in conversation. I recognize that 3cx has done a handoff between the phone and the fxo -- and this may be more voip issue in general -- but bear with me please.
The linksys spa942 status screen shows a jitter of 5ms (inconsequential) and 'decode time' ranging from 90ms up to as high as 150ms using 711u.

If I understand these statistics, then the delay I am experiencing is equal to
I talk --> encode time + jitter + decode time at the fxo --> out to the pstn
The recipient listens and responds back adding
fxo encode time + jitter + decode time at the phone.

The network has only a server, 1 laptop, and the fxo box. There are no collisions or dropped packets.

At a minimum -- I have two decodes at 90ms + the jitter and encode -- making me think that the total approaches or exceeds 200ms.
I've read on the web that anything over 200ms causes dificulties for the participants.

Am I missing the obvious here?

It is enough of a problem, that the system -- which has some awesome features, a great price point, etc -- doesn't meet my needs. Any help would be greatly appreciated.

Kind Regards
Dean.

 

[SY]

Hi folks,
Environment: 3cx v7, spa942 and Grandstream 4104 fxo to pstn.

General question: I am having problems with 'delay' which is noticable in conversation. I recognize that 3cx has done a handoff between the phone and the fxo -- and this may be more voip issue in general -- but bear with me please.
The linksys spa942 status screen shows a jitter of 5ms (inconsequential) and 'decode time' ranging from 90ms up to as high as 150ms using 711u.

If I understand these statistics, then the delay I am experiencing is equal to
I talk --> encode time + jitter + decode time at the fxo --> out to the pstn
The recipient listens and responds back adding
fxo encode time + jitter + decode time at the phone.

The network has only a server, 1 laptop, and the fxo box. There are no collisions or dropped packets.

At a minimum -- I have two decodes at 90ms + the jitter and encode -- making me think that the total approaches or exceeds 200ms.
I've read on the web that anything over 200ms causes dificulties for the participants.

Am I missing the obvious here?

It is enough of a problem, that the system -- which has some awesome features, a great price point, etc -- doesn't meet my needs. Any help would be greatly appreciated.

Kind Regards
Dean.

Hi Dean,

Could you please set verbose log level on Settings/Advanced page, restart media server and replicate problematic call few times? Then, please, post 3CXMediaServer.trace.log (Data\Logs) here.

Thanks

 

[dbergsma]

sorry for the delay -- I'm opening a new office (that wants to use 3cx) in a different city than I live in -- and am not always on site.

SPA942 reports 80ms decode time on this go around.
Under v6 -- I needed to have pbx delivers audio turned on for Grandstream FXO to work reliably. I turned it off before running this test -- would this make any difference?

Thanks for the help.

**************************************************
spa-942
Line 1 Call 1 Status
Call State: Connected Tone: None
Encoder: G711u Decoder: G711u
Type: Inbound Remote Hold: No
Callback: Peer Name: DEAN BERGSMA
Peer Phone: 14036177797 Duration: 00:00:08
Packets Sent: 414 Packets Recv: 276
Bytes Sent: 66240 Bytes Recv: 66240
Decode Latency: 80 ms Jitter: 1 ms
Round Trip Delay: 0 ms Packets Lost: 0
Packet Error: 0 Mapped RTP Port: 16436 >> 0
***************************************************************************************

log is
2009/01/19 >>
12:37:32.067|.\Service.cpp(240)|Log2||??:*** Initialize ***
12:37:32.083|.\Service.cpp(316)|Log2||??:*** Start Server ***
12:37:32.083|.\Service.cpp(80)|Log2||??:*** Listen ***
12:37:32.083|.\Service.cpp(96)|Log2||??:*** Connecting to [127.0.0.1:5482] ***
12:37:32.083|.\Service.cpp(103)|Log2||??:*** Connected to s6p:5482/CallManager at 127.0.0.1:5482 ***
12:37:38.083|.\Service.cpp(155)|Trace5||??arametersUpdated:=====[03821F58]
STUN=ARRAY
[0]=stun.3cx.com:3478
[1]=stun2.3cx.com:3478
ADD2833=1
ANSP=0
CS=62914560
EXTADDR=
FEP=9000
FLP=7000
LEP=9049
LLP=7499
LOCALADDR=
MCFS=5242880
MOH=C:\Program Files (x86)\3CX PhoneSystem\Data\Ivr\Prompts\onhold.mp3
STUNTOUT=3000
TOS=0
=================================

12:38:11.518|.\MediaServer.cpp(612)|Trace5||??:EndPoint created: (destination=192.168.1.37)
EndPoint: ID=00000001@(LOCAL)
LOGID=C:335.1 Status: MSEP_LOCAL
RTP:192.168.1.33:7000
RTCP:192.168.1.33:7001
STUN RTP:0.0.0.0:0
STUN RTCP:0.0.0.0:0
Coder:
NOT SET
101:telephony-event
Party ptime:20
Party RTP:0.0.0.0:0
Party RTCP:0.0.0.0:0
Decoders:
<empty>

12:38:11.518|.\MediaServer.cpp(1058)|Trace5||??:EP 00000001@ joined to call 335
12:38:11.518|.\MediaServer.cpp(1067)|Trace5||??:starting send on new call 335
12:38:11.534|.\MediaServer.cpp(709)|Trace5||??:Set Party EP:C:335.1SDP:v=0
o=10000 8002 8001 IN IP4 192.168.1.37
s=SIP Call
c=IN IP4 192.168.1.37
t=0 0
m=audio 5012 RTP/AVP 18 4 0 8 3
a=sendrecv
a=rtpmap:18 G729/8000
a=rtpmap:4 G723/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=ptime:20

12:38:11.534|.\MSEndPoint.cpp(2472)|Trace5||??:New state00000001@ SILENCE
12:38:11.534|.\MSEndPoint.cpp(1484)|Log2||??:[MS210000] C:335.1:Offer received. RTP connection: 192.168.1.37:5012(5013)
12:38:11.550|.\MediaServer.cpp(612)|Trace5||??:EndPoint created: (destination=192.168.1.36)
EndPoint: ID=00000002@(LOCAL)
LOGID=C:335.2 Status: MSEP_LOCAL
RTP:192.168.1.33:7002
RTCP:192.168.1.33:7003
STUN RTP:0.0.0.0:0
STUN RTCP:0.0.0.0:0
Coder:
NOT SET
101:telephony-event
Party ptime:20
Party RTP:0.0.0.0:0
Party RTCP:0.0.0.0:0
Decoders:
<empty>

12:38:11.550|.\MediaServer.cpp(1058)|Trace5||??:EP 00000002@ joined to call 335
12:38:11.550|.\MediaServer.cpp(1103)|Trace5||??:EndPoint 00000002@ removed from call 335
12:38:11.550|.\MediaServer.cpp(1058)|Trace5||??:EP 00000002@ joined to call 335
12:38:11.550|.\MSEndPoint.cpp(2472)|Trace5||??:New state00000002@ SILENCE
12:38:11.550|.\MSEndPoint.cpp(1242)|Log2||??:[MS210006] C:335.2:Offer provided. Connection(by pass mode): 192.168.1.37:5012(5013)
12:38:11.550|.\MediaServer.cpp(647)|Trace5||??:Get Local SDP. EP:C:335.2SDP:v=0
o=3cxPS 107659395072 20937965569 IN IP4 192.168.1.33
s=3cxPS Audio call
c=IN IP4 192.168.1.37
t=0 0
m=audio 5012 RTP/AVP 18 4 0 8 3
a=sendrecv
a=rtpmap:18 G729/8000
a=rtpmap:4 G723/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=ptime:20

12:38:11.550|.\MediaServer.cpp(1103)|Trace5||??:EndPoint 00000002@ removed from call 335
12:38:19.003|.\MediaServer.cpp(709)|Trace5||??:Set Party EP:C:335.2SDP:v=0
o=- 121618776 121618776 IN IP4 192.168.1.36
s=-
c=IN IP4 192.168.1.36
t=0 0
m=audio 16438 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:30
a=sendrecv

12:38:19.003|.\MSEndPoint.cpp(2472)|Trace5||??:New state00000002@ SILENCE
12:38:19.003|.\MSEndPoint.cpp(2472)|Trace5||??:New state00000002@ SILENCE
12:38:19.003|.\MSEndPoint.cpp(1489)|Log2||??:[MS210001] C:335.2:Answer received. RTP connection: 192.168.1.36:16438(16439)
12:38:19.003|.\MediaServer.cpp(1058)|Trace5||??:EP 00000002@ joined to call 335
12:38:19.003|.\MSEndPoint.cpp(2472)|Trace5||??:New state00000001@ SILENCE
12:38:19.003|.\MSEndPoint.cpp(1247)|Log2||??:[MS210007] C:335.1:Answer provided. Connection(by pass mode): 192.168.1.36:16438(16439)
12:38:19.003|.\MediaServer.cpp(647)|Trace5||??:Get Local SDP. EP:C:335.1SDP:v=0
o=3cxPS 471121002496 50063212545 IN IP4 192.168.1.33
s=3cxPS Audio call
c=IN IP4 192.168.1.36
t=0 0
m=audio 16438 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:30
a=sendrecv

12:38:40.254|.\MediaServer.cpp(1103)|Trace5||??:EndPoint 00000001@ removed from call 335
12:38:40.270|.\MediaServer.cpp(1103)|Trace5||??:EndPoint 00000002@ removed from call 335
12:38:40.270|.\MediaServer.cpp(1115)|Trace5||??:EP 00000002@ not found in call 335
12:38:40.270|.\MediaServer.cpp(862)|Trace5||??:references to EndPoint 00000001@ were removed
12:38:40.270|.\MSEndPoint.cpp(676)|Trace5||??:EndPoint 00000001@ destroyed
12:38:40.270|.\RTPReceiver.cpp(127)|Trace5||??:Endpoint for socket 0 is not found!
12:38:40.379|.\MediaServer.cpp(862)|Trace5||??:references to EndPoint 00000002@ were removed
12:38:40.379|.\MSEndPoint.cpp(676)|Trace5||??:EndPoint 00000002@ destroyed
12:38:40.379|.\MediaServer.cpp(1181)|Trace5||??:references to call 335 were removed
12:38:40.379|.\MSCallConf.cpp(33)|Trace5||??:Call: 335 destroyed
12:41:25.760|.\MediaServer.cpp(612)|Trace5||??:EndPoint created: (destination=192.168.1.37)
EndPoint: ID=00000003@(LOCAL)
LOGID=C:336.1 Status: MSEP_LOCAL
RTP:192.168.1.33:7004
RTCP:192.168.1.33:7005
STUN RTP:0.0.0.0:0
STUN RTCP:0.0.0.0:0
Coder:
NOT SET
101:telephony-event
Party ptime:20
Party RTP:0.0.0.0:0
Party RTCP:0.0.0.0:0
Decoders:
<empty>

12:41:25.760|.\MediaServer.cpp(1058)|Trace5||??:EP 00000003@ joined to call 336
12:41:25.760|.\MediaServer.cpp(1067)|Trace5||??:starting send on new call 336
12:41:25.791|.\MediaServer.cpp(709)|Trace5||??:Set Party EP:C:336.1SDP:v=0
o=10000 8003 8001 IN IP4 192.168.1.37
s=SIP Call
c=IN IP4 192.168.1.37
t=0 0
m=audio 5016 RTP/AVP 18 4 0 8 3
a=sendrecv
a=rtpmap:18 G729/8000
a=rtpmap:4 G723/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=ptime:20

12:41:25.791|.\MSEndPoint.cpp(2472)|Trace5||??:New state00000003@ SILENCE
12:41:25.791|.\MSEndPoint.cpp(1484)|Log2||??:[MS210000] C:336.1:Offer received. RTP connection: 192.168.1.37:5016(5017)
12:41:25.807|.\MediaServer.cpp(612)|Trace5||??:EndPoint created: (destination=192.168.1.36)
EndPoint: ID=00000004@(LOCAL)
LOGID=C:336.2 Status: MSEP_LOCAL
RTP:192.168.1.33:7006
RTCP:192.168.1.33:7007
STUN RTP:0.0.0.0:0
STUN RTCP:0.0.0.0:0
Coder:
NOT SET
101:telephony-event
Party ptime:20
Party RTP:0.0.0.0:0
Party RTCP:0.0.0.0:0
Decoders:
<empty>

12:41:25.807|.\MediaServer.cpp(1058)|Trace5||??:EP 00000004@ joined to call 336
12:41:25.807|.\MediaServer.cpp(1103)|Trace5||??:EndPoint 00000004@ removed from call 336
12:41:25.807|.\MediaServer.cpp(1058)|Trace5||??:EP 00000004@ joined to call 336
12:41:25.807|.\MSEndPoint.cpp(2472)|Trace5||??:New state00000004@ SILENCE
12:41:25.807|.\MSEndPoint.cpp(1242)|Log2||??:[MS210006] C:336.2:Offer provided. Connection(by pass mode): 192.168.1.37:5016(5017)
12:41:25.807|.\MediaServer.cpp(647)|Trace5||??:Get Local SDP. EP:C:336.2SDP:v=0
o=3cxPS 95663685632 304053485569 IN IP4 192.168.1.33
s=3cxPS Audio call
c=IN IP4 192.168.1.37
t=0 0
m=audio 5016 RTP/AVP 18 4 0 8 3
a=sendrecv
a=rtpmap:18 G729/8000
a=rtpmap:4 G723/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=ptime:20

12:41:25.807|.\MediaServer.cpp(1103)|Trace5||??:EndPoint 00000004@ removed from call 336
12:41:28.104|.\MediaServer.cpp(709)|Trace5||??:Set Party EP:C:336.2SDP:v=0
o=- 121638195 121638195 IN IP4 192.168.1.36
s=-
c=IN IP4 192.168.1.36
t=0 0
m=audio 16440 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:30
a=sendrecv

12:41:28.104|.\MSEndPoint.cpp(2472)|Trace5||??:New state00000004@ SILENCE
12:41:28.104|.\MSEndPoint.cpp(2472)|Trace5||??:New state00000004@ SILENCE
12:41:28.104|.\MSEndPoint.cpp(1489)|Log2||??:[MS210001] C:336.2:Answer received. RTP connection: 192.168.1.36:16440(16441)
12:41:28.120|.\MediaServer.cpp(1058)|Trace5||??:EP 00000004@ joined to call 336
12:41:28.120|.\MSEndPoint.cpp(2472)|Trace5||??:New state00000003@ SILENCE
12:41:28.120|.\MSEndPoint.cpp(1247)|Log2||??:[MS210007] C:336.1:Answer provided. Connection(by pass mode): 192.168.1.36:16440(16441)
12:41:28.120|.\MediaServer.cpp(647)|Trace5||??:Get Local SDP. EP:C:336.1SDP:v=0
o=3cxPS 416326615040 511285657601 IN IP4 192.168.1.33
s=3cxPS Audio call
c=IN IP4 192.168.1.36
t=0 0
m=audio 16440 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:30
a=sendrecv

12:42:00.043|.\MediaServer.cpp(1103)|Trace5||??:EndPoint 00000003@ removed from call 336
12:42:00.043|.\MediaServer.cpp(1103)|Trace5||??:EndPoint 00000004@ removed from call 336
12:42:00.043|.\MediaServer.cpp(1115)|Trace5||??:EP 00000004@ not found in call 336
12:42:00.058|.\MediaServer.cpp(862)|Trace5||??:references to EndPoint 00000003@ were removed
12:42:00.058|.\MSEndPoint.cpp(676)|Trace5||??:EndPoint 00000003@ destroyed
12:42:00.058|.\RTPReceiver.cpp(127)|Trace5||??:Endpoint for socket 0 is not found!
12:42:00.152|.\MediaServer.cpp(862)|Trace5||??:references to EndPoint 00000004@ were removed
12:42:00.152|.\MSEndPoint.cpp(676)|Trace5||??:EndPoint 00000004@ destroyed
12:42:00.152|.\MediaServer.cpp(1181)|Trace5||??:references to call 336 were removed
12:42:00.152|.\MSCallConf.cpp(33)|Trace5||??:Call: 336 destroyed
12:42:00.152|.\RTPReceiver.cpp(127)|Trace5||??:Endpoint for socket 0 is not found!
12:45:42.128|.\Service.cpp(323)|Log2||??:*** Server started ***
12:45:42.128|.\Service.cpp(167)|Log2||??:*** Exit Listen ***
12:45:42.128|.\Service.cpp(325)|Log2||??:*** Server shut down ***
12:45:42.316|.\LPLogger.cpp(298)|Debug2||??:Closing logger

 

[dbergsma]

had to turn 'pbx delivers audio' back on as internal voice is garbled on inbound calls.

 

[SY]

Hi Dean,

RTP stream handling requires time for synchronization, audio processing (encoding/decoding) and delivery of stream over network.
"PBX delivers audio"=on activates additional audio processing on the PBX side, so latency will be increased. (additional processing of RTP stream).
If your devices may talk directly without any problems (call signaling and media delivery work perfect) then you don't need to engage PBX to take care about RTP streams. In your case there is the interoperability problem between your devices, so you need to ask PBX to take care about it.
The cost of this service is additional latency, it depends on many factors but PBX tries to don't allow it to exceed ~100 ms (if it is possible).

I hope, I've answered your questions (at least some of them).

PBX cannot control latency which is added by device(PSTN, VoIP provider, phone) but should not provoke it. Do you see any differences in spa942 report for different setting of "PBX delivers audio"?

Thanks

 

[dbergsma]

replaced grandstream with patton, problem solved.
can't say I recomend grandstream.
3cx system works well.

dean.

 

[houston]

replaced grandstream with patton, problem solved.
can't say I recomend grandstream.
3cx system works well.

dean.

Thank you Dean, you just made me feel a whole lot better buying the $450 box instead of the $250 one.