Accumulated Delay

ManKeer

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

Giuseppe Corti

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

ManKeer

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

Dario Crivelli

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?

ManKeer

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

Dario Crivelli

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.

ManKeer

Dear Dario,

I have the following scenario on the server:

Line 267015: 04-Apr-23 13:38:08,273|INFO |L.requests |SERVER POOLED THREAD 3380 |Serving request: /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=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]& on "Lightstreamer HTTP Server" from 10.244.210.1:22410
Line 267016: 04-Apr-23 13:38:08,461|INFO |L.requests |SERVER POOLED THREAD 3379 |Serving request: /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=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]& on "Lightstreamer HTTP Server" from 10.244.210.1:57570
Line 267023: 04-Apr-23 13:38:12,195|INFO |L.requests |SERVER POOLED THREAD 3428 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.create.timeout&LS_polling_millis=0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]&LS_old_session=& on "Lightstreamer HTTP Server" from 10.244.210.1:26519
Line 267024: 04-Apr-23 13:38:12,430|INFO |L.requests |SERVER POOLED THREAD 3427 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.create.timeout&LS_polling_millis=0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]&LS_old_session=& on "Lightstreamer HTTP Server" from 10.244.210.1:48389
Line 267035: 04-Apr-23 13:38:16,195|INFO |L.requests |SERVER POOLED THREAD 3433 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.create.timeout&LS_polling_millis=0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]&LS_old_session=& on "Lightstreamer HTTP Server" from 10.244.210.1:51146
Line 267036: 04-Apr-23 13:38:16,430|INFO |L.requests |SERVER POOLED THREAD 3433 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.create.timeout&LS_polling_millis=0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]&LS_old_session=& on "Lightstreamer HTTP Server" from 10.244.210.1:9642
Line 267044: 04-Apr-23 13:38:20,195|INFO |L.requests |SERVER POOLED THREAD 3433 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.create.timeout&LS_polling_millis=0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]&LS_old_session=& on "Lightstreamer HTTP Server" from 10.244.210.1:16613
Line 267051: 04-Apr-23 13:38:20,430|INFO |L.requests |SERVER POOLED THREAD 3395 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.create.timeout&LS_polling_millis=0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]&LS_old_session=& on "Lightstreamer HTTP Server" from 10.244.210.1:61370
Line 267107: 04-Apr-23 13:38:24,211|INFO |L.requests |SERVER POOLED THREAD 3410 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.create.timeout&LS_polling_millis=0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]&LS_old_session=& on "Lightstreamer HTTP Server" from 10.244.210.1:20579
Line 267108: 04-Apr-23 13:38:24,445|INFO |L.requests |SERVER POOLED THREAD 3408 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.create.timeout&LS_polling_millis=0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]&LS_old_session=& on "Lightstreamer HTTP Server" from 10.244.210.1:13569
Line 267117: 04-Apr-23 13:38:28,227|INFO |L.requests |SERVER POOLED THREAD 3297 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.create.timeout&LS_polling_millis=0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]&LS_old_session=& on "Lightstreamer HTTP Server" from 10.244.210.1:15778
Line 267118: 04-Apr-23 13:38:28,477|INFO |L.requests |SERVER POOLED THREAD 3411 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.create.timeout&LS_polling_millis=0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]&LS_old_session=& on "Lightstreamer HTTP Server" from 10.244.210.1:7935
Line 267138: 04-Apr-23 13:38:32,227|INFO |L.requests |SERVER POOLED THREAD 3445 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.create.timeout&LS_polling_millis=0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]&LS_old_session=& on "Lightstreamer HTTP Server" from 10.244.210.1:28391
Line 267139: 04-Apr-23 13:38:32,461|INFO |L.requests |SERVER POOLED THREAD 3445 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.create.timeout&LS_polling_millis=0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]&LS_old_session=& on "Lightstreamer HTTP Server" from 10.244.210.1:54842
Line 267552: 04-Apr-23 13:39:31,764|INFO |L.requests |SERVER POOLED THREAD 3375 |Serving request: /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=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]& on "Lightstreamer HTTP Server" from 10.244.210.1:47873
Line 267554: 04-Apr-23 13:39:31,795|INFO |L.requests |SERVER POOLED THREAD 3375 |Serving request: /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=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]& on "Lightstreamer HTTP Server" from 10.244.210.1:29280
Line 267574: 04-Apr-23 13:39:32,686|INFO |L.requests |SERVER POOLED THREAD 3377 |Serving request: /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=pcYgxptg4pkpW39AN3R4hwLri8L7R7q&LS_adapter_set=STOCKLISTDEMO&LS_user=205021&LS_password=[...]& on "Lightstreamer HTTP Server" from 10.244.210.1:9975

Why do I receive multiple requests ? the client request one connection, so why do I receive this number of requests?

Giuseppe Corti

Hi ManKeer,

If you are expecting only one client session, there are two strange things that can be inferred from this request list:

1) It seems that there are two streams of parallel requests separated by about 200 milliseconds.
Look for example at the first two, both of them with LS_cause=new.ap, that means that both are triggered by an explicit call of the connect method of the API.

2) Then new attempts are noted every 4 seconds. This means that the client library fails to establish the session within the defined timeout, precisely 4 seconds, and then proceeds with a new attempt.
Understanding why it fails is difficult with just this log excerpt, but it may be that the client is not receiving at all the create_request reply or the next attempt to bind is unsuccessful.
Are you targeting a single instance of Lightstreamer server or a cluster of two or more instances? Because in the latter case maybe there are addressing problems, i.e. two requests from the same client end up at two different instances.

Regards,
Giuseppe

ManKeer

why do I receive this message " Unexpected update for item xxxx" ?

Giuseppe Corti

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

ManKeer

ManKeer

Dario Crivelli

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.

ManKeer

Hi giuseppe,

Unfortunately, the accumulated delay problem back again.

Some clients face this issue too much and they're big customers.

the delay keep accumulated, starting from seconds up to minutes.

In the code we:

setRequestedMaxFrequency("unlimited");
setRequestedSnapshot("yes");

Could this cause that issue? this adapter works in MERGE mode.

How can I eliminate queueing in case there's a queue of messages for that customer.

Is there's a way to enable the pumps log on PRODUCTION for specific users ?
Your help is appreciated..

Giuseppe Corti

Hi ManKeer,

Delays can have two different origins, either on the server-side or on the client-side.

If the origin is on the server-side, it would affect all clients indiscriminately first and should be relatively easily traceable in the server log.
Could you please send us (support@lightstreamer.com) an excerpt from the lightstreamer.log of a server to which these clients who experienced the issue were connected?
A portion covering approximately one hour of time should be ok.

If the issue is on the client-side, the right way to avoid data queuing is to use the MERGE mode.
In this way, the server does not maintain a data buffer, and for each user subscription, only the most recent image is retained.
However, this mechanism does not exclude the possibility that the client itself, in its TCP buffer, may accumulate some data, assuming it is slow in processing and presenting this data delays can still occur in this case.
In this scenario, it may be useful to reduce the update frequency on the client side, by replacing setRequestedMaxFrequency("unlimited"); with a lower frequency setting. For example, you can request only 1 or 2 updates per second and check if the problem is mitigated.

setRequestedMaxFrequency(1);

or

setRequestedMaxFrequency(2);

On the other hand, requesting the snapshot should not make any difference during the data streaming unless it is an extremely large amount of data that triggers a delay in the application from the beginning. However, I would tend to exclude this.

ManKeer

Thanks giuseppe,

Does the queueing happen per user session on the server side?

Giuseppe Corti

Hi ManKeer,

Yes, server-side queuing occurs independently for each individual subscription of each user session. But as I mentioned, for MERGE-mode subscriptions, there is no server-side queuing unless the 'unfiltered' mode is explicitly requested.

Regards,
Giuseppe

ManKeer

Hi giuseppe,

I have sent you an email on support@lightstreamer.com

the email contains two attachments of the server logs , one for an accumulated delay customer and the other for normal customer.

I hope we can solve this issue ASAP.

Regards

Giuseppe Corti

Hi ManKeer,

Thank you for the logs.
We have analyzed them and it appears evident that for the client experiencing delays, there are duplicate subscriptions.
In fact, the difference in the data volume between the two scenarios can only be explained this way.
In the case with delays, we have the same subscription repeated six times:

Line 739: 08-Oct-23 09:43:14,553|INFO |L.requests |SERVER POOLED THREAD 69 |Serving request: control -> LS_reqId=7 &LS_op=add&LS_subId=3&LS_mode=MERGE&LS_group=tad.market_status tad.indices.TASI tad.list_prices&LS_schema=prices&LS_snapshot=true&LS_requested_max_frequency=unlimited&LS_session=S9c405df8ade4eebeMa4dT4314240& on "Lightstreamer HTTP Server" from 10.244.210.1:9819
Line 740: 08-Oct-23 09:43:14,553|INFO |L.requests |SERVER POOLED THREAD 50 |Serving request: control -> LS_reqId=8 &LS_op=add&LS_subId=5&LS_mode=MERGE&LS_group=tad.market_status tad.indices.TASI tad.list_prices&LS_schema=prices&LS_snapshot=true&LS_requested_max_frequency=unlimited&LS_session=S9c405df8ade4eebeMa4dT4314240& on "Lightstreamer HTTP Server" from 10.244.210.1:9819
Line 741: 08-Oct-23 09:43:14,553|INFO |L.requests |SERVER POOLED THREAD 35 |Serving request: control -> LS_reqId=9 &LS_op=add&LS_subId=6&LS_mode=MERGE&LS_group=tad.market_status tad.indices.TASI tad.list_prices&LS_schema=prices&LS_snapshot=true&LS_requested_max_frequency=unlimited&LS_session=S9c405df8ade4eebeMa4dT4314240& on "Lightstreamer HTTP Server" from 10.244.210.1:9819
Line 743: 08-Oct-23 09:43:14,553|INFO |L.requests |SERVER POOLED THREAD 50 |Serving request: control -> LS_reqId=12&LS_op=add&LS_subId=9&LS_mode=MERGE&LS_group=tad.market_status tad.indices.TASI tad.list_prices&LS_schema=prices&LS_snapshot=true&LS_requested_max_frequency=unlimited&LS_session=S9c405df8ade4eebeMa4dT4314240& on "Lightstreamer HTTP Server" from 10.244.210.1:9819
Line 746: 08-Oct-23 09:43:14,553|INFO |L.requests |SERVER POOLED THREAD 39 |Serving request: control -> LS_reqId=10&LS_op=add&LS_subId=7&LS_mode=MERGE&LS_group=tad.market_status tad.indices.TASI tad.list_prices&LS_schema=prices&LS_snapshot=true&LS_requested_max_frequency=unlimited&LS_session=S9c405df8ade4eebeMa4dT4314240& on "Lightstreamer HTTP Server" from 10.244.210.1:9819
Line 747: 08-Oct-23 09:43:14,553|INFO |L.requests |SERVER POOLED THREAD 71 |Serving request: control -> LS_reqId=11&LS_op=add&LS_subId=8&LS_mode=MERGE&LS_group=tad.market_status tad.indices.TASI tad.list_prices&LS_schema=prices&LS_snapshot=true&LS_requested_max_frequency=unlimited&LS_session=S9c405df8ade4eebeMa4dT4314240& on "Lightstreamer HTTP Server" from 10.244.210.1:9819

instead the 'no delay' case only one:

Line 227577: 08-Oct-23 09:44:54,768|INFO |L.requests |SERVER POOLED THREAD 159 |Serving request: control -> LS_reqId=3 &LS_op=add&LS_subId=2&LS_mode=MERGE&LS_group=tad.market_status tad.indices.TASI tad.list_prices&LS_schema=prices&LS_snapshot=true&LS_requested_max_frequency=unlimited&LS_session=S52e4fe9b5763e735Ma4dT4454753& on "Lightstreamer HTTP Server" from 10.244.210.1:9526

That, for example, causes the number of snapshot images sent immediately after the subscriptions to be around 70 for the 'no delay' case compared to approximately 430.

I cannot know whether this repetition is something normal and perhaps handled during the processing of getItems, or if it simply generates subscriptions for duplicate items. Looking at the logs, I also noticed identical updates twice.

To address this issue, you can take action on the client side by ensuring that your application does not generate duplicate subscriptions, especially during disconnection and reconnection.
Alternatively, you can also handle it on the adapter side by enforcing, in your metadata, the rejection of subscriptions to the same group if a user already has an active subscription for the same.

That being said, The message frequency doesn't seem to be that high, approximately 10 updates per second, but we fear that you performed a grep for the session ID, and this way, many updates sent might have been missed. And so, we are unable to establish with certainty the data repetition rate.
Could you provide us with a snippet, even just 10 seconds, of the complete log within the same interval as the ones you sent us, say around 08-Oct-23 10:02:00?

Regards,
Giuseppe

ManKeer

Thanks giuseppe,

I will try to send you the log by tomorrow morning.

Now, how can I detect if this user already subscribed in this group from adapter side?

Regards