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

Discussion in '3CX Phone System - General' started by dbergsma, Jan 13, 2009.

Thread Status:
Not open for further replies.
  1. dbergsma

    Joined:
    Oct 27, 2008
    Messages:
    39
    Likes Received:
    0
    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.
     
  2. SY

    SY Well-Known Member
    3CX Support

    Joined:
    Jan 26, 2007
    Messages:
    1,825
    Likes Received:
    2
    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
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  3. dbergsma

    Joined:
    Oct 27, 2008
    Messages:
    39
    Likes Received:
    0
    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||??:parametersUpdated:=====[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
     
  4. dbergsma

    Joined:
    Oct 27, 2008
    Messages:
    39
    Likes Received:
    0
    had to turn 'pbx delivers audio' back on as internal voice is garbled on inbound calls.
     
  5. SY

    SY Well-Known Member
    3CX Support

    Joined:
    Jan 26, 2007
    Messages:
    1,825
    Likes Received:
    2
    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
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  6. dbergsma

    Joined:
    Oct 27, 2008
    Messages:
    39
    Likes Received:
    0
    replaced grandstream with patton, problem solved.
    can't say I recomend grandstream.
    3cx system works well.

    dean.
     
  7. houston

    Joined:
    Jul 21, 2009
    Messages:
    40
    Likes Received:
    0
    Thank you Dean, you just made me feel a whole lot better buying the $450 box instead of the $250 one.
     
Thread Status:
Not open for further replies.