[erlang-questions] Time to client > time to server?! Is my testing flawed? Please help me explain my results!

[Joel Reymont]

Here's a more revealing set of latency measurements.

I'm now tracking the maximum time to client and time to server.

Note the peak latency of over 8 seconds in a distributed scenario.

--- Single VM ---

(1@REDACTED)4> dmb:test(500).
gateway:start('1@REDACTED', 4000, 500000)
Waiting for game servers...
Starting a port server on 4000...
Simulating gameplay with 500 games...
50 games started, 262 players
100 games started, 504 players
150 games started, 743 players
200 games started, 1019 players
250 games started, 1288 players
300 games started, 1529 players
350 games started, 1766 players
400 games started, 2057 players
450 games started, 2304 players
500 games started, 2562 players
dmb: 500 games launching simultaneously
dmb: waiting for games to end...

=INFO REPORT==== 6-Oct-2008::09:03:52 ===
     module: stats
     elapsed: 10.000245
     {time_to_client,max}: 4.32
     {time_to_server,max}: 2.841
     {time_to_client,avg}: 0.2320246180635134
     {time_to_server,avg}: 0.22264713927830931
     bytes: 146366
     packets: 8186
     {bytes,per_sec}: 14636
     {packets,per_sec}: 818

=INFO REPORT==== 6-Oct-2008::09:04:02 ===
     module: stats
     elapsed: 10.001825
     {time_to_client,max}: 11.05
     {time_to_server,max}: 411.33
     {time_to_client,avg}: 1.5062184064818505
     {time_to_server,avg}: 0.7171950578502572
     bytes: 448415
     packets: 18778
     {bytes,per_sec}: 44833
     {packets,per_sec}: 1877

=INFO REPORT==== 6-Oct-2008::09:04:12 ===
     module: stats
     elapsed: 9.998174
     {time_to_client,max}: 12.69
     {time_to_server,max}: 418.076
     {time_to_client,avg}: 0.4114940672586087
     {time_to_server,avg}: 289.4916230003739
     bytes: 152103
     packets: 6370
     {bytes,per_sec}: 15213
     {packets,per_sec}: 637

=INFO REPORT==== 6-Oct-2008::09:04:22 ===
     module: stats
     elapsed: 10.120701
     {time_to_client,max}: 13.341
     {time_to_server,max}: 49.669
     {time_to_client,avg}: 5.355944891472721
     {time_to_server,avg}: 5.743951365303288
     bytes: 41369
     packets: 1670
     {bytes,per_sec}: 4087
     {packets,per_sec}: 165
50 games finished
100 games finished
150 games finished

=INFO REPORT==== 6-Oct-2008::09:04:32 ===
     module: stats
     elapsed: 9.963557
     {time_to_client,max}: 10.079
     {time_to_server,max}: 83.54
     {time_to_client,avg}: 7.568428330186793
     {time_to_server,avg}: 47.86868493253832
     bytes: 23612
     packets: 951
     {bytes,per_sec}: 2369
     {packets,per_sec}: 95
200 games finished
...
450 games finished

=INFO REPORT==== 6-Oct-2008::09:04:42 ===
     module: stats
     elapsed: 9.924854
     {time_to_client,max}: 25.995
     {time_to_server,max}: 228.509
     {time_to_client,avg}: 12.582011113358574
     {time_to_server,avg}: 63.03305165784938
     bytes: 56429
     packets: 2277
     {bytes,per_sec}: 5685
     {packets,per_sec}: 229
500 games finished
dmb: exited successfully, 58.173462 seconds elapsed
ok
(1@REDACTED)5>
=INFO REPORT==== 6-Oct-2008::09:04:52 ===
     module: stats
     elapsed: 9.990864
     {time_to_client,max}: 242.641
     {time_to_server,max}: 2591.385
     {time_to_client,avg}: 1.396611881112888
     {time_to_server,avg}: 4.433587847758173
     bytes: 3924494
     packets: 164982
     {bytes,per_sec}: 392808
     {packets,per_sec}: 16513

--- Distributed over 3 VMs ---

(1@REDACTED)2> dmb:test(500).
gateway:start('1@REDACTED', 4000, 500000)
Waiting for game servers...
Starting a port server on 4000...
Simulating gameplay with 500 games...
50 games started, 262 players
100 games started, 504 players
150 games started, 743 players
200 games started, 1019 players
250 games started, 1288 players
300 games started, 1529 players
350 games started, 1766 players
400 games started, 2057 players
450 games started, 2304 players
500 games started, 2562 players
dmb: 500 games launching simultaneously
dmb: waiting for games to end...

=INFO REPORT==== 6-Oct-2008::09:14:51 ===
     module: stats
     elapsed: 10.000883
     {time_to_client,max}: 6.587
     {time_to_server,max}: 3.25
     {time_to_client,avg}: 0.8858832584049455
     {time_to_server,avg}: 0.3519747484853795
     bytes: 146366
     packets: 8186
     {bytes,per_sec}: 14635
     {packets,per_sec}: 818

=INFO REPORT==== 6-Oct-2008::09:15:01 ===
     module: stats
     elapsed: 10.000688
     {time_to_client,max}: 904.376
     {time_to_server,max}: 180.778
     {time_to_client,avg}: 392.1472970779772
     {time_to_server,avg}: 11.501733445497706
     bytes: 159498
     packets: 6790
     {bytes,per_sec}: 15948
     {packets,per_sec}: 678

=INFO REPORT==== 6-Oct-2008::09:15:11 ===
     module: stats
     elapsed: 9.998408
     {time_to_client,max}: 2736.19
     {time_to_server,max}: 453.471
     {time_to_client,avg}: 287.5398604052754
     {time_to_server,avg}: 0.3376213403517969
     bytes: 441020
     packets: 18358
     {bytes,per_sec}: 44109
     {packets,per_sec}: 1836

=INFO REPORT==== 6-Oct-2008::09:15:21 ===
     module: stats
     elapsed: 10.000147
     {time_to_client,max}: 7792.444
     {time_to_server,max}: 748.145
     {time_to_client,avg}: 6795.083519124172
     {time_to_server,avg}: 1.8773269961041452
     bytes: 696655
     packets: 28135
     {bytes,per_sec}: 69664
     {packets,per_sec}: 2813

(1@REDACTED)3>
=INFO REPORT==== 6-Oct-2008::09:15:31 ===
     module: stats
     elapsed: 9.999866
     {time_to_client,max}: 8154.04
     {time_to_server,max}: 728.917
     {time_to_client,avg}: 6218.081375635741
     {time_to_server,avg}: 58.365337024422914
     bytes: 48660
     packets: 1972
     {bytes,per_sec}: 4866
     {packets,per_sec}: 197