Virtual Service too long time to respond back and causing the application to timeout

[harika.gonela1]

Hi Team,

 We are facing an issue where Virtual Service takes too long time to respond back and thereby causing the application to timeout.

Is this latency issue related to delay in fetching the data from DB. DB which we are using is Oracle 12c. 

If not how can we resolve the VS latency issue ? 

We can see below exception in registry.log , 

2020-09-15 2228,975Z (15:55) [qtp1899999514-23055] WARN  com.itko.lisa.utils.db.LisaSessionCustomizer - SQL query took a long time (121 ms) : SELECT ACTIVITY_ID, DESCRIPTION, LICENSE_TYPE, ACTIVITY_NAME, PARENT_ACTIVITY_ID FROM ACL_ACTIVITIES
2020-09-15 2230,666Z (15:55) [qtp1899999514-23055] WARN  com.itko.lisa.utils.db.LisaSessionCustomizer - SQL query took a long time (1513 ms) : SELECT t1.ACTIVITY_ID, t1.DESCRIPTION, t1.LICENSE_TYPE, t1.ACTIVITY_NAME, t1.PARENT_ACTIVITY_ID, t0.ROLE_ID FROM ACL_ROLES_ACTIVITIES t0, ACL_ACTIVITIES t1 WHERE ((t1.ACTIVITY_ID = t0.ACTIVITY_ID) AND (t0.ROLE_ID IN ?))

Please suggest

Regards,
Harika Gonela.

[Vaibhav Jain]

Hi Harika,

In your JDBC step make sure, the Use Connection Pool option is checked. Also, you can try optimizing your queries with help from DBA (there used an option in Toad/SQL Developer if i recollect to check this).

For reducing the VS response time, while deploying the service, mark think scale as 0

Thanks

------------------------------
Regards,
Vaibhav Jain
Capgemini
------------------------------

[Danny Saro]

Classification: HCL Internal

Hi,

 

SQL queries taking too long within the registry process would not be related to your virtual service taking too long to respond.

 

Is this a customised VSM? If so, make sure that any additional steps added to the VSM have a 0 think time. Is there database access to retrieve response data too in your VSM? If so, that could an area to look at.

 

To do root-cause analysis, you could add timestamp filters at various steps inside your VSM and then put those filtered properties in the log message of the Respond step. That would allow you to find out where the time goes.

 

Cheers,

Danny

 

::DISCLAIMER::

---

The contents of this e-mail and any attachment(s) are confidential and intended for the named recipient(s) only. E-mail transmission is not guaranteed to be secure or error-free as information could be intercepted, corrupted, lost, destroyed, arrive late or incomplete, or may contain viruses in transmission. The e mail and its contents (with or without referred errors) shall therefore not attach any liability on the originator or HCL or its affiliates. Views or opinions, if any, presented in this email are solely those of the author and may not necessarily reflect the views or opinions of HCL or its affiliates. Any form of reproduction, dissemination, copying, disclosure, modification, distribution and / or publication of this message without the prior written consent of authorized representative of HCL is strictly prohibited. If you have received this email in error please delete it and notify the sender immediately. Before opening any email and/or attachments, please check them for viruses and other defects.

---

[harika.gonela1]

Hi,

Thank you Vaibhav & Danny.

• Think Scale is 0.
• No connection to external DB from vsm to fetch the response.
• Think time set as 0 on each step in vsm.
• Regarding timestamp filters, could you please share any some sample vsm to follow.

Below is exception we are seeing in vse.log:

 

2020-09-16 07:46:44,011Z (00:46) [Event Sink Thread Pool Thread 4] INFO  com.itko.lisa.coordinator.VirtualServiceEnvironmentImpl - REBELLION_UserSecurityEnterprise_DEV: status=running, capacity=10 current tx/sec: 0 peak tx/sec: 1 errors: 0

2020-09-16 07:46:44,011Z (00:46) [Event Sink Thread Pool Thread 4] INFO  com.itko.lisa.coordinator.VirtualServiceEnvironmentImpl - --------------------------------------------------------------------------------------------------

2020-09-16 07:46:57,784Z (00:46) [Metrics persister processing 7 objects] WARN  com.itko.lisa.utils.db.LisaSessionCustomizer - SQL query took a long time (6344 ms) : SELECT TXN_COUNTS_ID, VSE_NAME, VS_NAME, COUNTS_DATE, MISSES, REQUEST, SPECIFIC_HITS, TOTAL_COUNT, NODE_HITS FROM VSE_METRICS_TXN_COUNTS WHERE ((((VSE_NAME = ?) AND (VS_NAME = ?)) AND (REQUEST IS NULL)) AND (COUNTS_DATE = ?))

2020-09-16 07:46:59,256Z (00:46) [Metrics persister processing 7 objects] WARN  com.itko.lisa.utils.db.LisaSessionCustomizer - SQL query took a long time (1468 ms) : SELECT TXN_COUNTS_ID, VSE_NAME, VS_NAME, COUNTS_DATE, MISSES, REQUEST, SPECIFIC_HITS, TOTAL_COUNT, NODE_HITS FROM VSE_METRICS_TXN_COUNTS WHERE ((((VSE_NAME = ?) AND (VS_NAME = ?)) AND (REQUEST IS NULL)) AND (COUNTS_DATE = ?))

2020-09-16 07:47:16,778Z (00:47) [PortServer:0.0.0.0/0.0.0.0:3621] ERROR com.itko.lisa.vse.sio.PortServer - An error occurred reading from the client.

java.io.IOException: Connection reset by peer

                at sun.nio.ch.FileDispatcherImpl.read0(Native Method)

                at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)

                at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)

                at sun.nio.ch.IOUtil.read(IOUtil.java:197)

                at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)

                at com.itko.lisa.vse.sio.NIOSession.readFromSocketChannel(NIOSession.java:189)

                at com.itko.lisa.vse.sio.PlainSession.readApplicationData(PlainSession.java:64)

                at com.itko.lisa.vse.sio.NIOSession.handleRead(NIOSession.java:138)

                at com.itko.lisa.vse.sio.SelectorThread.handleOperations(SelectorThread.java:316)

                at com.itko.lisa.vse.sio.SelectorThread.run(SelectorThread.java:265)

                at java.lang.Thread.run(Thread.java:745)

2020-09-16 07:47:16,778Z (00:47) [PortServer:0.0.0.0/0.0.0.0:3602] ERROR com.itko.lisa.vse.sio.PortServer - An error occurred reading from the client.

java.io.IOException: Connection reset by peer

                at sun.nio.ch.FileDispatcherImpl.read0(Native Method)

                at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)

                at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)

                at sun.nio.ch.IOUtil.read(IOUtil.java:197)

                at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)

                at com.itko.lisa.vse.sio.NIOSession.readFromSocketChannel(NIOSession.java:189)

                at com.itko.lisa.vse.sio.PlainSession.readApplicationData(PlainSession.java:64)

                at com.itko.lisa.vse.sio.NIOSession.handleRead(NIOSession.java:138)

                at com.itko.lisa.vse.sio.SelectorThread.handleOperations(SelectorThread.java:316)

                at com.itko.lisa.vse.sio.SelectorThread.run(SelectorThread.java:265)

                at java.lang.Thread.run(Thread.java:745)

2020-09-16 07:47:22,235Z (00:47) [Metrics persister processing 36 objects] WARN  com.itko.lisa.utils.db.LisaSessionCustomizer - SQL query took a long time (140 ms) : SELECT TXN_COUNTS_ID, VSE_NAME, VS_NAME, COUNTS_DATE, MISSES, REQUEST, SPECIFIC_HITS, TOTAL_COUNT, NODE_HITS FROM VSE_METRICS_TXN_COUNTS WHERE ((((VSE_NAME = ?) AND (VS_NAME = ?)) AND (REQUEST IS NULL)) AND (COUNTS_DATE = ?))

2020-09-16 07:47:33,355Z (00:47) [Event Sink Thread Pool Thread 2] INFO  com.itko.lisa.coordinator.VirtualServiceEnvironmentImpl - Memory used 1,832mb, allocated 6,479mb, max 40,893mb (4%) Our cpu usage 14%, system cpu used 15% GC time 0%

2020-09-16 07:47:33,355Z (00:47) [Event Sink Thread Pool Thread 2] INFO  com.itko.lisa.coordinator.VirtualServiceEnvironmentImpl

Regards,
Harika Gonela.

[Vaibhav Jain]

Hi HArika,

what db is configured for DevTest Server (for registry)? Is it derby or someother?

Thanks

------------------------------
Regards,
Vaibhav Jain
Capgemini
------------------------------

[harika.gonela1]

It is Oracle Db.

Regards,
Harika Gonela.