Prototyping
Prototype was done for echo service. I means that generated code usually produced by Distributeme generator now created manually.
URL: http://svn.anotheria.net/services/distributeme-json-prototype
Following libraries were used for prototype:
- Jetty as embedded HTTP server
- Java-json-prc as json serialization and RPC call
Communication sample:
Request:
{"jsonrpc": "2.0", "method": "echo", "params": \[42\], "id": 1}"
Response:
{"id":"1","result":20,"jsonrpc":"2.0"}
How to use:
Manually generated client and server
1. Run org.distributeme.business.service.echo.EchoServer as standalone
Server log output:
log4j:WARN No appenders could be found for logger (net.anotheria.anoprise.metafactory.ConfigurableResolver). log4j:WARN Please initialize the log4j system properly. log4j:WARN See [http://logging.apache.org/log4j/1.2/faq.html#noconfig] for more info. 2011-02-07 11:19:18.878:INFO::Logging to STDERR via org.mortbay.log.StdErrLog 2011-02-07 11:19:19.563:INFO::jetty-6.1.26 Server org_distributeme_business_business_service_echo_EchoService is up and ready. 2011-02-07 11:19:19.608:INFO::Started SocketConnector@0.0.0.0:9350
2. Run org.distributeme.business.service.echo.EchoClient as standalone
Server log output:
Server org_distributeme_business_business_service_echo_EchoService is up and ready. 2011-02-07 11:19:19.608:INFO::Started SocketConnector@0.0.0.0:9350 Incoming call: 20 Incoming call: 41 Incoming call: 63 Incoming call: 0
Auto-generated client and server
1. Annotate target service using JSONRPC protocol:
@DistributeMe(
protocols = {ServiceDescriptor.Protocol.JSONRPC, ServiceDescriptor.Protocol.RMI}
)
public interface EchoService extends Service {
2. Run org.distributeme.business.service.echo.jsonrpc.generated.EchoServer as standlone:
log4j:WARN No appenders could be found for logger (org.configureme.repository.Attribute). log4j:WARN Please initialize the log4j system properly. log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info. 2011-02-12 21:29:14.949:INFO::Logging to STDERR via org.mortbay.log.StdErrLog 2011-02-12 21:29:14.997:INFO::jetty-6.1.26 Server org_distributeme_business_service_echo_EchoService is up and ready. 2011-02-12 21:29:15.046:INFO::Started SocketConnector@0.0.0.0:9350
3. Run org.distributeme.business.service.echo.EchoClient as standalone,
check that Remote generated factory registered and service instanse received from MetaFactory:
addRemoteFactory(EchoService.class,
"org.distributeme.business.service.echo.jsonrpc.generated.ClientEchoServiceFactory");
EchoService echoServiceGen = MetaFactory.get(EchoService.class, Extension.REMOTE);
Server log output:
Server org_distributeme_business_business_service_echo_EchoService is up and ready.
2011-02-07 11:19:19.608:INFO::Started SocketConnector@0.0.0.0:9350
Incoming call: 20
Incoming call: 41
Incoming call: 63
A{a='30'}
Client log:
2011-02-12 21:34:50.153:INFO::Logging to STDERR via org.mortbay.log.StdErrLog
20
A{a='89'}
SpeedTester results using JSON-RPC service
- Start the server with
. You will see some debug output:
./startServer.sh
Once you've seen last line, the server is ready (usually in the same second you started it).log4j:WARN No appenders could be found for logger (org.configureme.repository.Attribute). log4j:WARN Please initialize the log4j system properly. log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info. 2011-02-20 18:57:55.636:INFO::Logging to STDERR via org.mortbay.log.StdErrLog 2011-02-20 18:57:55.670:INFO::jetty-6.1.x 2011-02-20 18:57:55.698:INFO::Started SocketConnector@0.0.0.0:9351 Server org_distributeme_speedtester_TestingService is up and ready. First call called Last call called, duration between first and last call 224410 ms. First call called Last call called, duration between first and last call 696343 ms.
- Open another terminal window, and change into the same directory (speedtester).
- Now start the client:
. You will see something like this (output from my MBP):
./startRemoteClient.sh
Testing with rmi://org_distributeme_speedtester_TestingService.xxx@localhost:9249 Testing instance of org.distributeme.speedtester.jsonrpc.generated.ClientTestingServiceImpl@13aaa14a log4j:WARN No appenders could be found for logger (org.configureme.repository.Attribute). log4j:WARN Please initialize the log4j system properly. log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info. 2011-02-20 18:58:45.190:INFO::Logging to STDERR via org.mortbay.log.StdErrLog connection established Testing echo calls 1 - echo calls, Performed 1000 in 2053, 2.053 ms per call - LOUSY Testing inbound packets, size 1000 2 - inbound packets with size 1000, Performed 1000 in 2391, 2.391 ms per call - LOUSY Testing inbound packets, size 10000 3 - inbound packets with size 10000, Performed 1000 in 9162, 9.162 ms per call - DEAD HORSE Testing inbound packets, size 50000 4 - inbound packets with size 50000, Performed 1000 in 41478, 41.478 ms per call - DEAD HORSE Testing outbound packets, size 1000 5 - outbound packets with size 1000, Performed 1000 in 3021, 3.021 ms per call - LOUSY Testing outbound packets, size 10000 2011-02-20 18:59:45.202:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@f4d5bc9 JVM BUG(s) - injecting delay6 times 2011-02-20 18:59:45.202:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@f4d5bc9 JVM BUG(s) - recreating selector 6 times, canceled keys 170 times 6 - outbound packets with size 10000, Performed 1000 in 16194, 16.194 ms per call - DEAD HORSE Testing outbound packets, size 50000 2011-02-20 19:00:45.230:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@f4d5bc9 JVM BUG(s) - injecting delay59 times 2011-02-20 19:00:45.230:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@f4d5bc9 JVM BUG(s) - recreating selector 59 times, canceled keys 944 times 7 - outbound packets with size 50000, Performed 1000 in 53409, 53.409 ms per call - DEAD HORSE Testing in and out bound packets, size 1000 8 - in-and-out bound packets with size 1000, Performed 1000 in 4419, 4.419 ms per call - LOUSY Testing in and out bound packets, size 10000 9 - in-and-out bound packets with size 10000, Performed 1000 in 18812, 18.812 ms per call - DEAD HORSE Testing in and out bound packets, size 50000 2011-02-20 19:01:45.232:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@f4d5bc9 JVM BUG(s) - injecting delay58 times 2011-02-20 19:01:45.233:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@f4d5bc9 JVM BUG(s) - recreating selector 58 times, canceled keys 928 times 10 - in-and-out bound packets with size 50000, Performed 1000 in 73419, 73.419 ms per call - DEAD HORSE ========================== Finished Test In 224888 ServerSide: 224410 ========================== 1 - echo calls, Performed 1000 in 2053, 2.053 ms per call - LOUSY 2 - inbound packets with size 1000, Performed 1000 in 2391, 2.391 ms per call - LOUSY 3 - inbound packets with size 10000, Performed 1000 in 9162, 9.162 ms per call - DEAD HORSE 4 - inbound packets with size 50000, Performed 1000 in 41478, 41.478 ms per call - DEAD HORSE 5 - outbound packets with size 1000, Performed 1000 in 3021, 3.021 ms per call - LOUSY 6 - outbound packets with size 10000, Performed 1000 in 16194, 16.194 ms per call - DEAD HORSE 7 - outbound packets with size 50000, Performed 1000 in 53409, 53.409 ms per call - DEAD HORSE 8 - in-and-out bound packets with size 1000, Performed 1000 in 4419, 4.419 ms per call - LOUSY 9 - in-and-out bound packets with size 10000, Performed 1000 in 18812, 18.812 ms per call - DEAD HORSE 10 - in-and-out bound packets with size 50000, Performed 1000 in 73419, 73.419 ms per call - DEAD HORSE - Congrats you just executed your first speed test, with one thread. Now proceed with multithreaded test.
- Start multithreaded test:
and watch the output:
./startMultiThreadedRemoteClient.sh
2011-02-20 19:25:16.442:INFO::Logging to STDERR via org.mortbay.log.StdErrLog connection established -- testing echo calls with 10 threads 1 - echo calls, Performed 10000 in 6164, 0.6164 ms per call - ACCEPTABLE -- testing inbound packets with size 1000 with 10 threads 2 - inbound packets with size 1000, Performed 10000 in 27513, 2.7513 ms per call - LOUSY -- testing inbound packets with size 10000 with 10 threads 2011-02-20 19:26:16.499:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - injecting delay59 times 2011-02-20 19:26:16.499:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - recreating selector 59 times, canceled keys 340 times 3 - inbound packets with size 10000, Performed 10000 in 36781, 3.6781 ms per call - LOUSY -- testing inbound packets with size 50000 with 10 threads 2011-02-20 19:27:16.504:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - injecting delay10 times 2011-02-20 19:27:16.504:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - recreating selector 10 times, canceled keys 103 times 4 - inbound packets with size 50000, Performed 10000 in 156572, 15.6572 ms per call - DEAD HORSE -- testing outbound packets with size 1000 with 10 threads 2011-02-20 19:29:16.516:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - injecting delay13 times 2011-02-20 19:29:16.516:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - recreating selector 13 times, canceled keys 216 times 5 - outbound packets with size 1000, Performed 10000 in 19231, 1.9231 ms per call - LOUSY -- testing outbound packets with size 10000 with 10 threads 2011-02-20 19:30:16.524:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - injecting delay58 times 2011-02-20 19:30:16.524:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - recreating selector 58 times, canceled keys 833 times 6 - outbound packets with size 10000, Performed 10000 in 64298, 6.4298 ms per call - DEAD HORSE -- testing outbound packets with size 50000 with 10 threads 2011-02-20 19:31:16.525:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - injecting delay58 times 2011-02-20 19:31:16.525:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - recreating selector 58 times, canceled keys 908 times 7 - outbound packets with size 50000, Performed 10000 in 96312, 9.6312 ms per call - DEAD HORSE -- testing in-and-out bound packets with size 1000 with 10 threads 2011-02-20 19:32:16.560:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - injecting delay59 times 2011-02-20 19:32:16.560:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - recreating selector 59 times, canceled keys 881 times 8 - in-and-out bound packets with size 1000, Performed 10000 in 33398, 3.3398 ms per call - LOUSY -- testing in-and-out bound packets with size 10000 with 10 threads 2011-02-20 19:33:16.562:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - injecting delay58 times 2011-02-20 19:33:16.562:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - recreating selector 58 times, canceled keys 783 times 9 - in-and-out bound packets with size 10000, Performed 10000 in 76222, 7.6222 ms per call - DEAD HORSE -- testing in-and-out bound packets with size 50000 with 10 threads 2011-02-20 19:34:16.609:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - injecting delay59 times 2011-02-20 19:34:16.609:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - recreating selector 59 times, canceled keys 906 times 2011-02-20 19:35:16.658:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - injecting delay59 times 2011-02-20 19:35:16.658:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - recreating selector 59 times, canceled keys 933 times 2011-02-20 19:36:16.662:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - injecting delay58 times 2011-02-20 19:36:16.662:INFO::org.mortbay.io.nio.SelectorManager$SelectSet@5e3ca754 JVM BUG(s) - recreating selector 58 times, canceled keys 913 times 10 - in-and-out bound packets with size 50000, Performed 10000 in 179793, 17.9793 ms per call - DEAD HORSE ========================== Finished Test In 696633 ServerSide: 696343 with 10 ========================== 1 - echo calls, Performed 10000 in 6164, 0.6164 ms per call - ACCEPTABLE 2 - inbound packets with size 1000, Performed 10000 in 27513, 2.7513 ms per call - LOUSY 3 - inbound packets with size 10000, Performed 10000 in 36781, 3.6781 ms per call - LOUSY 4 - inbound packets with size 50000, Performed 10000 in 156572, 15.6572 ms per call - DEAD HORSE 5 - outbound packets with size 1000, Performed 10000 in 19231, 1.9231 ms per call - LOUSY 6 - outbound packets with size 10000, Performed 10000 in 64298, 6.4298 ms per call - DEAD HORSE 7 - outbound packets with size 50000, Performed 10000 in 96312, 9.6312 ms per call - DEAD HORSE 8 - in-and-out bound packets with size 1000, Performed 10000 in 33398, 3.3398 ms per call - LOUSY 9 - in-and-out bound packets with size 10000, Performed 10000 in 76222, 7.6222 ms per call - DEAD HORSE 10 - in-and-out bound packets with size 50000, Performed 10000 in 179793, 17.9793 ms per call - DEAD HORSE