AWS Testing

m4.x4large HTTP Polling Baseline

The tests below provide a localhost baseline we can use to check the machine-> machine testing and also give us visibility of the sort of message behaviour we expect. This builds on the HTTP baseline tests which provide a view on the raw HTTP handling.

These tests extend the HTTP by adding the protocol management, Engine-IO layer, batching and queueing behaviour detailed in the user guide.

All the HTTP Polling tests were run using the examples available in the test application. e.g:


$ ./run.sh 1 com.rubris.client.runners.HttpSubscribeMessageRunner 127.0.0.1 8091 
          login 1000 false 1000 timeHandler 100000

For example the above, command line runs 1 instance of 1000 users, with 1000 subscriptions each until they have each received 100,000 messages. The topics for each client are randomly chosen from a total pool of 50,000 topics (an expected average of ~50 clients/topic).

The timehandler sends 1024 byte messages, of which the first 8 bytes are an encoded timestamp. The channel itself uses 2 single-threaded ScheduledExecutors which run a scheduled push for each topic with a 1 ns pause (although in reality as we are trying to do 25,000 publications a second per executor, we are actually sending at a slower slower than the time suggests as the executor attempts to cycle through 25k topics per second).

The client code is operating on a batch of messages, so for each actual batch message received, individual message times are calculated in each individual message callback until the batch is exhausted. The message time on the server is part of the message and added before the message is enqueued.

1k users with 2 modules

The subscribes take about 2 seconds in total

2016-04-10 14:34:23,957 main DEBUG ... started OK.
14:34:24.421 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 100
14:34:24.540 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 200
14:34:24.540 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 100
14:34:24.810 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 100
14:34:24.820 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 200
14:34:24.867 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 300
14:34:24.907 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 400
14:34:24.922 [nioEventLoopGroup-2-10] INFO  HttpMessageLimit - Subscribe complete 100
14:34:24.947 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 200
14:34:24.953 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Clients ready 500
14:34:25.079 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 300
14:34:25.101 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 300
14:34:25.126 [nioEventLoopGroup-2-8] INFO  HttpMessageLimit - Subscribe complete 200
14:34:25.160 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 400
14:34:25.200 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 400
14:34:25.262 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 500
14:34:25.274 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 500
14:34:25.355 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 600
14:34:25.418 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit - Subscribe complete 300
14:34:25.499 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit - Subscribe complete 400
14:34:25.582 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 700
14:34:25.600 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit - Subscribe complete 500
14:34:25.625 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 600
14:34:25.645 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Clients ready 800
14:34:25.676 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Subscribe sent 600
14:34:25.784 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 700
14:34:25.812 [nioEventLoopGroup-2-8] INFO  HttpMessageLimit - Subscribe complete 600
14:34:25.833 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Subscribe sent 700
14:34:25.876 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 900
14:34:25.996 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 800
14:34:26.002 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 800
14:34:26.099 [nioEventLoopGroup-2-2] INFO  HttpMessageLimit - Subscribe complete 700
14:34:26.139 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 1000
14:34:26.207 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 900
14:34:26.237 [nioEventLoopGroup-2-8] INFO  HttpMessageLimit - Subscribe complete 800
14:34:26.260 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 900
14:34:26.344 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit - Subscribe complete 900
14:34:26.366 [nioEventLoopGroup-2-4] INFO  HttpSubscribeOnly - Channels complete 1000
14:34:26.556 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Subscribe sent 1000
14:34:26.640 [nioEventLoopGroup-2-4] INFO  HttpMessageLimit - Subscribe complete 1000

The timings for message receipt below were measured by calculating the difference between the processing time and the timestamps encoded in the message. Obviously this is the time when it has been delivered up from the Netty pipeline to the test code, rather than receipt and there is some drift (which can be significant) as we are dealing with many clients multiplexed on a much smaller number of threads.

Click to enlarge

The network throughput shows the local network throughput (Mb/s)

From the above graph we can see that the sustained throughput was ~ 11Gb/s.

The elapsed time is about 70 seconds and the number of messages/elapsed time results in a rate of:

14:35:35.463 [main] WARN  HttpSubscribeClientRunner - Total ms/sec 1,409,985

Assuming an average batch size of ~ 200k (observed empirically on similar experiments) we can infer that each client is making about ~7 poll requests /sec.

The message rate is very dependent on message size, for example at a similar throughput on say 100 byte messages the message rate would be ~14 million/s.

As this is localhost we should also be mindful of the limitations observed in the HTTP tests.

2k users with 2 modules

In this case the number of total subscriptions is 100,000 (2 pools of 50,000).


$ ./run.sh 2 com.rubris.client.runners.HttpSubscribeMessageRunner 127.0.0.1 8091 
          login 1000 false 1000 timeHandler 100000

As The client connection is mostly synchronous - the 2 client instances startup one after another (as the bash script is a loop) but process the data concurrently.

Client instance 1

The subscribes take about 2.5 seconds in total

2016-04-10 14:40:36,216 main DEBUG ... started OK.
14:40:36.711 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 100
14:40:36.797 [nioEventLoopGroup-2-4] INFO  HttpSubscribeOnly - Channels complete 100
14:40:36.858 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 200
14:40:37.052 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 100
14:40:37.094 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 200
14:40:37.116 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit- Subscribe complete 100
14:40:37.126 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 300
14:40:37.168 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 400
14:40:37.183 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Subscribe sent 200
14:40:37.311 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 300
14:40:37.341 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit- Subscribe complete 200
14:40:37.344 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 300
14:40:37.350 [nioEventLoopGroup-2-4] INFO  HttpSubscribeOnly - Channels complete 400
14:40:37.427 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 400
14:40:37.457 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 500
14:40:37.703 [nioEventLoopGroup-2-10] INFO  HttpMessageLimit- Subscribe complete 300
14:40:37.736 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 600
14:40:37.741 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 500
14:40:37.758 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit- Subscribe complete 400
14:40:37.880 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Subscribe sent 500
14:40:37.881 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 700
14:40:37.984 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 600
14:40:38.002 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit- Subscribe complete 500
14:40:38.085 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 600
14:40:38.096 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 700
14:40:38.202 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Clients ready 800
14:40:38.214 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 700
14:40:38.293 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit- Subscribe complete 600
14:40:38.440 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 800
14:40:38.448 [nioEventLoopGroup-2-4] INFO  HttpMessageLimit- Subscribe complete 700
14:40:38.456 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 900
14:40:38.554 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 800
14:40:38.678 [nioEventLoopGroup-2-8] INFO  HttpMessageLimit- Subscribe complete 800
14:40:38.684 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 900
14:40:38.774 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Clients ready 1000
14:40:38.878 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 900
14:40:38.939 [nioEventLoopGroup-2-10] INFO  HttpMessageLimit- Subscribe complete 900
14:40:39.127 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 1000
14:40:39.359 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 1000
14:40:39.367 [nioEventLoopGroup-2-10] INFO  HttpMessageLimit- Subscribe complete 1000

Click to enlarge

Client instance 2

The subscribes take a little over 3 seconds


2016-04-10 14:40:39,107 main DEBUG ... started OK.
14:40:39.851 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Clients ready 100
14:40:40.030 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 200
14:40:40.068 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 100
14:40:40.262 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 300
14:40:40.851 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 200
14:40:40.866 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 100
14:40:40.880 [nioEventLoopGroup-2-4] INFO  HttpMessageLimit - Subscribe complete 100
14:40:40.947 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 400
14:40:41.091 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 300
14:40:41.109 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Clients ready 501
14:40:41.232 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 600
14:40:41.238 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 700
14:40:41.239 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 200
14:40:41.243 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 800
14:40:41.253 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 900
14:40:41.305 [nioEventLoopGroup-2-10] INFO  HttpMessageLimit - Subscribe complete 200
14:40:41.333 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 400
14:40:41.423 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 1000
14:40:41.436 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Subscribe sent 300
14:40:41.477 [nioEventLoopGroup-2-8] INFO  HttpMessageLimit - Subscribe complete 300
14:40:41.483 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 500
14:40:41.550 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 600
14:40:41.621 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 700
14:40:41.710 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 400
14:40:41.711 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 800
14:40:41.728 [nioEventLoopGroup-2-4] INFO  HttpSubscribeOnly - Channels complete 900
14:40:41.768 [nioEventLoopGroup-2-4] INFO  HttpMessageLimit - Subscribe complete 400
14:40:41.837 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 1000
14:40:41.872 [nioEventLoopGroup-2-2] INFO  HttpMessageLimit - Subscribe complete 500
14:40:41.883 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Subscribe sent 500
14:40:41.969 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Subscribe sent 600
14:40:42.071 [nioEventLoopGroup-2-2] INFO  HttpMessageLimit - Subscribe complete 600
14:40:42.075 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 700
14:40:42.116 [nioEventLoopGroup-2-2] INFO  HttpMessageLimit - Subscribe complete 700
14:40:42.190 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 800
14:40:42.199 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit - Subscribe complete 800
14:40:42.284 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 900
14:40:42.290 [nioEventLoopGroup-2-10] INFO  HttpMessageLimit - Subscribe complete 900
14:40:42.451 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 1000
14:40:42.497 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit - Subscribe complete 1000

Click to enlarge

Overall Network throughput

Total Elapsed Time

Total elapsed time is 160 seconds or so.

Client instance 1
14:43:11.020 [main] WARN HttpSubscribeClientRunner - Total ms/sec 650,062
Client instance 2
14:43:12.220 [main] WARN HttpSubscribeClientRunner - Total ms/sec 658,553

Gives us a total average throughput of ~ 1.3 million messages/sec

Total throughput has declined compared to 1000 users suggesting that we have reached the push limit of the 2 executors and 2 modules.

2k Users with 4 modules

In this experiment we increase the module count (same executor count), to examine if the limit is the module event thread. In this case the number of total subscriptions is 100,000 (2 pools of 50,000).


$ ./run.sh 2 com.rubris.client.runners.HttpSubscribeMessageRunner 127.0.0.1 8091 
          login 1000 false 1000 timeHandler 100000

Client 1 instance

Subscribes took ~ 4.5 seconds

2016-04-10 15:02:06,891 main DEBUG ... started OK
15:02:07.464 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 100
15:02:07.615 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 100
15:02:07.679 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 200
15:02:07.886 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 300
15:02:07.892 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Subscribe sent 100
15:02:07.947 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 200
15:02:07.985 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 400
15:02:08.047 [nioEventLoopGroup-2-4] INFO  HttpSubscribeOnly - Channels complete 300
15:02:08.054 [nioEventLoopGroup-2-8] INFO   HttpMessageLimit - Subscribe complete 100
15:02:08.114 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 500
15:02:08.130 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 200
15:02:08.197 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 401
15:02:08.242 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 300
15:02:08.262 [nioEventLoopGroup-2-2] INFO   HttpMessageLimit - Subscribe complete 200
15:02:08.274 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 600
15:02:08.327 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 500
15:02:08.328 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 400
15:02:08.409 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 700
15:02:08.443 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Subscribe sent 500
15:02:08.515 [nioEventLoopGroup-2-4] INFO   HttpMessageLimit - Subscribe complete 300
15:02:08.763 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 600
15:02:08.768 [nioEventLoopGroup-2-8] INFO   HttpMessageLimit - Subscribe complete 400
15:02:08.785 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 600
15:02:08.829 [nioEventLoopGroup-2-4] INFO  HttpSubscribeOnly - Channels complete 700
15:02:08.958 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Subscribe sent 700
15:02:08.986 [nioEventLoopGroup-2-4] INFO   HttpMessageLimit - Subscribe complete 500
15:02:08.991 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 800
15:02:09.161 [nioEventLoopGroup-2-6] INFO   HttpMessageLimit - Subscribe complete 600
15:02:09.482 [nioEventLoopGroup-2-4] INFO   HttpMessageLimit - Subscribe complete 700
15:02:09.487 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 800
15:02:09.492 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 900
15:02:09.547 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 800
15:02:09.726 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Clients ready 1000
15:02:09.812 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 900
15:02:09.832 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 900
15:02:09.900 [nioEventLoopGroup-2-8] INFO   HttpMessageLimit - Subscribe complete 800
15:02:10.354 [nioEventLoopGroup-2-10] INFO   HttpMessageLimit - Subscribe complete 900
15:02:10.359 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 1000
15:02:10.383 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 1000
15:02:11.053 [nioEventLoopGroup-2-10] INFO  HttpMessageLimit - Subscribe complete 1000

Click to enlarge

Client 2 instance

Subscribe took ~5.5 seconds

2016-04-10 15:02:10,499 main DEBUG  started OK.
15:02:11.668 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 100
15:02:12.386 [nioEventLoopGroup-2-4] INFO  HttpSubscribeOnly - Channels complete 100
15:02:12.400 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Clients ready 200
15:02:12.460 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 300
15:02:12.529 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 400
15:02:12.596 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 500
15:02:12.654 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 200
15:02:12.662 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 100
15:02:12.747 [nioEventLoopGroup-2-8] INFO   HttpMessageLimit - Subscribe complete 100
15:02:12.776 [nioEventLoopGroup-2-4] INFO  HttpSubscribeOnly - Channels complete 300
15:02:12.795 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 400
15:02:12.796 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 600
15:02:12.860 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 500
15:02:13.040 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 200
15:02:13.049 [nioEventLoopGroup-2-2] INFO   HttpMessageLimit - Subscribe complete 200
15:02:13.101 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 300
15:02:13.172 [nioEventLoopGroup-2-6] INFO   HttpMessageLimit - Subscribe complete 300
15:02:13.175 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 400
15:02:13.216 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 600
15:02:13.332 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 700
15:02:13.351 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 500
15:02:13.413 [nioEventLoopGroup-2-6] INFO   HttpMessageLimit - Subscribe complete 400
15:02:13.422 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 800
15:02:13.455 [nioEventLoopGroup-2-2] INFO   HttpMessageLimit - Subscribe complete 500
15:02:13.553 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 600
15:02:13.697 [nioEventLoopGroup-2-10] INFO   HttpMessageLimit - Subscribe complete 600
15:02:13.742 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 700
15:02:13.858 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 900
15:02:13.880 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 800
15:02:14.085 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 700
15:02:14.194 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 800
15:02:14.441 [nioEventLoopGroup-2-4] INFO   HttpMessageLimit - Subscribe complete 700
15:02:14.444 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 1000
15:02:14.480 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 900
15:02:14.630 [nioEventLoopGroup-2-8] INFO   HttpMessageLimit - Subscribe complete 800
15:02:14.732 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 900
15:02:15.017 [nioEventLoopGroup-2-8] INFO   HttpMessageLimit - Subscribe complete 900
15:02:15.035 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 1000
15:02:15.296 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Subscribe sent 1000
15:02:15.918 [nioEventLoopGroup-2-10] INFO  HttpMessageLimit - Subscribe complete 1000

Click to enlarge

Network throughput

Click to enlarge

We can see that the throughput is slightly more varied that with 2 modules but sustains at ~ 16Gb/s.

CPU Usage

The CPU usage shows that we are pretty much maxing the box at just < 1600% CPU.

Assuming 2 CPUs for the topic push we can see that each module is consuming 2 CPUs as we would expect (one read and one write thread) indicating we are getting steady usage of the IO threads.

 16419  27.4g 6.7g 5.0g S 1070.6 10.6   7:37.15 java 
 16704  20.5g 5.3g  20m S 262.3  8.5   1:50.78 java  
 16632  20.5g 5.3g  20m S 258.0  8.5   2:02.58 java  
 16419  27.4g 6.7g 5.0g S 1066.0 10.6   8:09.18 java 
 16704  20.5g 5.3g  20m S 263.2  8.5   1:58.69 java  
 16632  20.5g 5.3g  20m S 262.2  8.4   2:10.46 java  
 16419  27.4g 6.7g 5.0g S 1094.6 10.6   8:42.10 java 
 16632  20.5g 5.2g  20m S 248.7  8.3   2:17.94 java  
 16704  20.5g 5.4g  20m S 246.7  8.5   2:06.11 java  
 16419  27.4g 6.7g 5.0g S 1065.3 10.6   9:14.11 java 
 16632  20.5g 5.2g  20m S 263.6  8.3   2:25.86 java  
 16704  20.5g 5.4g  20m S 261.6  8.5   2:13.97 java  
 16419  27.4g 6.7g 5.0g S 1079.7 10.6   9:46.58 java 
 16704  20.5g 5.3g  20m S 255.7  8.5   2:21.66 java  
 16632  20.5g 5.2g  20m S 252.7  8.3   2:33.46 java  
 16419  27.4g 6.7g 5.0g S 1067.4 10.6  10:18.65 java 
 16704  20.5g 5.3g  20m S 266.6  8.5   2:29.67 java  
 16632  20.5g 5.4g  20m S 260.3  8.6   2:41.28 java  
 16419  27.4g 6.7g 5.0g S 1076.4 10.6  10:51.02 java 
 16704  20.5g 5.3g  20m S 256.7  8.4   2:37.39 java  
 16632  20.5g 5.4g  20m S 254.7  8.7   2:48.94 java  
 16419  27.4g 6.7g 5.0g S 1094.3 10.6  11:23.90 java 
 16704  20.5g 5.4g  20m S 249.3  8.6   2:44.88 java  
 16632  20.5g 5.5g  20m S 246.0  8.7   2:56.33 java  
 16419  27.4g 6.7g 5.0g S 1092.8 10.6  11:56.77 java 
 16704  20.5g 5.4g  20m S 250.0  8.6   2:52.40 java  
 16632  20.5g 5.4g  20m S 248.7  8.7   3:03.81 java  
 16419  27.4g 6.7g 5.0g S 1076.0 10.6  12:29.13 java 
 16704  20.5g 5.4g  20m S 258.4  8.6   3:00.17 java  
 16632  20.5g 5.4g  20m S 256.7  8.6   3:11.53 java  
 16419  27.4g 6.7g 5.0g S 1085.4 10.6  13:01.74 java 
 16704  20.5g 5.4g  20m S 252.3  8.6   3:07.75 java  
 16632  20.5g 5.4g  20m S 250.6  8.6   3:19.06 java  
 16419  27.4g 6.7g 5.0g S 1079.5 10.6  13:34.21 java 
 16704  20.5g 5.4g  20m S 257.0  8.6   3:15.48 java  
 16632  20.5g 5.4g  20m S 252.7  8.6   3:26.66 java

Total Elapsed Time

Total lapsed time is just under 110 seconds.

Client instance 1
15:04:01.764 [main] WARN HttpSubscribeClientRunner - Total ms/sec 878174
Client instance 2
15:04:02.636 [main] WARN HttpSubscribeClientRunner - Total ms/sec 901776

Gives us a total average throughput of ~ 1.8 million messages/s

We do not have linear scaling here so further investigation is required to investigate where the bottleneck is occurring.

c3.x8 large Polling

In order to examine the restriction of the CPU we bump the instance to a c3.x8large to increase the cpu count. The clients were also started in individual shells rather than in the script loop.

2k Users with 4 modules

Client 1 instance

Subscribes took ~ 3 sec

2016-08-31 08:56:57,518 main DEBUG  started OK.
08:56:57.966 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 101
08:56:57.998 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 100
08:56:58.152 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Subscribe sent 100
08:56:58.163 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 200
08:56:58.224 [nioEventLoopGroup-2-2] INFO  HttpMessageLimit - Subscribe complete 100
08:56:58.314 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 200
08:56:58.318 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Clients ready 300
08:56:58.324 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 200
08:56:58.430 [nioEventLoopGroup-2-8] INFO  HttpMessageLimit - Subscribe complete 200
08:56:58.483 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 300
08:56:58.486 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Subscribe sent 300
08:56:58.496 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 400
08:56:58.594 [nioEventLoopGroup-2-8] INFO  HttpMessageLimit - Subscribe complete 300
08:56:58.662 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 400
08:56:58.677 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Clients ready 500
08:56:58.715 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 400
08:56:58.786 [nioEventLoopGroup-2-2] INFO  HttpMessageLimit - Subscribe complete 400
08:56:58.807 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 600
08:56:58.867 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 500
08:56:58.875 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Subscribe sent 500
08:56:59.210 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 700
08:56:59.232 [nioEventLoopGroup-2-4] INFO  HttpMessageLimit - Subscribe complete 500
08:56:59.239 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 600
08:56:59.264 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 600
08:56:59.319 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 800
08:56:59.420 [nioEventLoopGroup-2-4] INFO  HttpMessageLimit - Subscribe complete 600
08:56:59.448 [nioEventLoopGroup-2-4] INFO  HttpSubscribeOnly - Channels complete 700
08:56:59.476 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 700
08:56:59.493 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Clients ready 900
08:56:59.572 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 800
08:56:59.583 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Subscribe sent 800
08:56:59.656 [nioEventLoopGroup-2-4] INFO  HttpMessageLimit - Subscribe complete 700
08:56:59.685 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 1000
08:56:59.761 [nioEventLoopGroup-2-4] INFO  HttpSubscribeOnly - Channels complete 900
08:56:59.766 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Subscribe sent 900
08:56:59.787 [nioEventLoopGroup-2-8] INFO  HttpMessageLimit - Subscribe complete 800
08:56:59.999 [nioEventLoopGroup-2-10] INFO  HttpMessageLimit - Subscribe complete 900
08:57:00.042 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 1000
08:57:00.074 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 1000
08:57:00.457 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit - Subscribe complete 1000

Click to enlarge Click to enlarge

Client 2 instance

Subscribes took ~ 3 sec

2016-08-31 09:02:59,370 main DEBUG started OK.
09:02:59.826 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 100
09:02:59.938 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 100
09:03:00.003 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Clients ready 200
09:03:00.048 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Subscribe sent 103
09:03:00.162 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 200
09:03:00.164 [nioEventLoopGroup-2-4] INFO  HttpMessageLimit - Subscribe complete 100
09:03:00.206 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 200
09:03:00.227 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 300
09:03:00.386 [nioEventLoopGroup-2-8] INFO  HttpMessageLimit - Subscribe complete 200
09:03:00.450 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 300
09:03:00.456 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 300
09:03:00.541 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Clients ready 400
09:03:00.605 [nioEventLoopGroup-2-2] INFO  HttpMessageLimit - Subscribe complete 300
09:03:00.721 [nioEventLoopGroup-2-4] INFO  HttpSubscribeOnly - Channels complete 400
09:03:00.734 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Subscribe sent 400
09:03:00.772 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Clients ready 500
09:03:00.914 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 600
09:03:00.962 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit - Subscribe complete 400
09:03:00.988 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 500
09:03:01.006 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 500
09:03:01.428 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 700
09:03:01.500 [nioEventLoopGroup-2-2] INFO  HttpSubscribeOnly - Channels complete 600
09:03:01.504 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Subscribe sent 600
09:03:01.505 [nioEventLoopGroup-2-6] INFO  HttpMessageLimit - Subscribe complete 500
09:03:01.547 [nioEventLoopGroup-2-3] INFO  HttpSubscribeOnly - Clients ready 800
09:03:01.673 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 900
09:03:01.742 [nioEventLoopGroup-2-2] INFO  HttpMessageLimit - Subscribe complete 600
09:03:01.747 [nioEventLoopGroup-2-4] INFO  HttpSubscribeOnly - Channels complete 700
09:03:01.768 [nioEventLoopGroup-2-5] INFO  HttpSubscribeOnly - Subscribe sent 700
09:03:01.889 [nioEventLoopGroup-2-6] INFO  HttpSubscribeOnly - Channels complete 800
09:03:01.935 [nioEventLoopGroup-2-9] INFO  HttpSubscribeOnly - Subscribe sent 800
09:03:01.976 [nioEventLoopGroup-2-1] INFO  HttpSubscribeOnly - Clients ready 1000
09:03:02.022 [nioEventLoopGroup-2-4] INFO  HttpMessageLimit - Subscribe complete 700
09:03:02.024 [nioEventLoopGroup-2-10] INFO  HttpSubscribeOnly - Channels complete 900
09:03:02.050 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 900
09:03:02.287 [nioEventLoopGroup-2-2] INFO  HttpMessageLimit - Subscribe complete 800
09:03:02.329 [nioEventLoopGroup-2-8] INFO  HttpSubscribeOnly - Channels complete 1000
09:03:02.332 [nioEventLoopGroup-2-7] INFO  HttpSubscribeOnly - Subscribe sent 1000
09:03:02.336 [nioEventLoopGroup-2-2] INFO  HttpMessageLimit - Subscribe complete 900
09:03:02.889 [nioEventLoopGroup-2-10] INFO  HttpMessageLimit - Subscribe complete 1000

Click to enlarge

Network Throughput

Click to enlarge

The network throughput is much flatter at a more constant ~16.5Mb/s than on the m4.x4large machines and we can see this in the fact that cpu is no longer bounding behaviour.

CPU Usage

9867 ec2-user  20   0 27.2g 6.6g 5.0g S 1225.9 11.2   2:29.41 java            
 10202 ec2-user  20   0 20.3g 1.7g  20m S 347.6  2.9   0:40.28 java             
 10113 ec2-user  20   0 20.3g 3.2g  20m S 326.4  5.5   0:52.21 java             
  9474 ec2-user  20   0 20.3g 3.2g  20m S  0.0  5.4   0:44.50 java              
  9867 ec2-user  20   0 27.2g 6.6g 5.0g S 1223.2 11.2   3:06.25 java            
 10113 ec2-user  20   0 20.3g 3.5g  20m S 322.4  5.9   1:01.92 java             
 10202 ec2-user  20   0 20.3g 1.9g  20m S 321.7  3.2   0:49.97 java             
  9474 ec2-user  20   0 20.3g 3.2g  20m S  0.0  5.4   0:44.50 java

And the overall message counts:

Client instance 1
08:58:42.614 [main] WARN  HttpSubscribeClientRunner - Total ms/sec 981383
Client instance 2
08:58:41.808 [main] WARN  HttpSubscribeClientRunner - Total ms/sec 971986

Gives us a total average throughput of just under 2 million messages/s (about 10% improvement)

The average 99.9 and max message time has also reduced by about 10%, with nearly all < 700ms.

It is worth noting here that the longest message times are nearly all in the early message counts, indicating strongly that the concurrent subscribes for 2000 users (in blocks of 1000) are slowing the delivery more than would be expected. We can see this in the graph for the client where the max time drops to <600ms for a proportion of the clientids that were able to perform subscribes with less contention. This is more visible in the WS case as the poll does mask the behaviour somewhat.

There is perhaps some improvement we can make here, but in reality 2000 users setting up 2,000,000 subscriptions (over a pool of 100,000 total topics) is going to cause jitter in trying to process messages on those topics at the same time.

We could rerun the experiments and discount the subscribe jitter, but it is better to demonstrate these effects that may occur at points such as large client number failovers.