Page 1 of 3 123 LastLast
Results 1 to 10 of 33

Hybrid View

  1. #1
    Senior Member
    Join Date
    Dec 2019
    Posts
    66

    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

  2. #2
    Administrator
    Join Date
    Feb 2012
    Location
    Milano
    Posts
    716
    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

  3. #3
    Senior Member
    Join Date
    Dec 2019
    Posts
    66
    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

  4. #4
    Administrator
    Join Date
    Jul 2006
    Location
    Milan
    Posts
    1,091
    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?

  5. #5
    Senior Member
    Join Date
    Dec 2019
    Posts
    66
    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

  6. #6
    Administrator
    Join Date
    Jul 2006
    Location
    Milan
    Posts
    1,091
    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.

  7. #7
    Administrator
    Join Date
    Feb 2012
    Location
    Milano
    Posts
    716
    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

  8. #8
    Senior Member
    Join Date
    Dec 2019
    Posts
    66
    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

  9. #9
    Senior Member
    Join Date
    Dec 2019
    Posts
    66
    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

  10. #10
    Administrator
    Join Date
    Jul 2006
    Location
    Milan
    Posts
    1,091
    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

  1. delay and strange behavior
    By ahmedsmart4tech in forum Adapter SDKs
    Replies: 7
    Last Post: August 19th, 2014, 02:11 PM
  2. Delay in retrieving data
    By New Soft in forum Client SDKs
    Replies: 3
    Last Post: July 7th, 2014, 09:57 AM
  3. Current delay in log file
    By faa666 in forum General
    Replies: 1
    Last Post: February 15th, 2012, 08:54 AM
  4. Unexpected Delay
    By omidqrose in forum General
    Replies: 2
    Last Post: May 23rd, 2011, 12:44 PM
  5. Delay in notifyUser() causes erratic create_session behavior
    By brianjohnson in forum Adapter SDKs
    Replies: 2
    Last Post: April 5th, 2010, 12:02 PM

Tags for this Thread

Bookmarks

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •  
All times are GMT +1. The time now is 09:43 AM.