We've Moved! Please visit our new and improved forum over at our new portal: https://portal.plumvoice.com/hc/en-us/community/topics

Latency issue

Questions and answers about IVR programming for Plum DEV

Moderators: admin, support

Post Reply
averlan
Posts: 30
Joined: Thu Sep 21, 2017 8:24 pm

Latency issue

Post by averlan »

Hello,

We have noticed a period of silence before call pickup. When calling Plum IVR for the first time after a break, there may be 14 - 18 seconds (approx) of dead air before the call is answered. This happens mostly on the first call after a break of an hour or more to the system. Is this because of network issues? Or the system performs some checkpoints? Please advise where to look to avoid this issue. Thanks.

support
Posts: 3632
Joined: Mon Jun 02, 2003 3:47 pm
Location: Boston, MA
Contact:

Re: Latency issue

Post by support »

Hi,

Could you please post an excerpt from a call log where this behavior occurs? We have no reports of network issues so this intermittent silence is likely related to your call flow design. We can further assist you once we have some log entries to look at.

Regards,
Plum Support

averlan
Posts: 30
Joined: Thu Sep 21, 2017 8:24 pm

Re: Latency issue

Post by averlan »

Please check below. This one was slightly less (about 8-10 seconds wait), but still why did it take so long to initiate the call?


Thu 15 Mar 2018 11:58:28.535 AM EDT (200035;006;1521129449) [client] EVENT: Call Start Event: ANII 2403611617 DNIS 5713548803 VURL http://us.popproxy.plumgroup.com/plumvp ... ibe.com/qa
Thu 15 Mar 2018 11:58:28.535 AM EDT (200035;006;1521129449) [vxi] EVENT: DocumentParser::FetchDocument()
Thu 15 Mar 2018 11:58:28.542 AM EDT (200035;006;1521129449) [vxi] EVENT: Fetching Document: http://us.popproxy.plumgroup.com/plumvp ... ibe.com/qa
Thu 15 Mar 2018 11:58:28.542 AM EDT (200035;006;1521129449) [vxi] EVENT: DocumentParser::FetchDocument(http://us.popproxy.plumgroup.com/plumvp ... ibe.com/qa)
Thu 15 Mar 2018 11:58:28.546 AM EDT (200035;006;1521129449) [vxi] EVENT: Cache Miss: http://us.popproxy.plumgroup.com/plumvp ... ibe.com/qa
Thu 15 Mar 2018 11:58:28.546 AM EDT (200035;006;1521129449) [inet] EVENT: Attempting to fetch http://us.popproxy.plumgroup.com/plumvp ... ibe.com/qa
Thu 15 Mar 2018 11:58:28.579 AM EDT (200035;006;1521129449) [log] EVENT: Saved http://us.popproxy.plumgroup.com/plumvp ... ibe.com/qa as dnislogs/5713548803_2943712144_0.vxml for DNIS 5713548803 on channel 6
Thu 15 Mar 2018 11:58:28.583 AM EDT (200035;006;1521129449) [vxi] EVENT: Entering form = '$_internalName_926633' form item = '$_internalName_926634'
Thu 15 Mar 2018 11:58:28.583 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="sessionId" expr = "session.id")
Thu 15 Mar 2018 11:58:28.583 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="callerid" expr = "session.telephone.ani")
Thu 15 Mar 2018 11:58:28.583 AM EDT (200035;006;1521129449) [vxi] EVENT: Fetching Document: http://qapayivr.paymentvision.com/MainI ... ?payee=QQQ
Thu 15 Mar 2018 11:58:28.583 AM EDT (200035;006;1521129449) [vxi] EVENT: DocumentParser::FetchDocument(http://qapayivr.paymentvision.com/MainI ... ?payee=QQQ)
Thu 15 Mar 2018 11:58:28.583 AM EDT (200035;006;1521129449) [inet] EVENT: Posted form data is URL encoded
Thu 15 Mar 2018 11:58:28.583 AM EDT (200035;006;1521129449) [inet] EVENT: Attempting to fetch http://qapayivr.paymentvision.com/MainI ... ?payee=QQQ
Thu 15 Mar 2018 11:58:36.734 AM EDT (200035;006;1521129449) [log] EVENT: Saved http://qapayivr.paymentvision.com/MainI ... ?payee=QQQ as dnislogs/5713548803_2943712144_1.vxml for DNIS 5713548803 on channel 6
Thu 15 Mar 2018 11:58:36.734 AM EDT (200035;006;1521129449) [vxi] EVENT: Fetching Root Document: VoiceXMLGlobal.aspx
Thu 15 Mar 2018 11:58:36.734 AM EDT (200035;006;1521129449) [vxi] EVENT: DocumentParser::FetchDocument(VoiceXMLGlobal.aspx)
Thu 15 Mar 2018 11:58:36.734 AM EDT (200035;006;1521129449) [vxi] EVENT: Cache Miss: http://qapayivr.paymentvision.com/VoiceXMLGlobal.aspx
Thu 15 Mar 2018 11:58:36.734 AM EDT (200035;006;1521129449) [inet] EVENT: Attempting to fetch http://qapayivr.paymentvision.com/VoiceXMLGlobal.aspx
Thu 15 Mar 2018 11:58:36.834 AM EDT (200035;006;1521129449) [log] EVENT: Saved VoiceXMLGlobal.aspx as dnislogs/5713548803_2943712144_2.vxml for DNIS 5713548803 on channel 6
Thu 15 Mar 2018 11:58:36.841 AM EDT (200035;006;1521129449) [rec] EVENT: Loading Builtin grammar: builtin:dtmf/digits
Thu 15 Mar 2018 11:58:36.843 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldUserID" expr = "")
Thu 15 Mar 2018 11:58:36.843 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldPassword" expr = "")
Thu 15 Mar 2018 11:58:36.843 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldCheckingAccount" expr = "")
Thu 15 Mar 2018 11:58:36.843 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldRoutingNumber" expr = "")
Thu 15 Mar 2018 11:58:36.843 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldCheckNumber" expr = "")
Thu 15 Mar 2018 11:58:36.843 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldLoginCheckCount" expr = "")
Thu 15 Mar 2018 11:58:36.843 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldPwdCheckCount" expr = "")
Thu 15 Mar 2018 11:58:36.843 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="iMaxTries" expr = "3")
Thu 15 Mar 2018 11:58:36.843 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="iMinAmount" expr = "2000")
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="validSecretKey" expr = "0")
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="lengthPasswordCount" expr = "0")
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldPaymentDue" expr = "")
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldPartialPayment" expr = "")
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldMinPayment" expr = "")
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldTransactionAmount" expr = "")
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldSession" expr = "")
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldCreditCardDate" expr = "")
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="fldCreditCardNumber" expr = "")
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::var_element(name="lengthCheckCount" expr = "0")
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [vxi] EVENT: Entering form = 'frmMainIntro' form item = 'userID'
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::queue_prompts()
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [prompt] EVENT: bargein set to true
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [prompt] EVENT: INPUTMODES set to "DTMF"
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [prompt] EVENT: Cache Miss: http://qapayivr.paymentvision.com/audio ... ing_EN.wav
Thu 15 Mar 2018 11:58:36.844 AM EDT (200035;006;1521129449) [inet] EVENT: Attempting to fetch http://qapayivr.paymentvision.com/audio ... ing_EN.wav
Thu 15 Mar 2018 11:58:36.957 AM EDT (200035;006;1521129449) [prompt] EVENT: Audio segment from the URL audio\QQQ\ACE_Greeting_EN.wav added to prompt queue
Thu 15 Mar 2018 11:58:36.961 AM EDT (200035;006;1521129449) [prompt] EVENT: bargein set to true
Thu 15 Mar 2018 11:58:36.961 AM EDT (200035;006;1521129449) [prompt] EVENT: INPUTMODES set to "DTMF"
Thu 15 Mar 2018 11:58:36.962 AM EDT (200035;006;1521129449) [prompt] EVENT: Audio segment added to prompt queue from TTS application/synthesis+ssml for:
---------
<?xml version='1.0'?><speak xml:lang="en-US"><break size="medium" time="1s"/></speak>
---------
Thu 15 Mar 2018 11:58:36.966 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::field_element - activating grammars for form = 'frmMainIntro' formitem = 'userID'
Thu 15 Mar 2018 11:58:36.967 AM EDT (200035;006;1521129449) [vxi] EVENT: VXI::do_recognition()
Thu 15 Mar 2018 11:58:36.967 AM EDT (200035;006;1521129449) [vxi] EVENT: PromptManager::Play()
Thu 15 Mar 2018 11:58:36.967 AM EDT (200035;006;1521129449) [prompt] EVENT: Newly queued prompts are now being played
Thu 15 Mar 2018 11:58:43.161 AM EDT (200035;006;1521129449) [vxi] EVENT: received event: connection.disconnect.hangup:
Thu 15 Mar 2018 11:58:43.161 AM EDT (200035;006;1521129449) [prompt] EVENT: bargein set to true
Thu 15 Mar 2018 11:58:43.161 AM EDT (200035;006;1521129449) [prompt] EVENT: Can not queue audio -- line disconnected
Thu 15 Mar 2018 11:58:43.162 AM EDT (200035;006;1521129449) [prompt] EVENT: Playing filler!
Thu 15 Mar 2018 11:58:43.162 AM EDT (200035;006;1521129449) [vxi] EVENT: Fetching Document: authentication.aspx?mode=hangup
Thu 15 Mar 2018 11:58:43.162 AM EDT (200035;006;1521129449) [vxi] EVENT: DocumentParser::FetchDocument(authentication.aspx?mode=hangup)
Thu 15 Mar 2018 11:58:43.162 AM EDT (200035;006;1521129449) [vxi] EVENT: Cache Miss: http://qapayivr.paymentvision.com/authe ... ode=hangup
Thu 15 Mar 2018 11:58:43.162 AM EDT (200035;006;1521129449) [inet] EVENT: Attempting to fetch http://qapayivr.paymentvision.com/authe ... ode=hangup
Thu 15 Mar 2018 11:58:43.718 AM EDT (200035;006;1521129449) [log] EVENT: Saved authentication.aspx?mode=hangup as dnislogs/5713548803_2943712144_3.vxml for DNIS 5713548803 on channel 6
Thu 15 Mar 2018 11:58:43.718 AM EDT (200035;006;1521129449) [vxi] ERROR: VXI::DoOuterJump - no dialog element found in "authentication.aspx?mode=hangup"
Thu 15 Mar 2018 11:58:43.719 AM EDT (200035;006;1521129449) [vxi] EVENT: received event: error.badfetch.baddialog:
Thu 15 Mar 2018 11:58:43.719 AM EDT (200035;006;1521129449) [prompt] EVENT: Can not queue audio -- line disconnected
Thu 15 Mar 2018 11:58:43.719 AM EDT (200035;006;1521129449) [vxi] EVENT: received event: connection.disconnect.hangup:
Thu 15 Mar 2018 11:58:43.719 AM EDT (200035;006;1521129449) [vxi] ERROR: Max Disconnect Count Exceeded
Thu 15 Mar 2018 11:58:43.745 AM EDT (200035;006;1521129449) [client] EVENT: Call End Event
Thu 15 Mar 2018 11:58:43.746 AM EDT (200035;006;1521129449) [prompt] EVENT: Ending session
Thu 15 Mar 2018 11:58:43.746 AM EDT (200035;006;1521129449) [tel] EVENT: Ending Session On Channel 6

support
Posts: 3632
Joined: Mon Jun 02, 2003 3:47 pm
Location: Boston, MA
Contact:

Re: Latency issue

Post by support »

Hi,

According to the call log it took a fraction of a second for the initial scratchpad to be loaded (from 11:58:28.535 to 11:58:28.579). After the scratchpad loads it attempts to fetch your url at http://qapayivr.paymentvision.com/MainI ... ?payee=QQQ.

You can see this fetch begin at 11:58:28.583:

Code: Select all

Thu 15 Mar 2018 11:58:28.583 AM EDT (200035;006;1521129449) [inet] EVENT: Attempting to fetch http://qapayivr.paymentvision.com/MainI ... ?payee=QQQ
But it is not successfully loaded until 11:58:36.734:

Code: Select all

Thu 15 Mar 2018 11:58:36.734 AM EDT (200035;006;1521129449) [log] EVENT: Saved http://qapayivr.paymentvision.com/MainI ... ?payee=QQQ as dnislogs/5713548803_2943712144_1.vxml for DNIS 5713548803 on channel 6
This 8 second delay is caused by our platform waiting for your web server to respond with the VXML script. We recommend consulting your internal team regarding the slow response from your web server.

Regards,
Plum Support

Post Reply