netperf tcp_cc results are unstable

[asias]

• how netperf tcp_cc works

client side (linux): netperf connect() recv()
server side (osv): netserver listen() accept() close()

client side creates a connection, server accepts the connection and
closes it immediately, client side will return from recv(). This
completes a single transaction. client will repeat above. The
benchmark score is N Transaction/second.

• TIME_WAIT
  Since OSv closes the socket first, OSv will have a lot socket in
  TIME_WAIT state. This explains why increasing the TCBHASHSIZE would
  decrease the cpu usage.
• issue we have
  Centos has a very stable 12K Trans/s results, while OSv has a very
  unstable results: from <1k, 1K, 3K to 12K.

I used strace to see time spend on connect() and recv() syscall in
client side. They usually takes ~100us to complete each.
When OSv has bad results, some of the recv() take up to ~200000us.
This is the show stopper for performance. So probably, OSv has
slowness doing the close() on the socket in some cases

[asias]

I added trace to net_channel code. Seems time in net_channel code is
not significant including the rcu waiting.

 $ sudo scripts/run.py -nv -m4g -c1  -b bridge2   --trace classifier_*
--trace net_channel_* --trace-backtrace

1) Trace for SLOW run 0.5K Trans/Sec
[asias@huginn netperf-2.6.0]$ netperf -H 192.168.2.53 -t TCP_CC -l -1000 --  -D
TCP Connect/Close TEST from 0.0.0.0 (0.0.0.0) port 0 AF_INET to
192.168.2.53 () port 0 AF_INET : nodelay
Local /Remote
Socket Size   Request  Resp.   Elapsed  Trans.
Send   Recv   Size     Size    Time     Rate
bytes  Bytes  bytes    bytes   secs.    per sec

65536  87380  1        1       2.08      481.69
32768  65536


[asias@huginn osv]$ trace summary --timed
Collected 14120 samples spanning 13.46 s

Tracepoint statistics:

  name                             count
  ----                             -----
  classifier_add                    1001
  classifier_add_ret                1001
  classifier_post_packet            3039
  classifier_post_packet_ret        3039
  classifier_remove                 1001
  classifier_remove_ret             1001
  net_channel_process_queue         2019
  net_channel_process_queue_ret     2019

Timed tracepoints [ms]:

  name                    count      min      50%      90%      99%
99.9%      max           total
  ----                    -----      ---      ---      ---      ---
-----      ---           -----
  classifier_add           1000    0.000    0.000    0.001    0.004
0.010    0.010           0.604
  net_channel_process_queue     2018    0.000    0.000    0.000
0.003    0.007    0.007           0.568
  classifier_post_packet     3038    0.000    0.000    0.000    0.002
  0.005    0.013           0.816
  classifier_remove        1000    0.000    0.000    0.001    0.007
0.213    0.213           1.051

[asias@huginn osv]$ trace prof-timed -t classifier_remove
1.05 ms (100.00%, #1000) All
 classifier::remove(ipv4_tcp_conn_id)
 ifnet::del_net_channel(ipv4_tcp_conn_id)
 tcp_teardown_net_channel
 |-- 1.05 ms (99.96%, #999) tcp_usrclosed
 |    tcp_disconnect
 |    tcp_usr_disconnect
 |    soclose
 |    fdrop
 |    fdclose(int)
 |    close
 |    0x10000081e909
 |
 \-- 371.00 ns (0.04%, #1) tcp_do_segment
      tcp_input
      ip_input
      netisr_dispatch_src
      ether_input_internal
      ether_nh_input
      netisr_dispatch_src
      virtio::net::receiver()
      operator()

2) Trace for FAST run 10K Trans/Sec

[asias@huginn netperf-2.6.0]$ netperf -H 192.168.2.53 -t TCP_CC -l -1000 --  -D
TCP Connect/Close TEST from 0.0.0.0 (0.0.0.0) port 0 AF_INET to
192.168.2.53 () port 0 AF_INET : nodelay
Local /Remote
Socket Size   Request  Resp.   Elapsed  Trans.
Send   Recv   Size     Size    Time     Rate
bytes  Bytes  bytes    bytes   secs.    per sec

65536  87380  1        1       0.10     10449.21
32768  65536

[asias@huginn osv]$ trace summary --timed
Collected 14104 samples spanning 8.93 s

Tracepoint statistics:

  name                             count
  ----                             -----
  classifier_add                    1001
  classifier_add_ret                1001
  classifier_post_packet            3032
  classifier_post_packet_ret        3032
  classifier_remove                 1001
  classifier_remove_ret             1001
  net_channel_process_queue         2018
  net_channel_process_queue_ret     2018

Timed tracepoints [ms]:

  name                    count      min      50%      90%      99%
99.9%      max           total
  ----                    -----      ---      ---      ---      ---
-----      ---           -----
  classifier_add           1000    0.000    0.001    0.001    0.001
0.008    0.008           0.613
  net_channel_process_queue     2017    0.000    0.000    0.000
0.002    0.009    0.015           0.638
  classifier_post_packet     3031    0.000    0.000    0.001    0.003
  0.005    0.017           1.150
  classifier_remove        1000    0.000    0.000    0.001    0.007
0.176    0.176           1.179

[asias@huginn osv]$ trace prof-timed -t classifier_remove
1.18 ms (100.00%, #1000) All
 classifier::remove(ipv4_tcp_conn_id)
 ifnet::del_net_channel(ipv4_tcp_conn_id)
 tcp_teardown_net_channel
 |-- 1.18 ms (99.94%, #999) tcp_usrclosed
 |    tcp_disconnect
 |    tcp_usr_disconnect
 |    soclose
 |    fdrop
 |    fdclose(int)
 |    close
 |    0x10000081e909
 |
 \-- 707.00 ns (0.06%, #1) tcp_do_segment
      tcp_input
      ip_input
      netisr_dispatch_src
      ether_input_internal
      ether_nh_input
      netisr_dispatch_src
      virtio::net::receiver()
      operator()