-
March 5th, 2023, 07:36 AM
#1
Accumulated Delay
Hi,
My customers start complaining that there's an accumulated delay in receiving data, the client can be connected to different domains.
I have the logs for both the server and the client, How can I know from the logs THAT THERE'S A DELAY IN THE STREAMING PROCESS,
I can upload the logs.
Regards
-
March 6th, 2023, 09:20 AM
#2
Hi ManKeer,
If the delays involve only a subset of the clients and then we can exclude a general problem affecting the whole server you should look for the "NIO write queue" and "NIO write queue wait" metrics in the MonitorText logs.
When these metrics show high values, and are constantly growing, it means that a part of the client sessions can not cope with the frequency of incoming real-time messages may be due to poor connectivity conditions or very slow devices, and the server accumulates delays in sending messages to them.
Below an example of MonitorText log line with the mentioned metrics in evidence:
"MonitorText|Timer-0 |Total threads = 460, Total heap = 231735296 (free = 16710304), Sessions = 3148 (max = 3175), New sessions = [+16, -12], Connections = 3473 (max = 3575), New connections = [+52, -37], In-pool threads = 128, Active threads = 4, Available threads = 124, Queued tasks = 0, Pool queue wait = 0, NIO write queue = 64, NIO write queue wait = 2457239, NIO write selectors = 32, NIO total selectors = 128, Subscribed items = 47 (for 25363 subscriptions), Inbound throughput = 116.3 updates/s (pre-filtered = 116.3), Outbound throughput = 13418.99 updates/s (6259.6 kbit/s, max = 11693.98), Lost updates = 0 (total = 0), Total bytes sent = 9265303321, Client messages throughput = 0 msgs/s (0 kbit/s, max = 0), Total messages handled = 0, Extra sleep = 0, Notify delay = 0 "
In any case if the size of the logs is not very big you can send them to support@lightstreamer.com
Regards,
Giuseppe
-
March 8th, 2023, 06:24 AM
#3
Thank you very much @giuseppe.corti, I have sent the logs from my personal email "mankeer@gmail.com", I have attached the logs for both LS server and client,
I need to know if this is a general problem [for all clients, I have about 7 to 10 clients keep claiming of this] or it's a specific problem for those clients only.
I appreciate your help in this problem, I will be so thankful if you advice how can I distinguish this problem and how it can be solved.
Regards
-
March 8th, 2023, 09:16 AM
#4
Hi ManKeer,
We have looked at the logs, but we too cannot find evidence of increasing delays, nor do we notice health problems on LS Server.
Do you confirm that the client log you have sent us comes from one of your users who observed delays?
The updates logged by the client library contain a timestamp coming from the Data Adapter and the difference between the client log timestamp and the data timestamp is stable at less than one second (apart from a timezone difference).
As far as we can see, if a delay was in place, it must have occurred either in the Data Adapter, when acquiring the data, or in the client page, when visualizing the data.
In fact, the update flow that reaches the client is significant, of various dozens of updates per second; hence slowness in processing, in some client scenarios, is a possibility.
But, since the logs are huge, please ask your user to provide the exact time of a moment in which they see a delay and, if possible, a quantification of the delay; so we can focus the inspection.
BTW, are you aware of the 61750 refusals of create_session requests by the Metadata Adapter occurring in a few hours, according to LS Server log?
-
March 9th, 2023, 06:17 AM
#5
Dear Dario,
Thank you for your response, I have attached the logs of the data adapter in my emails.
Unfortunately, I couldn't find any evidence for a delay from the data adapter side.
Regarding the 61750 refusals, I have seen all of these but do these refusals can affect the LS performance?
Regards
-
March 9th, 2023, 09:30 AM
#6
The Adapter-side logs regard custom code and we aren't able to find clues about the update flow.
Until we have a clear identification of the problem as the user perceives it, I don't think that we can proceed further.
If you confirm that the issue affects only a few clients and doesn't affect the other ones, it is more likely that the problem is related with the client application's ability to keep the pace of the incoming updates while trying to process them.
Please clarify if the client application's job is to visualize the data or to elaborate it internally.
BTW, the client log regards February 27, that is, the day before the Server and Adapter logs.
Could it be a mistake and perhaps the issue was observed on February 28 and never on February 27 ?
The refusals don't seem to affect the performance. Only in case a client application gets several refusals before succeeding, this may be seen by the user as a delay. Until we have a clear identification of the problem as the user perceives it, this is also a possibility.
Or perhaps this is just the evidence of another issue to be investigated.
-
April 5th, 2023, 02:55 PM
#7
It means that the Lightstreamer server receives an update from the Data Adapter for an item name that actually doesn't currently have an active subscription for.
Regards,
Giuseppe
-
April 6th, 2023, 08:53 AM
#8
Dear Dario,
Would you please take a look on the following log records?
I didn't receive anything as a client????
log4j:WARN No appenders could be found for logger (io.netty.util.internal.logging.InternalLoggerFact ory).
log4j:WARN Please initialize the log4j system properly.
06.أبر.23 10:14:37,141|DEBUG|lightstreamer.protocol|Session Thread <1>|New protocol oid=1
06.أبر.23 10:14:37,147|DEBUG|lightstreamer.heartbeat|Session Thread <1>|rhb max interval 0
06.أبر.23 10:14:37,148|DEBUG|lightstreamer.heartbeat|Session Thread <1>|rhb current interval 0
06.أبر.23 10:14:37,154|DEBUG|lightstreamer.session|Session Thread <1>|New session oid=1
Client property changed: sessionId
06.أبر.23 10:14:37,171|INFO |lightstreamer.actions|Session Thread <1>|Session ID value changed to null
Client property changed: serverSocketName
06.أبر.23 10:14:37,171|INFO |lightstreamer.actions|Session Thread <1>|Server Socket Name value changed to null
Client property changed: clientIp
06.أبر.23 10:14:37,171|INFO |lightstreamer.actions|Session Thread <1>|Client IP value changed to null
Client property changed: serverInstanceAddress
06.أبر.23 10:14:37,171|INFO |lightstreamer.actions|Session Thread <1>|Server Instance Address value changed to null
Client property changed: realMaxBandwidth
06.أبر.23 10:14:37,171|INFO |lightstreamer.session|Session Thread <1>|Opening new session
06.أبر.23 10:14:37,273|INFO |lightstreamer.utils|Session Thread <1>|Setting up custom CookieHandler: java.net.CookieManager@b6ed092
06.أبر.23 10:14:37,274|INFO |lightstreamer.utils|Session Thread <1>|Default CookieStore type: java.net.InMemoryCookieStore
06.أبر.23 10:14:37,274|DEBUG|lightstreamer.utils|Session Thread <1>|While getting cookies for http://etrdwebs02:8282/lightstreamer...col=TLCP-2.1.0
06.أبر.23 10:14:37,274|DEBUG|lightstreamer.utils|Session Thread <1>|Result of getting cookies for http://etrdwebs02:8282/lightstreamer...col=TLCP-2.1.0
06.أبر.23 10:14:37,274|INFO |lightstreamer.utils|Session Thread <1>|Cookies to be inserted for http://etrdwebs02:8282/lightstreamer...ol=TLCP-2.1.0: <none>
06.أبر.23 10:14:37,323|DEBUG|lightstreamer.stream|Session Thread <1>|HTTP transport connection establishing (oid=1): http://etrdwebs02:8282
/lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0
LS_polling=true&LS_cause=new.api&LS_polling_millis =0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwL ri8L7R7q&LS_adapter_set=FEEDERSERVER&LS_user=40252 9&LS_password=PT1239129115&
06.أبر.23 10:14:37,323|DEBUG|lightstreamer.netty.pool|Sessio n Thread <1>|Creating new HTTP channel pool map
06.أبر.23 10:14:37,746|DEBUG|lightstreamer.netty.pool|Sessio n Thread <1>|HTTP channel pool map [1] created and initialized
06.أبر.23 10:14:37,747|DEBUG|lightstreamer.netty.pool|Sessio n Thread <1>|New HTTP channel pool created. Remote address: etrdwebs02:8282
06.أبر.23 10:14:37,961|DEBUG|lightstreamer.session|Session Thread <1>|Session state change (1): OFF -> CREATING
06.أبر.23 10:14:37,962|DEBUG|lightstreamer.session|Session Thread <1>|Status timeout in 4000 [currentConnectTimeout]
Connection status changed to CONNECTING
06.أبر.23 10:14:37,992|DEBUG|lightstreamer.netty.pool|Netty Thread 1|HTTP channel created [e4e58556]
06.أبر.23 10:14:38,006|DEBUG|lightstreamer.netty.pool|Netty Thread 1|HTTP channel active [e4e58556]
06.أبر.23 10:14:38,007|DEBUG|lightstreamer.stream|Netty Thread 2|HTTP transport connection established (oid=1): http://etrdwebs02:8282
/lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0
LS_polling=true&LS_cause=new.api&LS_polling_millis =0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwL ri8L7R7q&LS_adapter_set=FEEDERSERVER&LS_user=40252 9&LS_password=PT1239129115&
06.أبر.23 10:14:38,009|DEBUG|lightstreamer.stream|Netty Thread 2|HTTP transport sending [e4e58556]: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0
LS_polling=true&LS_cause=new.api&LS_polling_millis =0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwL ri8L7R7q&LS_adapter_set=FEEDERSERVER&LS_user=40252 9&LS_password=PT1239129115&
06.أبر.23 10:14:39,045|DEBUG|lightstreamer.stream|Netty Thread 1|Response status: 200
06.أبر.23 10:14:39,049|DEBUG|lightstreamer.stream|Netty Thread 1|HTTP transport receiving [e4e58556]:
CONOK,S22dfab6342ca12c1M160T1438774,50000,0,*
SERVNAME,Lightstreamer HTTP Server
CLIENTIP,10.254.94.75
LOOP,0
-
April 6th, 2023, 08:54 AM
#9
here's the next lines
06.أبر.23 10:14:39,050|DEBUG|lightstreamer.protocol|Session Thread <1>|New message (1): CONOK,S22dfab6342ca12c1M160T1438774,50000,0,*
06.أبر.23 10:14:39,051|DEBUG|lightstreamer.session|Session Thread <1>|OK event while CREATING
06.أبر.23 10:14:39,051|INFO |lightstreamer.actions|Session Thread <1>|Session ID value changed to S22dfab6342ca12c1M160T1438774
06.أبر.23 10:14:39,051|DEBUG|lightstreamer.netty.pool|Netty Thread 1|HTTP channel released [e4e58556]
06.أبر.23 10:14:39,051|INFO |lightstreamer.actions|Session Thread <1>|Server Instance Address value changed to http://etrdwebs02:8282/
06.أبر.23 10:14:39,051|DEBUG|lightstreamer.session|Session Thread <1>|Data event while CREATING
06.أبر.23 10:14:39,051|DEBUG|lightstreamer.session|Session Thread <1>|Session state change (1): CREATING -> CREATED
06.أبر.23 10:14:39,051|DEBUG|lightstreamer.session|Session Thread <1>|Status timeout in 2000 [executionTimeout]
Client property changed: sessionId
06.أبر.23 10:14:39,052|DEBUG|lightstreamer.actions|Session Thread <1>|Subscription 1 ready to be sent to server
06.أبر.23 10:14:39,052|INFO |lightstreamer.subscribe|Session Thread <1>|Preparing subscription: 1
Client property changed: serverInstanceAddress
Connection status changed to CONNECTED:STREAM-SENSING
06.أبر.23 10:14:39,052|INFO |lightstreamer.protocol|Session Thread <1>|Sending subscription request
06.أبر.23 10:14:39,053|DEBUG|lightstreamer.protocol|Session Thread <1>|subscription parameters: LS_reqId=1&LS_op=add&LS_subId=1&LS_mode=MERGE&LS_g roup=LSTOCKS&LS_schema=key command Data&LS_data_adapter=FEEDER_ADAPTER&LS_snapshot=tr ue&LS_requested_max_frequency=1&LS_session=S22dfab 6342ca12c1M160T1438774&
06.أبر.23 10:14:39,054|INFO |lightstreamer.subscribe|Session Thread <1>|Start message handler
06.أبر.23 10:14:39,054|DEBUG|lightstreamer.subscribe|Session Thread <1>|Sending queued messages
06.أبر.23 10:14:39,057|DEBUG|lightstreamer.protocol|Session Thread <1>|New message (1): SERVNAME,Lightstreamer HTTP Server
Client property changed: serverSocketName
06.أبر.23 10:14:39,057|INFO |lightstreamer.actions|Session Thread <1>|Server Socket Name value changed to Lightstreamer HTTP Server
06.أبر.23 10:14:39,057|DEBUG|lightstreamer.protocol|Session Thread <1>|New message (1): CLIENTIP,10.254.94.75
Client property changed: clientIp
06.أبر.23 10:14:39,058|INFO |lightstreamer.actions|Session Thread <1>|Client IP value changed to 10.254.94.75
06.أبر.23 10:14:39,058|DEBUG|lightstreamer.protocol|Session Thread <1>|New message (1): LOOP,0
06.أبر.23 10:14:39,058|DEBUG|lightstreamer.session|Session Thread <1>|Loop event while CREATED
06.أبر.23 10:14:39,058|DEBUG|lightstreamer.session|Session Thread <1>|Session state change (1): CREATED -> FIRST_PAUSE
06.أبر.23 10:14:39,058|DEBUG|lightstreamer.session|Session Thread <1>|Timeout event [noPause] while FIRST_PAUSE cause=null startRecovery=false
06.أبر.23 10:14:39,058|INFO |lightstreamer.session|Session Thread <1>|Binding session
06.أبر.23 10:14:39,058|DEBUG|lightstreamer.session|Session Thread <1>|SessionWS state change (1) (sendBind): WS_NOT_CONNECTED -> WS_CONNECTING
06.أبر.23 10:14:39,058|DEBUG|lightstreamer.session|Session Thread <1>|WS connection: opening
06.أبر.23 10:14:39,060|DEBUG|lightstreamer.utils|Session Thread <1>|While getting cookies for http://etrdwebs02:8282/lightstreamer
06.أبر.23 10:14:39,060|DEBUG|lightstreamer.utils|Session Thread <1>|Result of getting cookies for http://etrdwebs02:8282/lightstreamer
06.أبر.23 10:14:39,060|INFO |lightstreamer.utils|Session Thread <1>|Cookies to be inserted for http://etrdwebs02:8282/lightstreamer: <none>
06.أبر.23 10:14:39,064|DEBUG|lightstreamer.netty.pool|Sessio n Thread <1>|New WS channel pool created. Remote address: etrdwebs02:8282
06.أبر.23 10:14:39,065|DEBUG|lightstreamer.netty.pool|Netty Thread 1|HTTP channel acquired [e4e58556]
06.أبر.23 10:14:39,067|DEBUG|lightstreamer.netty.pool|Netty Thread 3|ChannelUpgradeFuture state change [e4e58556]: CONNECTING -> CONNECTION_OK
06.أبر.23 10:14:39,068|DEBUG|lightstreamer.stream|Session Thread <1>|WebSocket transport: CONNECTING
06.أبر.23 10:14:39,068|DEBUG|lightstreamer.stream|Session Thread <1>|WebSocket transport: CONNECTING
06.أبر.23 10:14:39,069|DEBUG|lightstreamer.session|Session Thread <1>|Status timeout in 4000 [currentConnectTimeoutWS]
06.أبر.23 10:14:39,086|DEBUG|lightstreamer.netty.pool|Netty Thread 1|WS channel handshake [e4e58556]
06.أبر.23 10:14:39,132|DEBUG|lightstreamer.netty.pool|Netty Thread 1|ChannelUpgradeFuture state change [e4e58556]: CONNECTION_OK -> UPGRADE_OK
06.أبر.23 10:14:39,133|DEBUG|lightstreamer.netty.pool|Netty Thread 1|WS channel created [e4e58556]
06.أبر.23 10:14:39,136|DEBUG|lightstreamer.netty|Netty Thread 1|WebSocket handler added [e4e58556]
06.أبر.23 10:14:39,137|DEBUG|lightstreamer.stream|Session Thread <1>|WebSocket transport: CONNECTED
06.أبر.23 10:14:39,137|DEBUG|lightstreamer.session|Session Thread <1>|WS connection: open
06.أبر.23 10:14:39,137|DEBUG|lightstreamer.session|Session Thread <1>|SessionWS state change (1) (ok): WS_CONNECTING -> WS_CONNECTED
06.أبر.23 10:14:39,138|DEBUG|lightstreamer.stream|Session Thread <1>|WS transport sending [e4e58556]: bind_session
LS_cause=loop1&LS_session=S22dfab6342ca12c1M160T14 38774&
06.أبر.23 10:14:39,140|DEBUG|lightstreamer.session|Session Thread <1>|Session state change (1): FIRST_PAUSE -> FIRST_BINDING
06.أبر.23 10:14:39,141|DEBUG|lightstreamer.session|Session Thread <1>|Status timeout in 4000 [bindTimeout]
06.أبر.23 10:14:39,142|DEBUG|lightstreamer.stream|Session Thread <1>|WS transport sending [e4e58556]: control
LS_reqId=1&LS_op=add&LS_subId=1&LS_mode=MERGE&LS_g roup=LSTOCKS&LS_schema=key command Data&LS_data_adapter=FEEDER_ADAPTER&LS_snapshot=tr ue&LS_requested_max_frequency=1&LS_session=S22dfab 6342ca12c1M160T1438774&
06.أبر.23 10:14:39,143|DEBUG|lightstreamer.actions|Session Thread <1>|Subscription 1 sent to server
06.أبر.23 10:14:39,143|DEBUG|lightstreamer.heartbeat|Session Thread <1>|rhb updated
06.أبر.23 10:14:39,254|DEBUG|lightstreamer.stream|Netty Thread 1|WS transport receiving [e4e58556]:
CONOK,S22dfab6342ca12c1M160T1438774,50000,5000,*
06.أبر.23 10:14:39,255|DEBUG|lightstreamer.protocol|Session Thread <1>|New message (1): CONOK,S22dfab6342ca12c1M160T1438774,50000,5000,*
06.أبر.23 10:14:39,255|DEBUG|lightstreamer.session|Session Thread <1>|OK event while FIRST_BINDING
06.أبر.23 10:14:39,255|INFO |lightstreamer.actions|Session Thread <1>|Keepalive Interval value changed to 5000
06.أبر.23 10:14:39,256|INFO |lightstreamer.actions|Session Thread <1>|Session ID value changed to S22dfab6342ca12c1M160T1438774
06.أبر.23 10:14:39,256|INFO |lightstreamer.actions|Session Thread <1>|Server Instance Address value changed to http://etrdwebs02:8282/
06.أبر.23 10:14:39,256|DEBUG|lightstreamer.session|Session Thread <1>|Data event while FIRST_BINDING
06.أبر.23 10:14:39,256|DEBUG|lightstreamer.session|Session Thread <1>|Session state change (1): FIRST_BINDING -> RECEIVING
06.أبر.23 10:14:39,256|DEBUG|lightstreamer.session|Session Thread <1>|Status timeout in 5000 [keepaliveInterval]
Client property changed: keepaliveInterval
Client property changed: sessionId
Client property changed: serverInstanceAddress
Connection status changed to CONNECTED:WS-STREAMING
06.أبر.23 10:14:39,257|DEBUG|lightstreamer.mpn|Session Thread <1>|MpnManager state change (null) on 'onSessionStart': NoSessionState -> SessionOkState
06.أبر.23 10:14:39,259|DEBUG|lightstreamer.session|Session Thread <1>|Reset currentRetryDelay: 4000
06.أبر.23 10:14:39,259|DEBUG|lightstreamer.session|Session Thread <1>|Reset currentConnectTimeout: 4000
06.أبر.23 10:14:39,264|DEBUG|lightstreamer.stream|Netty Thread 1|WS transport receiving [e4e58556]:
CONS,unlimited
-
April 6th, 2023, 01:18 PM
#10
The log seems truncated before any data could be received.
Really this is the only log collected and after 10:14:39,264 nothing else is logged?
In this case the whole application would be frozen.
Similar Threads
-
By ahmedsmart4tech in forum Adapter SDKs
Replies: 7
Last Post: August 19th, 2014, 02:11 PM
-
By New Soft in forum Client SDKs
Replies: 3
Last Post: July 7th, 2014, 09:57 AM
-
By faa666 in forum General
Replies: 1
Last Post: February 15th, 2012, 08:54 AM
-
By omidqrose in forum General
Replies: 2
Last Post: May 23rd, 2011, 12:44 PM
-
By brianjohnson in forum Adapter SDKs
Replies: 2
Last Post: April 5th, 2010, 12:02 PM
Tags for this Thread
Posting Permissions
- You may not post new threads
- You may not post replies
- You may not post attachments
- You may not edit your posts
-
Forum Rules
All times are GMT +1. The time now is 09:22 AM.
Bookmarks