Page 1 of 2 12 LastLast
Results 1 to 10 of 18
  1. #1
    Power Member
    Join Date
    Nov 2012
    Posts
    182

    Need to reduce overhead on a round-trip message/response

    I have been using a SmartDataProvider to perform a task which basically does this:

    -> Subscription with one data element (field)
    -> sendMessage from client
    -> Message received by MetadataAdapter and passed to data adapter
    -> Response (of about 20000 bytes) returned to client using smartUpdate

    Although the process is working, I have noticed that when the response is consistently the same I get a round-trip of between 150-200ms. It seems quite a lot, but it is acceptable. However, if the response is different each time (albeit still around 20000 bytes) the round trip is consistently about 120ms longer.

    This seems to indicate that somewhere along the line some sort of check is being carried out on the data being returned to see if it has changed. Is the possible? If so, is there any way I can avoid that check? I can see why this would be happening/necessary in a normal subscription where (for example) you only want the client to be bothered if the data changes, but in this instance I want the data regardless, and I don't want any overhead at all.

    I am using DISTINCT on my subscription, but I haven't yet got my head around the difference between DISTINCT, MERGE, COMMAND etc - so this could be one thing I am doing incorrectly. I am also using a SmartDataProvider, and perhaps for this I need to use a "LessSmart"DataProvider.

    Can you give me any idea what I could/should be doing differently in this case?

    Many thanks.

  2. #2
    Administrator
    Join Date
    Jul 2006
    Location
    Milan, Italy
    Posts
    517
    My colleagues will give you an answer tomorrow, but I was curious to know if you are performing the test locally. In such case, a 150ms roundtrip looks like a huge time. Consider that when not under heavy stress, the upper latency limit should be equal to <max_delay_millis> as configured in lightstreamer_conf.xml, which, by default, is 30ms.

  3. #3
    Power Member
    Join Date
    Nov 2012
    Posts
    182
    Hello Alessandro,

    Your answer has me a bit worried that I have messed something up. I am not testing locally as such. The client is obviously running on my PC, and Lightstreamer is running on a very powerful IBMi partition (JDK 7). It is on the same subnet (so not over the internet).

    I am effectively having to use Lighstreamer to emulate a XHR request for comparison purposes. I know this is not what it is usually meant for, but my benchmarking includes this test.

    I am effectively creating a connection, a subscription (DISTINCT) and a listener on the subscription. I then send a querystring using sendMessage and my data adapter passes this to an RPG program (via a data queue) that generate about 20000 bytes of static HTML with embedded script etc. This is passed back to the client using smartUpdate, and when onItemUpdate fires on my listener, some script uses jQuery to replace some elements of the DOM with the HTML etc received.

    It works - so good. However, if I cache the response in the data adapter so that subsequent calls completely omit the RPG call and just sends back the previous response, I still get a round trip averaging around 150-170ms. I am sending a tiny querystring of about 200 bytes and returning about 20000 bytes. Why does it take so long? My timer starts when the sendMessage() is called, and stops when onItemUpdate() fires - so the fiddling around with the response is omitted from the timer completely.

    My metadataadapter and dataadapter are fairly trivial. I could include the code if it helps, but I don't want to clutter up the thread yet unless you think it is necessary. I am hoping I have a big mistake there that explains it.

    Even my simple echo server takes about 120ms to echo a message back.
    Last edited by kpturner; December 12th, 2012 at 12:00 AM.

  4. #4
    Power Member
    Join Date
    Nov 2012
    Posts
    182
    I should also add that it woud be normal (without the caching test) for the bit that calls the RPG program to take around 250-250ms. I would therefore expect the total round trip to be about 300 at the most. Do I need to consider anything in the config to cater for that (you mentioned <max_delay_millis>)? This question is obviously secondary to the above issue.

  5. #5
    Power Member
    Join Date
    Jul 2006
    Location
    Cesano Maderno, Italy
    Posts
    784
    hi,

    Yes the max_delay_millis has an impact on the minimum delay as it represents the longest delay that the Server is allowed to apply to outgoing updates in order to collect more updates in the same packet.

    As per the problem you're facing, I would start to verify that the delay is not inside the server, if you have the LightstreamerLogger.requests lo category set to INFO and LightstreamerLogger.subscriptions and LightstreamerLogger.push log categories set to DEBUG you can trace when the message reaches the server when the response is sent back from the adapter to the server and when the response is written out to the client. All of the exceeding delay is spent on the net and on the client.

    As per the client part, I just discovered that there is a sort of bug in the client that is triggered when the client is executed from file:/// that slows the execution of internal tasks; Do you load your test pages from file:/// ?

    I'm also introducing another speed-up in the client and I'm going to send you via private message a download link that points to the fixed & improved client.

    HTH

  6. #6
    Power Member
    Join Date
    Nov 2012
    Posts
    182
    I have the client fix thanks. Now I will modify my logging and see what I can fathom out on the simple echo server. I guess a round trip of 150-170ms for a simple echo is not expected?

    I am not quite clear on the max_delay_millis config option despite your explanation. If I have expected longish roundtrips of 300ms (for example), should I change this value to be higher than that? What are the implications of making it too high (or too low)?

  7. #7
    Power Member
    Join Date
    Nov 2012
    Posts
    182
    I forgot to answer your question - no I am not using file://

    I set the logging as instructed in lightstreamer_log_conf.xml but it made no difference whatsoever to the output from the server. The log file for my adapters seems to behave OK though (I can switch between INFO, DEBUG etc successfully with my adapters). Have I changed the logging in the wrong place?
    <!-- logging of Data Adapters interactions -->
    <!-- at DEBUG level, events coming from the Data Adapters are dumped -->
    <logger name="LightstreamerLogger.subscriptions" level="DEBUG"/>

    <!-- logging of socket write activity -->
    <!-- at DEBUG level, all socket writes are dumped -->
    <logger name="LightstreamerLogger.push" level="DEBUG"/>
    EDIT: Ignore that - I am looking at the console output! Let me check the other logs.

  8. #8
    Power Member
    Join Date
    Nov 2012
    Posts
    182
    OK - so I have a request/response cycle that took 313ms from the "sendMessage()" to the "onItemUpdate()" on the listener.

    The log is shown below. This seems to indicate that the request was received at 10:19:32,710 and the push took place at 10:19:32,832 -> 122ms
    So that is 191ms on the network and in client.

    Other than length of time on the network/client, something else puzzles me: The output during this test is just a cached global string. My data adapter is doing virtually zero work other than to echo back 20000 bytes. So what accounts for the 119ms here? It seems to be related to the size of the response? Is it the execution of the smartUpdate or the logging itself?


    Log
    Pragma: no-cache
    Expires: Thu, 1 Jan 1970 00:00:00 GMT
    Date: Thu, 13 Dec 2012 10:19:27 GMT
    Content-Length: 86
    Access-Control-Allow-Origin: http://rnsdev:8081
    Access-Control-Allow-Credentials: true

    setPhase(7543);start('Sb60d90daf0c2c74T1553581', null, 19000, 50000);loop(0);end( );

    13-Dec-12 10:19:32,710|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 8 |Serving request: /lightstreamer/msg.js --> LS_message=<--querystring here--> on "Lightstreamer HTTP Server" from 10.2.0.167:59712
    13-Dec-12 10:19:32,711|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 8 |Sending message to session: S2e472b1dd69c6329T1553581 on "Lightstreamer HTTP Server" from 10.2.0.167:59712
    13-Dec-12 10:19:32,712|DEBUG|LightstreamerLogger.push |PUMP POOLED THREAD 8 |RELEASING DATA --> HTTP/1.1 200 OK
    Server: Lightstreamer/5.0 build 1576 (Lightstreamer Push Server - www.lightstreamer.com) Vivace edition
    Content-Type: text/javascript; charset=iso-8859-1
    Cache-Control: no-store
    Cache-Control: no-cache
    Pragma: no-cache
    Expires: Thu, 1 Jan 1970 00:00:00 GMT
    Date: Thu, 13 Dec 2012 10:19:32 GMT
    Content-Length: 119
    Access-Control-Allow-Origin: http://rnsdev:8081
    Access-Control-Allow-Credentials: true

    setPhase(3703);start('S2e472b1dd69c6329T1553581', null, 19000, 50000);c(4,3,"UNORDERED_MESSAGES",0,0);loop(0);end ( );

    13-Dec-12 10:19:32,713|DEBUG|LightstreamerLogger.subscriptio ns|Thread-38 |INCOMING DATA for RPC.CXRMCJF6ZP.S2e472b1dd69c6329T1553581 --> {response=Content-type: text/html

    <-----Approximately 20000 bytes of data from application logged here --->
    }

    13-Dec-12 10:19:32,831|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 6 |Polling (42) to session: S2e472b1dd69c6329T1553581 on "Lightstreamer HTTP Server" from 10.2.0.167:59693
    13-Dec-12 10:19:32,832|DEBUG|LightstreamerLogger.push |PUMP POOLED THREAD 8 |RELEASING DATA --> HTTP/1.1 200 OK
    Server: Lightstreamer/5.0 build 1576 (Lightstreamer Push Server - www.lightstreamer.com) Vivace edition
    Content-Type: text/javascript; charset=iso-8859-1
    Cache-Control: no-store
    Cache-Control: no-cache
    Pragma: no-cache
    Expires: Thu, 1 Jan 1970 00:00:00 GMT
    Date: Thu, 13 Dec 2012 10:19:32 GMT
    Content-Length: 96
    Access-Control-Allow-Origin: http://rnsdev:8081
    Access-Control-Allow-Credentials: true

    setPhase(3705);start('S2e472b1dd69c6329T1553581', null, 19000, 50000);d(6,1,1);loop(0);end( );

  9. #9
    Administrator
    Join Date
    Jul 2006
    Location
    Milan
    Posts
    975
    The <max_delay_millis> setting allows batching of updates in a single packet.
    The batching involves updates for different items and, depending on the kind of subscription, also subsequent updates for the same item.
    The delay caused by this batching operation depends on the whole sequence of updates;
    you can only expect that the delays will be distributed between 0 and the <max_delay_millis> value chosen.

    So, for a test like yours, you should set it to 0, so it will not alter the flow.
    In the final application, depending on the expected throughput on your sessions, you may decide to set it higher, to reduce the Server and network overload at the expense of some additional delay on the updates.

  10. #10
    Power Member
    Join Date
    Nov 2012
    Posts
    182
    Here is a second test, using the exact same code, but where the cached response is a trivial size. The round trip took 74ms, and here athe log is shown below. The time spent between the request and the response is a mere 32ms in comparison - although still in excess of <max_delay_millis>

    So it does seem to point to some issue regarding the size of the response.....or you may say it is expected (although 20000 bytes does not strike me a massive amount of data).



    13-Dec-12 10:46:34,998|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 7 |Serving request: msg -> LS_message=<--querystring-->on "Lightstreamer HTTP Server" from 10.2.0.167:60056
    13-Dec-12 10:46:35,002|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 7 |Sending message to session: S72cd3ecfd5e822e0T4604590 on "Lightstreamer HTTP Server" from 10.2.0.167:60056
    13-Dec-12 10:46:35,010|DEBUG|LightstreamerLogger.subscriptio ns|Thread-36 |INCOMING DATA for RPC.CXRMCJF6ZP.S72cd3ecfd5e822e0T4604590 --> {response=Trivial response}
    13-Dec-12 10:46:35,020|DEBUG|LightstreamerLogger.push |PUMP POOLED THREAD 8 |RELEASING DATA --> d(3,1,'Trivial response');

    13-Dec-12 10:46:40,030|DEBUG|LightstreamerLogger.push |PUMP POOLED THREAD 8 |RELEASING DATA --> p();

    13-Dec-12 10:46:44,324|DEBUG|LightstreamerLogger.push |PUMP POOLED THREAD 8 |RELEASING DATA --> HTTP/1.1 200 OK

 

 

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 01:36 PM.