Performance improvements to Californium-proxy #479

martinmine · 2017-11-17T13:06:18Z

This is another submission of PR #474 which targets the 2.0.x branch instead of the master branch in addition to support Java versions prior to Java 8. I will paste the original text from #474 here:

With this PR, the stability and throughput of the californium-proxy gets significantly improved:

Proper use of log formatting to avoid the performance problem I have discussed in issue Wrong use of java.util.logging.Logger is causing extensive GC and performance degradation #436.
For some strange reason, for each request that goes through the proxy (towards a CoAP server) creates two threads: One worker thread that will perform the CoAP request, and one that will send the HTTP response back to the original requester. The second one will wait for the first one to complete. On top of it all, these two threads are created for each time there is a request. Californium has an async/nonblocking API where there is also a heavy worker thread model already in place, which renders this way of creating threads (for what I assume is either before they got the async support with the message handler in place, or before the threading model was introduce) for each incoming request useless.
Outgoing HTTP requests are now using the Apache HttpAsyncClient.
Prevent race conditions where concurrent HTTP requests may use the same Endpoint for CoAP requests where the message body might get inter-mixed with other concurrent messages. This is solved by using a pool of EndpointManagers across requests.

To benchmark the impact of these performance optimizations, I send as many requests through a http/coap/http pipeline for 5 minutes towards a local nginx server:

HTTP requestster -- <HTTP> -- Californium -- <CoAP> -- Californium -- <HTTP> -- nginx

With the current master, I get an average request throughput of 2.7ms (std.dev 2.5ms), with the changes propsed in this PR: 2.1ms (std.dev 1.01ms). This can be further improved by scaling down the threading model in Californium. Currently, each request is captured in a networking thread, which is then queued to a "protocol stage thread" which will do the actual packet processing. Messages sent back are also running on their own thread. This leads to each message being passed through 4 different threads (2 additional in the current master) which introduce delays where a message is picked up by the next thread, and limits cache-hit rate for threads. Some of these threads could have been taken care of at a lower level, both simplifying application design and performance. However, this goes beyond the scope of this PR.

martinmine · 2017-11-17T13:09:08Z

Before this gets merged: Both me and @vikram919 have had some issues regarding the dependencies. Im building the Californium framework by running mvn clean install, however by doing so the produced JARs does not contain the dependencies that is required to use the framework, and these does then have to be added explicitly together with whatever project is then referencing the JARs. Is this intentional? I have a strong feeling I am missing something here.

vikram919 · 2017-11-17T15:39:44Z

@martinmine
Thanks for your information, after adding the dependency it worked for now, I will let you know If I know the solution for above question.
One question as you described the test setup:

HTTP requestster -- <HTTP> -- Californium -- <CoAP> -- Californium -- <HTTP> -- nginx

as from the example we can acheieve

HTTP requester --- <HTTP> --Californium Server

how can we establsih?

Coap requester ----<CoAP>----HTTP Server

boaks · 2017-11-17T15:55:39Z

californium-proxy/pom.xml

 			<scope>compile</scope>
 		</dependency>
+		<dependency>
+			<groupId>net.sourceforge.streamsupport</groupId>
+			<artifactId>streamsupport</artifactId>


GPL!
I'm not sure, if you read the ECA carefully, but I guess using GPL is not possible :-)

I've read through it briefly (and now, yet again) and to my understanding they are talking about including source code, not referencing through maven. This is more discussed here: https://www.eclipse.org/legal/eplfaq.php#USEINANOTHER What do you think? Edit: Nvm, it does not work lol

Thanks for making me aware of this, I'll try and find a workaround :)

boaks · 2017-11-17T16:00:16Z

Thanks!
But including GPL dependency is, as fa as I know, not possible for a eclipse project.
(I hope, I haven't overseen this in your first PR.)

For the "httpasyncclient" we (the committers) must apply a CQ at eclipse for that.
I'm out of the office until 27.11. but will work on your PR, when I'm back.

martinmine · 2017-11-17T16:05:02Z

@boaks Thanks, sorry, I was not aware of this regarding the licenses.
On another note, I just re-visited the benchmarks on the 2.x branch.
Against the commit before the changes (850f6f3): Avg: 3.47ms, stdDev: 1.09ms, N: 86399
Against the changes in this PR: Avg: 1.42ms, stdDev: 1ms, N: 210529

boaks · 2017-11-17T16:07:18Z

Very promising!

boaks · 2017-11-17T16:09:13Z

@sophokles73
Maybe, you can already ask eclipse about the "httpasyncclient" (CQ)

martinmine · 2017-11-17T16:13:41Z

@vikram919 I wrote my setup based on the proxy example in the repo. Requests are then made towards the coap2http resource. There is also one small change I made in CoapTranslator.java to make it work (for some reason it wasn't setting the proxy URIs on the requests:

diff --git a/californium-proxy/src/main/java/org/eclipse/californium/proxy/CoapTranslator.java b/californium-proxy/src/main/java/org/eclipse/californium/proxy/CoapTranslator.java
index 6ef83f6e..4d81c92a 100755
--- a/californium-proxy/src/main/java/org/eclipse/californium/proxy/CoapTranslator.java
+++ b/californium-proxy/src/main/java/org/eclipse/californium/proxy/CoapTranslator.java
@@ -90,6 +90,7 @@ public final class CoapTranslator {
 
 		// get the uri address from the proxy-uri option
 		URI serverUri;
+		String proxyUriForward = null;
 		try {
 			/*
 			 * The new draft (14) only allows one proxy-uri option. Thus, this
@@ -97,6 +98,13 @@ public final class CoapTranslator {
 			 */
 			String proxyUriString = URLDecoder.decode(
 					incomingRequest.getOptions().getProxyUri(), "UTF-8");
+
+			final String proxyEndpoint = "coap2http/";
+			final int proxyEndpointPos = proxyUriString.indexOf(proxyEndpoint);
+			if (proxyEndpointPos > 0) {
+				proxyUriForward = proxyUriString.substring(proxyEndpointPos + proxyEndpoint.length());
+				proxyUriString = proxyUriString.substring(0, proxyEndpointPos + proxyEndpoint.length());
+			}
 			serverUri = new URI(proxyUriString);
 		} catch (UnsupportedEncodingException e) {
 			LOGGER.warn("UTF-8 do not support this encoding: {}", e);
@@ -121,6 +129,11 @@ public final class CoapTranslator {
 		options.removeBlock2();
 		options.clearUriPath();
 		options.clearUriQuery();
+
+		if (proxyUriForward != null && proxyUriForward.length() > 0) {
+			options.setProxyUri(proxyUriForward);
+		}
+
 		outgoingRequest.setOptions(options);
 		
 		// set the proxy-uri as the outgoing uri

martinmine · 2017-11-17T18:11:09Z

@boaks I've rebased and re-implemented the CompletableFuture class under the compat package. Should be good from the GPL license now :)

vikram919 · 2017-11-20T11:56:20Z

Hi @martinmine
Thanks for the help with the code.
I have created a test case:
Coap Client --> Californium<coap2coap> -->Californium<coap2http> --> HTTP local Server
and calculated the average after exchanging requests 1000 times it is 8.432ms
I have not tried with the same test case as yours.
I will put it here as soon as I have them.

martinmine · 2017-11-20T12:02:38Z

@vikram919 Do you also have some warmup period/request in your test? What was the standard deviation in your result? In my setup, I run as many requests as possible through the system for 10 minutes on one single thread requesting a HTML document and one warmup request.

martinmine · 2017-11-20T12:04:39Z

Btw, what system are you testing it on? (CPU/OS/memory)

vikram919 · 2017-11-20T12:19:37Z

Do you also have some warmup period/request in your test? What was the standard deviation in your result?

SD is 3.105ms, I see at the beginning it started with 16ms (initially).

Btw, what system are you testing it on? (CPU/OS/memory)

CPU: Intel 4600M, i7 2.90GHz processor
16GB RAM Windows OS

ResponseTime: 5 milli-seconds
==[ CoAP Response ]============================================
MID    : 57075
Token  : 2b9d9e51d4c72dd1
Type   : CON
Status : 2.05
Options: {"Content-Format":"application/octet-stream", "Max-Age":60}
Payload: 14 Bytes
===============================================================

sophokles73 · 2017-11-20T13:50:27Z

californium-proxy/src/main/java/org/eclipse/californium/compat/CompletableFuture.java

@@ -0,0 +1,59 @@
+/*******************************************************************************
+ * Copyright (c) 2015 Institute for Pervasive Computing, ETH Zurich and others.


this seems to be a new class so you should

put in the current year

use your name/affiliation instead of Institute of Pervasive ... suffixed by and others.

just put yourself to the list of contributors since nobody else has contributed anything to this class (yet)

sophokles73 · 2017-11-20T13:50:47Z

californium-proxy/src/main/java/org/eclipse/californium/compat/CompletableFuture.java

+ * Backport of the class introduced in Java java.util.concurrent.CompletableFuture<T>.
+ * @param <T> Type of the result the future shall complete with.
+ */
+public class CompletableFuture<T> {


has any of this code been copied from somewhere (given that you call it a backport)?

Nope, I just wrote it from the top of my head. It is a very basic straight-forward implementation.

ok, that's good :-)

sophokles73 · 2017-11-20T13:51:17Z

californium-proxy/src/main/java/org/eclipse/californium/compat/Consumer.java

@@ -0,0 +1,32 @@
+/*******************************************************************************
+ * Copyright (c) 2015 Institute for Pervasive Computing, ETH Zurich and others.


same as above ...

sophokles73 · 2017-11-20T13:52:58Z

californium-proxy/src/main/java/org/eclipse/californium/proxy/CoapTranslator.java

@@ -99,10 +99,10 @@ public static Request getRequest(final Request incomingRequest) throws Translati
 					incomingRequest.getOptions().getProxyUri(), "UTF-8");
 			serverUri = new URI(proxyUriString);
 		} catch (UnsupportedEncodingException e) {
-			LOGGER.warn("UTF-8 do not support this encoding: " + e);
+			LOGGER.warn("UTF-8 do not support this encoding: {}", e);


if you want to include the stack trace in the log statement, then you do not need to have a {} placeholder in here.
The placeholder syntax makes more sense if you just want to include the exception's message property:
LOGGER.warn("....: {}", e.getMessage());

sophokles73 · 2017-11-20T13:53:09Z

californium-proxy/src/main/java/org/eclipse/californium/proxy/EndPointManagerPool.java

@@ -0,0 +1,80 @@
+/*******************************************************************************
+ * Copyright (c) 2015 Institute for Pervasive Computing, ETH Zurich and others.


same as above ...

sophokles73 · 2017-11-20T14:00:38Z

californium-proxy/src/main/java/org/eclipse/californium/proxy/ProxyHttpServer.java

+					context.handleRequestForwarding(response);
+					LOGGER.info("HTTP returned {}", response);
+				} catch (Exception e) {
+					LOGGER.warn("Exception while responding to Http request {}", e);


either remove placeholder or use e.getMessage()

sophokles73 · 2017-11-20T14:01:08Z

californium-proxy/src/main/java/org/eclipse/californium/proxy/ProxyHttpServer.java

-					LOGGER.warn("Exception while responding to Http request", e);
+					context.handleRequestForwarding(response);
+					LOGGER.info("HTTP returned {}", response);
+				} catch (Exception e) {


please catch specific exceptions only

sophokles73 · 2017-11-20T14:02:39Z

...ium-proxy/src/main/java/org/eclipse/californium/proxy/resources/ProxyCoapClientResource.java

+			LOGGER.debug("Sending proxied CoAP request.");
+
+			if (outgoingRequest.getDestination() == null)
+					throw new NullPointerException("Destination is null");


please add brackets

sophokles73 · 2017-11-20T14:02:48Z

...ium-proxy/src/main/java/org/eclipse/californium/proxy/resources/ProxyCoapClientResource.java

+			if (outgoingRequest.getDestination() == null)
+					throw new NullPointerException("Destination is null");
+			if (outgoingRequest.getDestinationPort() == 0)
+				throw new NullPointerException("Destination port is 0");


please add brackets

sophokles73 · 2017-11-20T14:52:28Z

californium-proxy/pom.xml

@@ -18,6 +18,7 @@

 	<properties>
 		<httpcomponents.version>4.2.5</httpcomponents.version>
+		<httpasyncclient.version>4.1.3</httpasyncclient.version>


in order for this to work properly we should also update http-core etc accordingly. IMHO since the dependency on the async client pulls in everything else needed from HttpComponents, we should remove the explicit dependency on httpcore-nio and also remove the httpcomponents.version property.

vikram919 · 2017-11-20T16:55:43Z

@martinmine
As @sophokles73 mentioned,
This dependency is alone okay, it works now without including it again in cf-proxy pom.xml.


<dependency>
	<groupId>org.apache.httpcomponents</groupId>
	<artifactId>httpasyncclient</artifactId>
	<version>4.1.3</version>
	<scope>compile</scope>
</dependency>

martinmine · 2017-11-20T17:03:24Z

@vikram919 @sophokles73 Thanks for your comments, I will address them shortly.

martinmine · 2017-11-20T18:02:32Z

@sophokles73 Maybe you should add the thing about the copyright headers to the contributors.md file as well? :) Regarding the exceptions, I highly appreciate (as a developer when using Californium) that I get a more appropriate message out rather than just for example "Null pointer exception". A stack trace is soooo much more useful if no other exception is thrown. For future work, I would suggest that you go by the convention of providing the Throwable object to the logger so it can print the stack trace (if any).

vikram919 · 2017-11-21T08:30:55Z

@martinmine
I created a test setup without changing the code just only with the pull request,
Coap client<--<coap2http>-->HTTP local Server - Average 0,236708 milli seconds for a each response
Http client<--<HttpProxy>-->Coap local Server - Average 0,865336 milli seconds

This time I run the tests using a single thread sending 1000 get requets and calculating delay on every response in approx nano time precision with the same machine mentioned above
Thank you for the good work!

sophokles73 · 2017-11-21T09:36:07Z

californium-proxy/pom.xml

-		<httpcomponents.version>4.2.5</httpcomponents.version>
-		<httpcomponents.version.lowerbound>4.2</httpcomponents.version.lowerbound>
-		<httpcomponents.version.upperbound>5</httpcomponents.version.upperbound>
+		<httpasyncclient.version>4.1.3</httpasyncclient.version>


ok, I have done some research regarding already approved CQs for HttpComponents artifacts at Eclipse. It seems that using version 4.1.2 of the async client will induce the least effort regarding dependencies while still being sufficiently up to date. So please change the version to 4.1.2.

we will then need to make a lot of additions to the maven bundle plugin configuration in order to specify the required versions of packages to import. Sadly but truly it seems that the arbitrary HttpComponents artifacts do not contain separate sub-trees of packages which would allow us to use some reasonable wild cards but instead contain a wild mix of complementary packages at all levels of the package hierarchy (sigh). I will take take of that once this PR is integrated, though, so you do not need to bother ...

sophokles73 · 2017-11-21T09:36:50Z

californium-proxy/src/main/java/org/eclipse/californium/compat/CompletableFuture.java

@@ -0,0 +1,56 @@
+/*******************************************************************************
+ * Copyright (c) 2017 NTNU Gjøvik and others.


this looks good 👍

martinmine · 2017-11-21T10:10:36Z

@vikram919 Thanks for your investigation, did you run it without the changes from this PR as well?

vikram919 · 2017-11-21T10:12:25Z

@martinmine yes, I run it without changing anything in the current pull request.

martinmine · 2017-11-21T10:15:00Z

@vikram919 Sorry, if I was unclear. Did you run your benchmark on the head of the branch eclipse:2.0.x so that we know how much of a performance boost this PR gives? According to your results, we only know how it performs with the changes proposed in this PR.

vikram919 · 2017-11-21T10:38:21Z

@martinmine
Sorry for not mentioning these readings earlier!
on head of the branch eclipse:2.0.x
Coap client<--<coap2http>-->HTTP local Server - Average 0,453586 milli seconds for a each response
Http client<--<HttpProxy>-->Coap local Server - Average 1,737686 milli seconds

seems like it is twice the values taken for the current PR

sophokles73

Ok, now we will need to wait for the CQs being approved by the Eclipse IP team. Then I can merge the PR.
Thanks for contributing and your patience :-)

martinmine · 2017-11-21T11:05:55Z

@vikram919 Thats awesome! Thanks a lot for looking into this!
@sophokles73 Great!

sophokles73 · 2017-11-22T05:57:35Z

@martinmine can you please squash your changes into one or two commits, e.g. one adapting the logging and the other implementing the improvements?

martinmine · 2017-11-22T09:00:01Z

@sophokles73 Done. I squashed it into one commit as I had commits between log-related changes that I didn't want to start mess with. Hope this is fine.

sophokles73 · 2017-11-22T11:13:15Z

@martinmine
thanks for squashing, but you should fix the commit message which now contains all messages of the squashed commits including the "signed-off-by" footer. You should at least remove the duplicate footers so that there is only one single "signed-off-by" at the bottom. Maybe you could also arrange the changes in a bullet point list? Or include some excerpts from the excellent description you created for the PR?

This commit improves the performance of californium-proxy. The changes are summarized as follows: - Proper use of log formatting. - Avoid spawning two threads for processing incoming requests. - Outgoing HTTP requests are now using the Apache HttpAsyncClient. - Prevent race conditions where concurrent HTTP requests may use the same Endpoint for CoAP requests where the message body might get inter-mixed with other concurrent messages. This is solved by using a pool of EndpointManagers across requests. Signed-off-by: martinmine <martin_mine@hotmail.com>

martinmine · 2017-11-22T11:45:23Z

@sophokles73 Thanks. Do you think it looks better now?

sophokles73 · 2017-11-22T12:26:42Z

Excellent 👍

vikram919 · 2017-11-24T17:01:28Z

@martinmine
Did you try using observe option over coap2coap proxy?

martinmine · 2017-11-27T10:26:32Z

@vikram919 are you talking about this? https://github.com/martinmine/californium/blob/8c0fbe3cf92d99a3e6e3385471fdd662b41edea7/californium-proxy/src/main/java/org/eclipse/californium/proxy/resources/ProxyCoapClientResource.java#L78 Otherwise, I use the proxy example in the current master.

vikram919 · 2017-11-27T11:51:14Z

@martinmine
I mean,
Have you tested the eclipse/californium with below scenario:
coap client (sends GET request with observe option )-----<coap2coap>------coap server (sending notifications when the resource is changed)

martinmine · 2017-11-27T11:52:47Z

@vikram919 Nope. The goal of my project was to proxy HTTP requests using CoAP, so I have not looked into that.

martinmine · 2017-11-27T11:53:17Z

@vikram919 But thanks, you gave me some ideas for some more things I can discuss in my thesis :)

vikram919 · 2017-11-27T12:53:03Z

@martinmine
some more information,
If the application uses proxy,
Coap server must explicitly define max age option for the response , If the max age option is not defined it will assume the default value MAX_AGE = 60 seconds.
As per RFC 7252, Section 5.6.1:
If an origin server wishes to prevent caching, it MUST explicitly include a Max-Age Option with a value of zero seconds.
I have just now tested the above definition californium coap2coap proxy neglects any notification from server, if received before MAX_AGE option.
Good Luck with your Thesis :-)

martinmine · 2017-11-27T13:21:52Z

@vikram919 I see. One problem might be how we use the endpoint pooling to avoid the race condition I mentioned earlier. If you want to discuss this more, we can take it somewhere else as it goes beyond the scope of this PR (maybe on Twitter or whatever else you can use for IM?)
And thanks!

vikram919 · 2017-11-27T13:52:53Z

@martinmine
We close this here. you found me already,please check your twitter for further discussions

martinmine mentioned this pull request Nov 17, 2017

Performance improvements to Californium-proxy #474

Closed

boaks reviewed Nov 17, 2017

View reviewed changes

martinmine changed the title ~~Proxy optimizations 2.0.x upstream~~ Performance improvements to Californium-proxy Nov 18, 2017

sophokles73 requested changes Nov 20, 2017

View reviewed changes

sophokles73 requested changes Nov 21, 2017

View reviewed changes

sophokles73 approved these changes Nov 21, 2017

View reviewed changes

martinmine mentioned this pull request Nov 22, 2017

Lack of buffer re-use leads to extensive GC and performance degradation #483

Closed

sophokles73 merged commit 9e0bf22 into eclipse-californium:2.0.x Nov 27, 2017

vikram919 mentioned this pull request Nov 29, 2017

Timeout handling #472

Closed

		@@ -0,0 +1,59 @@
		/*******************************************************************************
		* Copyright (c) 2015 Institute for Pervasive Computing, ETH Zurich and others.

		@@ -0,0 +1,32 @@
		/*******************************************************************************
		* Copyright (c) 2015 Institute for Pervasive Computing, ETH Zurich and others.

		@@ -0,0 +1,80 @@
		/*******************************************************************************
		* Copyright (c) 2015 Institute for Pervasive Computing, ETH Zurich and others.

		@@ -0,0 +1,56 @@
		/*******************************************************************************
		* Copyright (c) 2017 NTNU Gjøvik and others.

Performance improvements to Californium-proxy #479

Performance improvements to Californium-proxy #479

Conversation

martinmine commented Nov 17, 2017

martinmine commented Nov 17, 2017

vikram919 commented Nov 17, 2017

Choose a reason for hiding this comment

martinmine Nov 17, 2017 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

boaks commented Nov 17, 2017

martinmine commented Nov 17, 2017

boaks commented Nov 17, 2017

boaks commented Nov 17, 2017

martinmine commented Nov 17, 2017

martinmine commented Nov 17, 2017

vikram919 commented Nov 20, 2017

martinmine commented Nov 20, 2017

martinmine commented Nov 20, 2017

vikram919 commented Nov 20, 2017 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vikram919 commented Nov 20, 2017 • edited

martinmine commented Nov 20, 2017

martinmine commented Nov 20, 2017

vikram919 commented Nov 21, 2017 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

martinmine commented Nov 21, 2017

vikram919 commented Nov 21, 2017

martinmine commented Nov 21, 2017

vikram919 commented Nov 21, 2017 • edited

sophokles73 left a comment • edited

Choose a reason for hiding this comment

martinmine commented Nov 21, 2017

sophokles73 commented Nov 22, 2017

martinmine commented Nov 22, 2017

sophokles73 commented Nov 22, 2017

martinmine commented Nov 22, 2017

sophokles73 commented Nov 22, 2017

vikram919 commented Nov 24, 2017

martinmine commented Nov 27, 2017

vikram919 commented Nov 27, 2017

martinmine commented Nov 27, 2017

martinmine commented Nov 27, 2017

vikram919 commented Nov 27, 2017 • edited

martinmine commented Nov 27, 2017

vikram919 commented Nov 27, 2017 • edited

martinmine Nov 17, 2017 •

edited

vikram919 commented Nov 20, 2017 •

edited

vikram919 commented Nov 20, 2017 •

edited

vikram919 commented Nov 21, 2017 •

edited

vikram919 commented Nov 21, 2017 •

edited

sophokles73 left a comment •

edited

vikram919 commented Nov 27, 2017 •

edited

vikram919 commented Nov 27, 2017 •

edited