log file analysis

ahmedsmart4tech

Dears,
i got a lot of messages like this one :
20-Aug-14 15:29:56,277|WARN |LightstreamerLogger.preprocessor |#1 Notify Receiver |Unexpected UPDATE event for key 196-o0-5. Event propagated as an ADD command.

&

20-Aug-14 15:35:07,614|ERROR|rs.remote.data.RemoteDataProvider|Timer-4 |Exception caught while unsubscribing from item 'oa40': Timeout while waiting for an answer to request 86300000147f236221e

&

20-Aug-14 15:35:07,616|WARN |emote.request_reply.RequestSender|#1 Reply Receiver |Reply to request 80600000147f236221e received too late

&

20-Aug-14 00:36:57,297|INFO |LightstreamerLogger.requests |FOR PUMPS PARKING DESTROYER|Closed session Sb1a5abb090445c5dT1324154 with internal cause code: 38 (Interrupted).

and please need to check that everything is OK and help me to solve all problems if found,
you can download the log file from here :
https://www.mediafire.com/?o9z3cqvpr9un39v
Regards,

ahmedsmart4tech

Waiting your reply,
Regards,

Mone

[COLOR=#333333]20-Aug-14 15:29:56,277|WARN |LightstreamerLogger.preprocessor |#1 Notify Receiver |Unexpected UPDATE event for key 196-o0-5. Event propagated as an ADD command.[/COLOR]

The first update for a new key in a COMMAND subscription is expected to carry the ADD value on the command field. In this case the first update was issued as an UPDATE command: with this log line the server is notifying you that something might be wrong in your code and that it corrected the value.

[COLOR=#000000]20-Aug-14 15:35:07,614|ERROR|rs.remote.data.RemoteDataProvid er|Timer-4 |Exception caught while unsubscribing from item 'oa40': Timeout while waiting for an answer to request 86300000147f236221e[/COLOR]

and

[COLOR=#000000]20-Aug-14 15:35:07,616|WARN |emote.request_reply.RequestSender|#1 Reply Receiver |Reply to request 80600000147f236221e received too late[/COLOR]

are related to the same issue: the remote adapter was too slow in answering to the server
This is the same issue you discussed with Giuseppe here.
From his post:

Please could you confirm if your unsubscribe method implementation is particularly heavy and, maybe, it requires calls to external components? Please note that in a case such your, with Remote adapters and several hundreds of calls involved, just only a processing time of few tenths of a second may result in significant delays.

Since one of our suspicions is that the server remains for a long time waiting for answers from the Metadata Adapter, a first possibility of change in the Lightstreamer server configuration, in order to mitigate the issue, is to increase the size of the SERVER thread pool.
A first suggestion would be to raise it to 100. Please refer to <server_pool_max_size> parameter in "lightstreamer_conf.xml" configuration file.

[COLOR=#000000]20-Aug-14 00:36:57,297|INFO |LightstreamerLogger.requests |FOR PUMPS PARKING DESTROYER|Closed session Sb1a5abb090445c5dT1324154 with internal cause code: 38 (Interrupted).[/COLOR]

This means that the socket of the specified session was closed.
This might be a problem with the network or simply a client closing down.

ahmedsmart4tech

Thanks for your reply,
now i have this in my monitor and i wondering about the total and free heap is it related to current session and connections , and if so what i have to do if i am expecting sessions u to 2000 users

Total Heap Free Heap Memory (Bytes) 271,581,184 33,808,872 Total Streaming Mode Smart-Polling Mode Max Sessions 28 28 0 28 Total Max Connections 28 35 Subscribed Items Throughput (updates/s) Total Received Updates Inbound 382 52.47 819,407 Throughput (updates/s) Throughput (kbit/s) Total Sent Bytes Total Sent Updates Total Lost Updates Outbound 282.36 204.32 145,527,666 2,823,790 0 Throughput (messages/s) Throughput (kbit/s) Total Processed Bytes Total Handled Messages Client Messages 0 0 0 0 Size Active Available Queued Tasks Thread Pool 38 0 38 0 Total JVM Threads 101

Dario Crivelli

The free heap as reported by the Monitor is the current sample of the available heap, as determined by the JVM.
However, this value does not include all that part of the heap that is already eligible for the garbage collection.
Hence, the free heap figure is significant only after a garbage collection has just taken place.
You can infer this amount only after comparing many subsequent samples. Assuming basic GC settings, you should see the free heap value decrease regularly, then increase sharply after a GC.
Obviously, for better statistics, you can leverage the JVM's own GC reports.

After determining the "real" free heap and the "real" used heap, consider that the static memory footprint of the active sessions is only part of the used heap.
In your scenario, since the sessions are just a few, their footprint may be a small part of the used heap and you may find out that there is room for 2000 sessions without enlarging the total heap.
But we cannot help you estimate the exact footprint of a session, because it also depends on the involved subscriptions and the involved data flow.
Obviously, apart from the static memory footprint, each session causes usage of short-lived memory because of the data delivery. Even though this memory is garbage collected, it may deserve a significant slice of the heap for best performance.

ahmedsmart4tech

Dears,
now i am expecting about 2000 concurrent users from tomorrow, theoretically how many the engine can handle ? , and each user connected the speed for subscribed data get slower , what should i check or handle to be ensure about the engine working perfectly Regards,

Mone

now i am expecting about 2000 concurrent users from tomorrow, theoretically how many the engine can handle ?

The total throughput is much more important than the number of connected users to estimate the expected performances. Obviously also the hardware in use plays a role.
Running a load test should clear any doubt beforehand

and each user connected the speed for subscribed data get slower , what should i check or handle to be ensure about the engine working perfectly

It depends on where the delay is forming.
For starters it is important to know how the client behave: how many items are available, how many items does a client subscribe, how many items are shared across clients and how do they intersect.
Then any slowdown in the adapter should be ruled out.
The default Lightstreamer server (and remote adapter) configuration is usually good for most cases, anyway both configuration files are well documented: you might want to read the various configuration descriptions to see if there is some suggestion that applies to your case.
At last it is possible to configure the server log to print the moment an update is received by the server kernel and the moment the update is sent to the client.

ahmedsmart4tech

Dears,
today the lightstreamer at the end of the session stopped working so i had to restart it which caused me a lot of troubles
the log file in this download link :
https://www.mediafire.com/?37qjf8m61rc61b0

and it's my first time to see those messages :

25-Aug-14 15:29:08,296|WARN |LightstreamerLogger.scheduler |Timer-1 |Current delay for tasks scheduled on thread pool SNAPSHOT is 35 seconds.

25-Aug-14 15:29:08,296|WARN |LightstreamerLogger.scheduler |Timer-1 |If the delay issue persists, taking a JVM full thread dump may be the best way to investigate the issue.

25-Aug-14 15:29:17,080|WARN |LightstreamerLogger.scheduler |Timer-1 |If the delay issue persists, taking a JVM full thread dump may be the best way to investigate the issue.

...
the server running the lightstreamer is xeon x5660 2.8 4 cores , 16.0 GB RAM ,
how i can allow max heap,Threads and throughput.

Regards,

ahmedsmart4tech

I appreciate your effort with us , waiting your reply,

Mone

sorry, got no time, I'll check the log as soon as possible

ahmedsmart4tech

Dear Mone,
Still waiting,
Regards,

Mone

Hi,

I checked the log, I think there was a load problem on the machine.

Unfortunately the LightstreamerMonitorText category of the log is still at INFO level (TRACE was suggested) so I can't tell if the CPU was stolen by the GC because of a shortage of memory or if the load on the machine was too much.
Did you notice how the CPU load was through the life of the server? Was it stable (at high levels) or had spikes?
Check the launch script of the server, (LS_HOME/bin/windows/LS.bat or LS_HOME/bin/unix/LS.sh depending on your system) is there any Xmx configured? Do you use the default GC? How much memory does the machine have?

Do you have any chance to run a load test?

ahmedsmart4tech

Dear Mone,
I changed the log fle to TRACE and here it is after that :
https://www.mediafire.com/?w8crwid46838vco
- the CPU was stable all the time.
- i used the default G.
- the machine is ( xeon x5660 2.8 4 cores , 16.0 GB RAM ).
- i contacted the support before to send me alod test , but they sent me java, so i replied to them to send me a .net load test, but with no answer till now.

Regards ,

Dario Crivelli

I see that the log was not taken in a real condition, as a maximum of 3 sessions were probed, with no updates.
So, it is not useful for the analysis of the previous issues.
Note that the same log setting of LightstreamerMonitorText as TRACE can be applied in your real scenario, with no need for a restart.

If you prefer to run a load test, you can also use the Java version, as the relevant part of the test is related with the update flow inside the Server, hence the client side is not involved. Our Load Test Toolkit uses its own clients and Adapters and requires that you configure them to simulate the traffic you expect in production. An implicit requirement is that you can estimate in some way the expected average behavior of your users, in terms of subscribed items and fields and the expected average activity of these items in terms of update rate and field length. Then you can simulate these items and fields.

As far as your current issues are concerned, we will switch to your new forum thread.