Performance loss when benchmark runs in a more powerful system

[mzimbres]

As discussed in private message, I am observing a slowdown in the performance of my benchmark program when running in a different and more powerful system. To investigate the problem I have extended the usage to incorporate more information and changed my benchmark program to log it every second. The problem occurs sporadically e.g. once every 10 runs. Below is the result of one normal and two problematic runs where colums have the following meaning

1. Commands sent
2. Bytes sent
3. Responses received
4. Pushes received
5. Response-bytes received
6. Push-bytes received
7. Bytes rotated
8. Socket reads (new)
9. Socket writes (new)
10. Time reading (new)
11. Time writing (new)

• Normal

7407762  139512851  7407760  1234627  48150439  53088961  250476  25904  25904  533ms  845ms
7140606  134483560  7140307  1190051  46411996  51172193  193807  26092  26093  544ms  714ms
7060362  132968004  7060661  1176777  45894296  50601411  206613  25441  25440  545ms  751ms
7137012  134413726  7137009  1189502  46390557  51148586  197649  25999  25999  544ms  728ms
7184478  135307669  7184478  1197413  46699107  51488759  246522  25040  25040  535ms  863ms
7333404  138118092  7333405  1222234  47667133  52556062  253598  25610  25611  529ms  879ms
7348080  138383190  7348084  1224680  47762548  52661240  299987  24715  24714  527ms  939ms
7405770  139475335  7405770  1234295  48137505  53074685  311615  24710  24710  526ms  957ms

• Slow 1

7066110  133078405  7060415  1176736  45892839  50599641  231447  24684  24683   547ms  839ms
7165848  134951154  7165737  1194290  46577289  51354470  168155  26131  26130   546ms  715ms
7401606  139396913  7401713  1233619  48111134  53045617  233868  25891  25891   534ms  833ms
7445286  140219553  7445291  1240881  48394394  53357883  328486  25260  25260   524ms  955ms
1216488   22916174  1216187   202698   7905215   8716014   56376   4148   4150   915ms  167ms
  20766     391093    20767     3461    134986    148823     807     73     73   828ms    6ms
  31764     598222    31764     5294    206466    227642    1267    111    111  1033ms   10ms
  38832     731336    38832     6472    252408    278296    1655    135    135  1032ms   13ms
  17130     322615    17127     2855    111324    122765     644     60     60  1034ms    8ms
  17124     322502    17127     2854    111327    122722    1013     60     60  1034ms    6ms
  13704     258092    13702     2284     89062     98212     447     48     48   829ms    5ms
  17124     322502    17126     2854    111320    122722    1012     61     61  1035ms    6ms
  17130     322615    17128     2855    111331    122765     554     60     60  1035ms    6ms
  17124     322502    17126     2854    111320    122722    1022     60     60  1035ms    6ms
  17130     322615    17129     2855    111338    122765     554     60     60  1036ms    6ms
  28338     533699    28339     4723    184204    203089    1175     99     99   826ms   10ms
  39432     742636    39427     6572    256273    282596    1500    138    138  1036ms   13ms

• Slow 2

7253970  136610785  7248276  1208046  47113936  51945971  252780  25578  25571   542ms  824ms
7191990  135449145  7191987  1198665  46747914  51542595  179458  26548  26548   541ms  737ms
7115652  134011446  7115655  1185942  46251759  50995506  237027  25416  25416   533ms  829ms
5633250  106098525  5632945   938825  36614140  40369475  246419  19292  19294   421ms  766ms
  14406     271313    14409     2401     93660    103243     681     50     50  1034ms    4ms
  14406     271313    14408     2401     93653    103243     418     50     50  1037ms    5ms
  14412     271426    14409     2402     93657    103286     407     50     50  1036ms    5ms
  14406     271313    14409     2401     93660    103243     625     51     51  1036ms    4ms
  11526     217073    11526     1921     74919     82603     330     40     40   829ms    4ms
  14412     271426    14408     2402     93650    103286     460     50     50  1036ms    5ms
  14406     271313    14410     2401     93667    103243     681     50     50  1036ms    5ms
  14412     271426    14407     2402     93643    103286     423     50     50  1037ms    4ms
  14406     271313    14409     2401     93660    103243     681     50     50  1036ms    5ms
  14406     271313    14408     2401     93653    103243     591     50     50  1036ms    5ms
  11532     217186    11527     1922     74923     82646     396     40     40   830ms    3ms
  14406     271313    14409     2401     93660    103243     681     50     50  1036ms    5ms

Contrary to what I expect the async read and write ops became faster, I guess this mean the client is coalescing less request when it enters this regime. Clients from other languages are not suffering this problem so I think the server is not the problem.

[mzimbres]

Contrary to what I expect the async read and write ops became faster

Actually only writes became faster, the reads are twice as slow. I extended the usage struct with the number of execs and coalesced requests and the result is

1. Commands sent
2. Bytes sent
3. Responses received
4. Pushes received
5. Response-bytes received
6. Push-bytes received
7. Bytes rotated
8. Execs
9. Coalesced
10. Socket reads
11. Socket writes
12. Time reading
13. Time writing

                                                                  execs    coales.
7393050  139235775  7387056  1231176  48016006  52940561  175517  1231175  1232175  26650  26649   540ms  768ms
7413636  139617828  7413934  1235656  48190570  53133208  154071  1235606  1235606  27049  27047   538ms  733ms
6953406  130961463  6953407  1158901  45197146  49832743  209290  1158951  1158901  24583  24580   530ms  838ms
6756690  127245345  6756689  1126115  43918478  48422945  216012  1126065  1126115  23567  23564   526ms  884ms
7368402  138771684  7368404  1228067  47894627  52806881  208298  1228067  1228067  26800  26798   536ms  741ms
7378740  138966157  7378735  1229790  47961775  52880970  188907  1229840  1229790  26861  26857   535ms  739ms
7141836  134510228  7141536  1190256  46419984  51181008  222277  1190256  1190306  26108  26110   523ms  701ms
6113220  115128807  6113522  1018920  39737894  43813560  156470  1018920  1018870  22112  22110   643ms  656ms
7340460  138243183  7340459  1223410  47712983  52606630  172828  1223360  1223410  26497  26496   535ms  772ms
1177764   22186872  1177464   196244   7653516   8438492   32181   196294   196294   4157   4159   916ms  131ms
  12396     233458    12397     2066     80581     88838     598     2066     2066     44     44   829ms    3ms
  15492     291766    15495     2582    100719    111026     690     2582     2582     55     55  1036ms    5ms
  15498     291879    15497     2583    100730    111069     594     2583     2583     55     55  1036ms    5ms
  15498     291879    15495     2583    100716    111069     670     2583     2583     55     55  1037ms    5ms
  39156     737438    39155     6526    254507    280618    1900     6526     6526    136    136  1035ms   10ms
  12396     233458    12397     2066     80581     88838     601     2066     2066     44     44   828ms    4ms
  15492     291766    15496     2582    100726    111026     766     2582     2582     55     55  1036ms    5ms

It makes sense that the writes are faster since the number of execs/s dropped from 1,223,360 to 2,582. This was more or less clear from column 2. where the number of bytes written/s dropped from 138M to 291K.

[mzimbres]

The problem persists when I disable pushes in the benchmark

7485095  104791330  7485095  0  52395665  0  29647  1497019  1497019  14069  14069   562ms  928ms 
7365285  103113990  7365287  0  51557009  0  29007  1472940  1473057  13841  13841   564ms  924ms 
7483295  104766130  7483293  0  52383051  0  29258  1496659  1496659  14072  14072   565ms  923ms 
4756545   66599820  4755958  0  33291706  0  18278   951309   951309   8968   8970   602ms  592ms 
  13165     184310    13165  0     92155  0     88     2633     2633     25     25  1037ms    4ms 
  13165     184310    13166  0     92162  0     73     2633     2633     25     25  1035ms    7ms 
  11115     147420    11703  0     81921  0     54     2340     2223     22     20  1034ms    5ms 
  12580     184310    11995  0     83965  0     83     2399     2516     23     25   830ms    7ms 
  13170     184380    13166  0     92162  0     73     2634     2634     25     25  1034ms    5ms 
  13165     184310    13166  0     92162  0     65     2633     2633     25     25  1035ms    6ms 
  13165     184310    13166  0     92162  0     78     2633     2633     25     25  1035ms    6ms

That is an indication it is not being somehow slowed down by the receiver.

[anarthal]

Does the slowdown happen also in the Corosio implementation?

[mzimbres]

It occurs less often, but after over 30 tries I go

$ column -s: -t --table-right - log 
7096818  133667926  7096326  1182721  46126119  50857003  252329  
7098882  133684311  7099318  1183219  46145569  50878417  251254  
7112310  133948618  7112366  1185395  46230377  50971985  250398  
7123086  134162640  7122593  1187099  46296854  51045257  243306  
2513112   47330276  2513114   418852  16335242  18010636   92562  
  13266     249843    13267     2211     86236     95073     360  
  16584     312332    16583     2764    107789    118852     364  
  16584     312332    16583     2764    107789    118852     366  
  16584     312332    16584     2764    107796    118852     416  
  16584     312332    16583     2764    107789    118852     275  
  13266     249843    13267     2211     86236     95073     347  
  16584     312332    16583     2764    107789    118852     265  
  92070    1733985    92074    15345    598483    659835    3891  
  16584     312332    16583     2764    107789    118852     291  
  16584     312332    16583     2764    107789    118852     365  
  13266     249843    13267     2211     86236     95073     231