[ovs-discuss] ovs-vswitchd 100% CPU in OVN scale test

aginwala aginwala at asu.edu
Mon Feb 19 17:23:11 UTC 2018


Hi All:

As per the discussions/requests by Mark and Numan, I finally reverted the
mtu patch (commit-id 8c319e8b73032e06c7dd1832b3b31f8a1189dcd1) on
branch-2.9 and re-ran the test with 10k lports to bind on farms, with 8 LRs
and 40 LS ;and results improvised.  Since ovs did not go super hot, it did
result in completion for 10k ports binding to HVs in 5 hrs 28 minutes vs 8
hours with mtu patch.  Thus, the extra strcmp did add the overhead. Cpu
idle graph of farm with 50 Hvs running 2.9 with/without mtu is available @
https://raw.githubusercontent.com/noah8713/ovn-scale-test/4cef99dbe9a0677a1b2d852b7f4f429ede340875/results/overlay/farm_cpu_2.9.png
which indicates ;running non-mtu patch had more idle cpu percentage vs with
mtu patch. In addition, I have also captured ovs-vswitchd process cpu util
on farm since ovs itself was creating a bottleneck by slowing down the port
binding on the computes.Graph is available @
https://raw.githubusercontent.com/noah8713/ovn-scale-test/scale_results/results/overlay/ovs-vswitchd_2.9_util.png
Hence, overall performance improved which resulted in faster completion of
all 10k port bindings.


On Thu, Feb 15, 2018 at 12:20 PM, Mark Michelson <mmichels at redhat.com>
wrote:

>
>
> On 02/08/2018 07:55 PM, Han Zhou wrote:
>
>>
>>
>> On Wed, Feb 7, 2018 at 12:47 PM, Han Zhou <zhouhan at gmail.com <mailto:
>> zhouhan at gmail.com>> wrote:
>>  >
>>  > When doing scale testing for OVN (using https://github.com/openvswitch
>> /ovn-scale-test), we had some interesting findings, and need some help
>> here.
>>  >
>>  > We ran the test "create and bind lports" against branch 2.9 and branch
>> 2.6, and we found that 2.6 was must faster. With some analysis, we found
>> out the reason is not because of OVN gets slower in 2.9, but because the
>> bottleneck of this test in branch 2.9 is ovs-vswitchd.
>>  >
>>  > The testing was run in an environment with 20 farm nodes, each has 50
>> sandbox HVs (I will just mention them as HVs in short). Before the test,
>> there are already 9500 lports bound in 950 HVs on 19 farm nodes. The test
>> run against the last farm node to bind the lport on the 50 HVs there. The
>> steps in the test scenario are:
>>  >
>>  > 1. Create 5 new LSs in NB (so that the LSs will not be shared with any
>> of HVs on other farm nodes)
>>  > 2. create 100 lports in NB on a LS
>>  > 3. bind these lports on HVs, 2 for each HV. They are bound
>> sequentially on each HV, and for each HV the 2 ports are bound using one
>> command together: ovs-vsctl add-port <port 1> -- set Interface
>> external-ids:...  -- add-port <port 2> -- set Interface external-ids:...
>> (the script didn't set type to internal, but I hope it is not an issue for
>> this test).
>>  > 4. wait the port stated changed to up in NB for all the 100 lports
>> (with a single ovn-nbctl command)
>>  >
>>  > These steps are repeated for 5 times, one for each LS. So in the end
>> we got 500 more lports created and bound (the total scale is then 1k HVs
>> and 10k lports).
>>  >
>>  > When running with 2.6, the ovn-controllers were taking most of the CPU
>> time. However, with 2.9, the CPU of ovn-controllers spikes but there is
>> always ovs-vswitchd on the top with 100% CPU. It means the ovs-vswitchd is
>> the bottleneck in this testing. There is only one ovs-vswitchd with 100% at
>> the same time and different ovs-vswitchd will spike one after another,
>> since the ports are bound sequentially on each HV. From the rally log, each
>> 2 ports binding takes around 4 - 5 seconds. This is just the ovs-vsctl
>> command execution time. The 100% CPU of ovs-vswitchd explains the slowness.
>>  >
>>  > So, based on this result, we can not using the total time to evaluate
>> the efficiency of OVN, instead we can evaluate by CPU cost of
>> ovn-controller processes. In fact, 2.9 ovn-controller costs around 70% less
>> CPU than 2.6, which I think is due to some optimization we made earlier.
>> (With my work-in-progress patch it saves much more, and I will post later
>> as RFC).
>>  >
>>  > However, I cannot explain why ovs-vswitchd is getting slower than 2.6
>> when doing port-binding. We need expert suggestions here, for what could be
>> the possible reason of this slowness. We can do more testing with different
>> versions between 2.6 and 2.9 to find out related change, but with some
>> pointers it might save some effort. Below are some logs of ovs-vswitchd
>> when port binding is happening:
>>  >
>>  > ======
>>  > 2018-02-07T00:12:54.558Z|01767|bridge|INFO|bridge br-int: added
>> interface lport_bc65cd_QFOU3v on port 1028
>>  > 2018-02-07T00:12:55.629Z|01768|timeval|WARN|Unreasonably long 1112ms
>> poll interval (1016ms user, 4ms system)
>>  > 2018-02-07T00:12:55.629Z|01769|timeval|WARN|faults: 336 minor, 0 major
>>  > 2018-02-07T00:12:55.629Z|01770|timeval|WARN|context switches: 0
>> voluntary, 13 involuntary
>>  > 2018-02-07T00:12:55.629Z|01771|coverage|INFO|Event coverage, avg rate
>> over last: 5 seconds, last minute, last hour,  hash=b256889c:
>>  > 2018-02-07T00:12:55.629Z|01772|coverage|INFO|bridge_reconfigure
>>     0.0/sec     0.000/sec        0.0056/sec   total: 29
>>  > 2018-02-07T00:12:55.629Z|01773|coverage|INFO|ofproto_flush
>>    0.0/sec     0.000/sec        0.0000/sec   total: 1
>>  > 2018-02-07T00:12:55.629Z|01774|coverage|INFO|ofproto_packet_out
>>     0.0/sec     0.000/sec        0.0111/sec   total: 90
>>  > 2018-02-07T00:12:55.629Z|01775|coverage|INFO|ofproto_recv_openflow
>>    0.2/sec     0.033/sec        0.4858/sec   total: 6673
>>  > 2018-02-07T00:12:55.629Z|01776|coverage|INFO|ofproto_update_port
>>    0.0/sec     0.000/sec        5.5883/sec   total: 28258
>>  > 2018-02-07T00:12:55.629Z|01777|coverage|INFO|rev_reconfigure
>>    0.0/sec     0.000/sec        0.0056/sec   total: 32
>>  > 2018-02-07T00:12:55.629Z|01778|coverage|INFO|rev_port_toggled
>>     0.0/sec     0.000/sec        0.0011/sec   total: 6
>>  > 2018-02-07T00:12:55.629Z|01779|coverage|INFO|rev_flow_table
>>     0.0/sec     0.000/sec        0.0078/sec   total: 124
>>  > 2018-02-07T00:12:55.629Z|01780|coverage|INFO|rev_mac_learning
>>     0.0/sec     0.000/sec        0.0036/sec   total: 13
>>  > 2018-02-07T00:12:55.629Z|01781|coverage|INFO|xlate_actions
>>    0.0/sec     0.000/sec        0.0111/sec   total: 90
>>  > 2018-02-07T00:12:55.629Z|01782|coverage|INFO|ccmap_expand
>>     0.0/sec     0.000/sec        0.0050/sec   total: 36
>>  > 2018-02-07T00:12:55.629Z|01783|coverage|INFO|ccmap_shrink
>>     0.0/sec     0.000/sec        0.0000/sec   total: 49
>>  > 2018-02-07T00:12:55.629Z|01784|coverage|INFO|cmap_expand
>>    0.0/sec     0.000/sec        0.0217/sec   total: 257
>>  > 2018-02-07T00:12:55.629Z|01785|coverage|INFO|cmap_shrink
>>    0.0/sec     0.000/sec        0.0000/sec   total: 141
>>  > 2018-02-07T00:12:55.629Z|01786|coverage|INFO|dpif_port_add
>>    0.0/sec     0.000/sec        0.0022/sec   total: 1020
>>  > 2018-02-07T00:12:55.629Z|01787|coverage|INFO|dpif_port_del
>>    0.0/sec     0.000/sec        0.0000/sec   total: 40
>>  > 2018-02-07T00:12:55.629Z|01788|coverage|INFO|dpif_flow_flush
>>    0.0/sec     0.000/sec        0.0000/sec   total: 2
>>  > 2018-02-07T00:12:55.629Z|01789|coverage|INFO|dpif_flow_get
>>    0.0/sec     0.000/sec        0.0000/sec   total: 20
>>  > 2018-02-07T00:12:55.629Z|01790|coverage|INFO|dpif_flow_put
>>    0.0/sec     0.000/sec        0.0000/sec   total: 21
>>  > 2018-02-07T00:12:55.629Z|01791|coverage|INFO|dpif_flow_del
>>    0.0/sec     0.000/sec        0.0000/sec   total: 20
>>  > 2018-02-07T00:12:55.629Z|01792|coverage|INFO|dpif_execute
>>     0.0/sec     0.000/sec        0.0100/sec   total: 71
>>  > 2018-02-07T00:12:55.629Z|01793|coverage|INFO|flow_extract
>>     0.0/sec     0.000/sec        0.0000/sec   total: 4
>>  > 2018-02-07T00:12:55.629Z|01794|coverage|INFO|miniflow_malloc
>>    0.0/sec     0.000/sec        0.4361/sec   total: 6435
>>  > 2018-02-07T00:12:55.629Z|01795|coverage|INFO|hindex_pathological
>>    0.0/sec     0.000/sec        0.0000/sec   total: 17
>>  > 2018-02-07T00:12:55.629Z|01796|coverage|INFO|hindex_expand
>>    0.0/sec     0.000/sec        0.0000/sec   total: 9
>>  > 2018-02-07T00:12:55.629Z|01797|coverage|INFO|hmap_pathological
>>    0.0/sec     0.000/sec        0.8131/sec   total: 13752
>>  > 2018-02-07T00:12:55.630Z|01798|coverage|INFO|hmap_expand
>>   21.0/sec    18.333/sec    11253.0167/sec   total: 55905271
>>  > 2018-02-07T00:12:55.630Z|01799|coverage|INFO|hmap_shrink
>>    0.0/sec     0.000/sec        0.0022/sec   total: 1029
>>  > 2018-02-07T00:12:55.630Z|01800|coverage|INFO|mac_learning_learned
>>     0.0/sec     0.000/sec        0.0022/sec   total: 18
>>  > 2018-02-07T00:12:55.630Z|01801|coverage|INFO|mac_learning_expired
>>     0.0/sec     0.000/sec        0.0017/sec   total: 6
>>  > 2018-02-07T00:12:55.630Z|01802|coverage|INFO|netdev_sent
>>    0.0/sec     0.000/sec        0.0400/sec   total: 350
>>  > 2018-02-07T00:12:55.630Z|01803|coverage|INFO|netdev_get_stats
>>  203.4/sec   203.400/sec      198.4978/sec   total: 798522
>>  > 2018-02-07T00:12:55.630Z|01804|coverage|INFO|txn_unchanged
>>    0.2/sec     0.200/sec        0.1911/sec   total: 776
>>  > 2018-02-07T00:12:55.630Z|01805|coverage|INFO|txn_incomplete
>>     0.0/sec     0.000/sec        0.0167/sec   total: 106
>>  > 2018-02-07T00:12:55.630Z|01806|coverage|INFO|txn_success
>>    0.0/sec     0.000/sec        0.0111/sec   total: 48
>>  > 2018-02-07T00:12:55.630Z|01807|coverage|INFO|poll_create_node
>>  162.6/sec   157.267/sec      156.3664/sec   total: 636465
>>  > 2018-02-07T00:12:55.630Z|01808|coverage|INFO|poll_zero_timeout
>>    0.2/sec     0.250/sec        0.4564/sec   total: 1936
>>  > 2018-02-07T00:12:55.630Z|01809|coverage|INFO|rconn_queued
>>     0.2/sec     0.033/sec        0.0453/sec   total: 1214
>>  > 2018-02-07T00:12:55.630Z|01810|coverage|INFO|rconn_sent
>>     0.2/sec     0.033/sec        0.0453/sec   total: 1214
>>  > 2018-02-07T00:12:55.630Z|01811|coverage|INFO|seq_change
>>  1098.8/sec  1099.167/sec     1097.4869/sec   total: 4468823
>>  > 2018-02-07T00:12:55.630Z|01812|coverage|INFO|pstream_open
>>     0.0/sec     0.000/sec        0.0000/sec   total: 5
>>  > 2018-02-07T00:12:55.630Z|01813|coverage|INFO|stream_open
>>    0.0/sec     0.000/sec        0.0000/sec   total: 1
>>  > 2018-02-07T00:12:55.630Z|01814|coverage|INFO|util_xalloc
>>  7223.8/sec  6527.317/sec    51569.9900/sec   total: 251999059
>>  > 2018-02-07T00:12:55.630Z|01815|coverage|INFO|vconn_received
>>     0.2/sec     0.033/sec        0.4858/sec   total: 6675
>>  > 2018-02-07T00:12:55.630Z|01816|coverage|INFO|vconn_sent
>>     0.2/sec     0.033/sec        0.0453/sec   total: 1216
>>  > 2018-02-07T00:12:55.630Z|01817|coverage|INFO|netlink_received
>>     0.0/sec     0.000/sec        0.0000/sec   total: 3
>>  > 2018-02-07T00:12:55.630Z|01818|coverage|INFO|netlink_sent
>>     0.0/sec     0.000/sec        0.0000/sec   total: 1
>>  > 2018-02-07T00:12:55.630Z|01819|coverage|INFO|57 events never hit
>>  > 2018-02-07T00:12:56.761Z|01820|timeval|WARN|Unreasonably long 1112ms
>> poll interval (948ms user, 4ms system)
>>  > 2018-02-07T00:12:56.761Z|01821|timeval|WARN|faults: 7 minor, 0 major
>>  > 2018-02-07T00:12:56.761Z|01822|timeval|WARN|context switches: 2
>> voluntary, 17 involuntary
>>  > 2018-02-07T00:12:56.761Z|01823|coverage|INFO|Event coverage, avg rate
>> over last: 5 seconds, last minute, last hour,  hash=fcc57021:
>>  > 2018-02-07T00:12:56.761Z|01824|coverage|INFO|bridge_reconfigure
>>     0.0/sec     0.000/sec        0.0056/sec   total: 30
>>  > 2018-02-07T00:12:56.761Z|01825|coverage|INFO|ofproto_flush
>>    0.0/sec     0.000/sec        0.0000/sec   total: 1
>>  > 2018-02-07T00:12:56.761Z|01826|coverage|INFO|ofproto_packet_out
>>     0.0/sec     0.000/sec        0.0111/sec   total: 90
>>  > 2018-02-07T00:12:56.761Z|01827|coverage|INFO|ofproto_recv_openflow
>>    0.2/sec     0.033/sec        0.4858/sec   total: 6683
>>  > 2018-02-07T00:12:56.761Z|01828|coverage|INFO|ofproto_update_port
>>    0.0/sec     0.000/sec        5.5883/sec   total: 29268
>>  > 2018-02-07T00:12:56.761Z|01829|coverage|INFO|rev_reconfigure
>>    0.0/sec     0.000/sec        0.0056/sec   total: 33
>>  > 2018-02-07T00:12:56.761Z|01830|coverage|INFO|rev_port_toggled
>>     0.0/sec     0.000/sec        0.0011/sec   total: 6
>>  > 2018-02-07T00:12:56.761Z|01831|coverage|INFO|rev_flow_table
>>     0.0/sec     0.000/sec        0.0078/sec   total: 124
>>  > 2018-02-07T00:12:56.761Z|01832|coverage|INFO|rev_mac_learning
>>     0.0/sec     0.000/sec        0.0036/sec   total: 13
>>  > 2018-02-07T00:12:56.761Z|01833|coverage|INFO|xlate_actions
>>    0.0/sec     0.000/sec        0.0111/sec   total: 90
>>  > 2018-02-07T00:12:56.761Z|01834|coverage|INFO|ccmap_expand
>>     0.0/sec     0.000/sec        0.0050/sec   total: 36
>>  > 2018-02-07T00:12:56.761Z|01835|coverage|INFO|ccmap_shrink
>>     0.0/sec     0.000/sec        0.0000/sec   total: 49
>>  > 2018-02-07T00:12:56.761Z|01836|coverage|INFO|cmap_expand
>>    0.0/sec     0.000/sec        0.0217/sec   total: 257
>>  > 2018-02-07T00:12:56.761Z|01837|coverage|INFO|cmap_shrink
>>    0.0/sec     0.000/sec        0.0000/sec   total: 141
>>  > 2018-02-07T00:12:56.761Z|01838|coverage|INFO|dpif_port_add
>>    0.0/sec     0.000/sec        0.0022/sec   total: 1020
>>  > 2018-02-07T00:12:56.761Z|01839|coverage|INFO|dpif_port_del
>>    0.0/sec     0.000/sec        0.0000/sec   total: 40
>>  > 2018-02-07T00:12:56.761Z|01840|coverage|INFO|dpif_flow_flush
>>    0.0/sec     0.000/sec        0.0000/sec   total: 2
>>  > 2018-02-07T00:12:56.761Z|01841|coverage|INFO|dpif_flow_get
>>    0.0/sec     0.000/sec        0.0000/sec   total: 20
>>  > 2018-02-07T00:12:56.761Z|01842|coverage|INFO|dpif_flow_put
>>    0.0/sec     0.000/sec        0.0000/sec   total: 21
>>  > 2018-02-07T00:12:56.761Z|01843|coverage|INFO|dpif_flow_del
>>    0.0/sec     0.000/sec        0.0000/sec   total: 20
>>  > 2018-02-07T00:12:56.761Z|01844|coverage|INFO|dpif_execute
>>     0.0/sec     0.000/sec        0.0100/sec   total: 71
>>  > 2018-02-07T00:12:56.761Z|01845|coverage|INFO|flow_extract
>>     0.0/sec     0.000/sec        0.0000/sec   total: 4
>>  > 2018-02-07T00:12:56.761Z|01846|coverage|INFO|miniflow_malloc
>>    0.0/sec     0.000/sec        0.4361/sec   total: 6440
>>  > 2018-02-07T00:12:56.761Z|01847|coverage|INFO|hindex_pathological
>>    0.0/sec     0.000/sec        0.0000/sec   total: 17
>>  > 2018-02-07T00:12:56.761Z|01848|coverage|INFO|hindex_expand
>>    0.0/sec     0.000/sec        0.0000/sec   total: 9
>>  > 2018-02-07T00:12:56.761Z|01849|coverage|INFO|hmap_pathological
>>    0.0/sec     0.000/sec        0.8131/sec   total: 13825
>>  > 2018-02-07T00:12:56.761Z|01850|coverage|INFO|hmap_expand
>>   21.0/sec    18.333/sec    11253.0167/sec   total: 57949607
>>  > 2018-02-07T00:12:56.761Z|01851|coverage|INFO|hmap_shrink
>>    0.0/sec     0.000/sec        0.0022/sec   total: 1029
>>  > 2018-02-07T00:12:56.761Z|01852|coverage|INFO|mac_learning_learned
>>     0.0/sec     0.000/sec        0.0022/sec   total: 18
>>  > 2018-02-07T00:12:56.761Z|01853|coverage|INFO|mac_learning_expired
>>     0.0/sec     0.000/sec        0.0017/sec   total: 6
>>  > 2018-02-07T00:12:56.761Z|01854|coverage|INFO|netdev_sent
>>    0.0/sec     0.000/sec        0.0400/sec   total: 350
>>  > 2018-02-07T00:12:56.761Z|01855|coverage|INFO|netdev_get_stats
>>  203.4/sec   203.400/sec      198.4978/sec   total: 799540
>>  > 2018-02-07T00:12:56.761Z|01856|coverage|INFO|txn_unchanged
>>    0.2/sec     0.200/sec        0.1911/sec   total: 777
>>  > 2018-02-07T00:12:56.761Z|01857|coverage|INFO|txn_incomplete
>>     0.0/sec     0.000/sec        0.0167/sec   total: 108
>>  > 2018-02-07T00:12:56.761Z|01858|coverage|INFO|txn_success
>>    0.0/sec     0.000/sec        0.0111/sec   total: 49
>>  > 2018-02-07T00:12:56.761Z|01859|coverage|INFO|poll_create_node
>>  162.6/sec   157.267/sec      156.3664/sec   total: 636681
>>  > 2018-02-07T00:12:56.761Z|01860|coverage|INFO|poll_zero_timeout
>>    0.2/sec     0.250/sec        0.4564/sec   total: 1937
>>  > 2018-02-07T00:12:56.761Z|01861|coverage|INFO|rconn_queued
>>     0.2/sec     0.033/sec        0.0453/sec   total: 1216
>>  > 2018-02-07T00:12:56.761Z|01862|coverage|INFO|rconn_sent
>>     0.2/sec     0.033/sec        0.0453/sec   total: 1216
>>  > 2018-02-07T00:12:56.761Z|01863|coverage|INFO|seq_change
>>  1098.8/sec  1099.167/sec     1097.4869/sec   total: 4471434
>>  > 2018-02-07T00:12:56.761Z|01864|coverage|INFO|pstream_open
>>     0.0/sec     0.000/sec        0.0000/sec   total: 5
>>  > 2018-02-07T00:12:56.761Z|01865|coverage|INFO|stream_open
>>    0.0/sec     0.000/sec        0.0000/sec   total: 1
>>  > 2018-02-07T00:12:56.761Z|01866|coverage|INFO|util_xalloc
>>  7223.8/sec  6527.317/sec    51569.9900/sec   total: 260206006
>>  > 2018-02-07T00:12:56.761Z|01867|coverage|INFO|vconn_received
>>     0.2/sec     0.033/sec        0.4858/sec   total: 6685
>>  > 2018-02-07T00:12:56.761Z|01868|coverage|INFO|vconn_sent
>>     0.2/sec     0.033/sec        0.0453/sec   total: 1218
>>  > 2018-02-07T00:12:56.761Z|01869|coverage|INFO|netlink_received
>>     0.0/sec     0.000/sec        0.0000/sec   total: 3
>>  > 2018-02-07T00:12:56.761Z|01870|coverage|INFO|netlink_sent
>>     0.0/sec     0.000/sec        0.0000/sec   total: 1
>>  > 2018-02-07T00:12:56.761Z|01871|coverage|INFO|57 events never hit
>>  > 2018-02-07T00:12:57.054Z|01872|bridge|INFO|bridge br-int: added
>> interface lport_bc65cd_lykjnm on port 1029
>>  > 2018-02-07T00:12:58.202Z|01873|timeval|WARN|Unreasonably long 1179ms
>> poll interval (1032ms user, 0ms system)
>>  > 2018-02-07T00:12:58.202Z|01874|timeval|WARN|faults: 41 minor, 0 major
>>  > 2018-02-07T00:12:58.202Z|01875|timeval|WARN|context switches: 0
>> voluntary, 19 involuntary
>>  > 2018-02-07T00:12:58.203Z|01876|coverage|INFO|Event coverage, avg rate
>> over last: 5 seconds, last minute, last hour,  hash=668121b0:
>>  > 2018-02-07T00:12:58.203Z|01877|coverage|INFO|bridge_reconfigure
>>     0.0/sec     0.000/sec        0.0056/sec   total: 31
>>  > 2018-02-07T00:12:58.203Z|01878|coverage|INFO|ofproto_flush
>>    0.0/sec     0.000/sec        0.0000/sec   total: 1
>>  > 2018-02-07T00:12:58.203Z|01879|coverage|INFO|ofproto_packet_out
>>     0.0/sec     0.000/sec        0.0111/sec   total: 90
>>  > 2018-02-07T00:12:58.203Z|01880|coverage|INFO|ofproto_recv_openflow
>>    0.2/sec     0.033/sec        0.4858/sec   total: 6733
>>  > 2018-02-07T00:12:58.203Z|01881|coverage|INFO|ofproto_update_port
>>    0.0/sec     0.000/sec        5.5883/sec   total: 30279
>>  > 2018-02-07T00:12:58.203Z|01882|coverage|INFO|rev_reconfigure
>>    0.0/sec     0.000/sec        0.0056/sec   total: 34
>>  > 2018-02-07T00:12:58.203Z|01883|coverage|INFO|rev_port_toggled
>>     0.0/sec     0.000/sec        0.0011/sec   total: 6
>>  > 2018-02-07T00:12:58.203Z|01884|coverage|INFO|rev_flow_table
>>     0.0/sec     0.000/sec        0.0078/sec   total: 125
>>  > 2018-02-07T00:12:58.203Z|01885|coverage|INFO|rev_mac_learning
>>     0.0/sec     0.000/sec        0.0036/sec   total: 13
>>  > 2018-02-07T00:12:58.203Z|01886|coverage|INFO|xlate_actions
>>    0.0/sec     0.000/sec        0.0111/sec   total: 90
>>  > 2018-02-07T00:12:58.203Z|01887|coverage|INFO|ccmap_expand
>>     0.0/sec     0.000/sec        0.0050/sec   total: 36
>>  > 2018-02-07T00:12:58.203Z|01888|coverage|INFO|ccmap_shrink
>>     0.0/sec     0.000/sec        0.0000/sec   total: 49
>>  > 2018-02-07T00:12:58.203Z|01889|coverage|INFO|cmap_expand
>>    0.0/sec     0.000/sec        0.0217/sec   total: 260
>>  > 2018-02-07T00:12:58.203Z|01890|coverage|INFO|cmap_shrink
>>    0.0/sec     0.000/sec        0.0000/sec   total: 141
>>  > 2018-02-07T00:12:58.203Z|01891|coverage|INFO|dpif_port_add
>>    0.0/sec     0.000/sec        0.0022/sec   total: 1021
>>  > 2018-02-07T00:12:58.203Z|01892|coverage|INFO|dpif_port_del
>>    0.0/sec     0.000/sec        0.0000/sec   total: 40
>>  > 2018-02-07T00:12:58.203Z|01893|coverage|INFO|dpif_flow_flush
>>    0.0/sec     0.000/sec        0.0000/sec   total: 2
>>  > 2018-02-07T00:12:58.203Z|01894|coverage|INFO|dpif_flow_get
>>    0.0/sec     0.000/sec        0.0000/sec   total: 20
>>  > 2018-02-07T00:12:58.203Z|01895|coverage|INFO|dpif_flow_put
>>    0.0/sec     0.000/sec        0.0000/sec   total: 21
>>  > 2018-02-07T00:12:58.203Z|01896|coverage|INFO|dpif_flow_del
>>    0.0/sec     0.000/sec        0.0000/sec   total: 20
>>  > 2018-02-07T00:12:58.203Z|01897|coverage|INFO|dpif_execute
>>     0.0/sec     0.000/sec        0.0100/sec   total: 71
>>  > 2018-02-07T00:12:58.203Z|01898|coverage|INFO|flow_extract
>>     0.0/sec     0.000/sec        0.0000/sec   total: 4
>>  > 2018-02-07T00:12:58.203Z|01899|coverage|INFO|miniflow_malloc
>>    0.0/sec     0.000/sec        0.4361/sec   total: 6489
>>  > 2018-02-07T00:12:58.203Z|01900|coverage|INFO|hindex_pathological
>>    0.0/sec     0.000/sec        0.0000/sec   total: 17
>>  > 2018-02-07T00:12:58.203Z|01901|coverage|INFO|hindex_expand
>>    0.0/sec     0.000/sec        0.0000/sec   total: 9
>>  > 2018-02-07T00:12:58.203Z|01902|coverage|INFO|hmap_pathological
>>    0.0/sec     0.000/sec        0.8131/sec   total: 13945
>>  > 2018-02-07T00:12:58.203Z|01903|coverage|INFO|hmap_expand
>>   21.0/sec    18.333/sec    11253.0167/sec   total: 59998044
>>  > 2018-02-07T00:12:58.203Z|01904|coverage|INFO|hmap_shrink
>>    0.0/sec     0.000/sec        0.0022/sec   total: 1030
>>  > 2018-02-07T00:12:58.203Z|01905|coverage|INFO|mac_learning_learned
>>     0.0/sec     0.000/sec        0.0022/sec   total: 18
>>  > 2018-02-07T00:12:58.203Z|01906|coverage|INFO|mac_learning_expired
>>     0.0/sec     0.000/sec        0.0017/sec   total: 6
>>  > 2018-02-07T00:12:58.203Z|01907|coverage|INFO|netdev_sent
>>    0.0/sec     0.000/sec        0.0400/sec   total: 350
>>  > 2018-02-07T00:12:58.203Z|01908|coverage|INFO|netdev_get_stats
>>  203.4/sec   203.400/sec      198.4978/sec   total: 799541
>>  > 2018-02-07T00:12:58.203Z|01909|coverage|INFO|txn_unchanged
>>    0.2/sec     0.200/sec        0.1911/sec   total: 777
>>  > 2018-02-07T00:12:58.203Z|01910|coverage|INFO|txn_incomplete
>>     0.0/sec     0.000/sec        0.0167/sec   total: 110
>>  > 2018-02-07T00:12:58.203Z|01911|coverage|INFO|txn_success
>>    0.0/sec     0.000/sec        0.0111/sec   total: 50
>>  > 2018-02-07T00:12:58.203Z|01912|coverage|INFO|poll_create_node
>>  162.6/sec   157.267/sec      156.3664/sec   total: 636974
>>  > 2018-02-07T00:12:58.203Z|01913|coverage|INFO|poll_zero_timeout
>>    0.2/sec     0.250/sec        0.4564/sec   total: 1939
>>  > 2018-02-07T00:12:58.203Z|01914|coverage|INFO|rconn_queued
>>     0.2/sec     0.033/sec        0.0453/sec   total: 1217
>>  > 2018-02-07T00:12:58.203Z|01915|coverage|INFO|rconn_sent
>>     0.2/sec     0.033/sec        0.0453/sec   total: 1217
>>  > 2018-02-07T00:12:58.203Z|01916|coverage|INFO|seq_change
>>  1098.8/sec  1099.167/sec     1097.4869/sec   total: 4474605
>>  > 2018-02-07T00:12:58.203Z|01917|coverage|INFO|pstream_open
>>     0.0/sec     0.000/sec        0.0000/sec   total: 5
>>  > 2018-02-07T00:12:58.203Z|01918|coverage|INFO|stream_open
>>    0.0/sec     0.000/sec        0.0000/sec   total: 1
>>  > 2018-02-07T00:12:58.203Z|01919|coverage|INFO|util_xalloc
>>  7223.8/sec  6527.317/sec    51569.9900/sec   total: 268435993
>>  > 2018-02-07T00:12:58.203Z|01920|coverage|INFO|vconn_received
>>     0.2/sec     0.033/sec        0.4858/sec   total: 6735
>>  > 2018-02-07T00:12:58.203Z|01921|coverage|INFO|vconn_sent
>>     0.2/sec     0.033/sec        0.0453/sec   total: 1219
>>  > 2018-02-07T00:12:58.203Z|01922|coverage|INFO|netlink_received
>>     0.0/sec     0.000/sec        0.0000/sec   total: 3
>>  > 2018-02-07T00:12:58.203Z|01923|coverage|INFO|netlink_sent
>>     0.0/sec     0.000/sec        0.0000/sec   total: 1
>>  > 2018-02-07T00:12:58.203Z|01924|coverage|INFO|57 events never hit
>>  > 2018-02-07T00:12:58.221Z|01925|bridge|INFO|bridge br-int: added
>> interface patch-br-int-to-provnet-lswitch_bc65cd_Y7sqEw on port 1030
>>  > 2018-02-07T00:12:58.221Z|01926|bridge|INFO|bridge br0: added
>> interface patch-provnet-lswitch_bc65cd_Y7sqEw-to-br-int on port 15
>>  > 2018-02-07T00:12:59.313Z|01927|timeval|WARN|Unreasonably long 1111ms
>> poll interval (1092ms user, 0ms system)
>>  > 2018-02-07T00:12:59.313Z|01928|timeval|WARN|faults: 45 minor, 0 major
>>  > 2018-02-07T00:12:59.313Z|01929|timeval|WARN|context switches: 6
>> voluntary, 59 involuntary
>>  > 2018-02-07T00:12:59.313Z|01930|coverage|INFO|Skipping details of
>> duplicate event coverage for hash=668121b0
>>  > 2018-02-07T00:13:00.430Z|01931|timeval|WARN|Unreasonably long 1117ms
>> poll interval (1112ms user, 0ms system)
>>  > 2018-02-07T00:13:00.430Z|01932|timeval|WARN|faults: 34 minor, 0 major
>>  > 2018-02-07T00:13:00.430Z|01933|timeval|WARN|context switches: 2
>> voluntary, 11 involuntary
>>  > 2018-02-07T00:13:00.431Z|01934|coverage|INFO|Event coverage, avg rate
>> over last: 5 seconds, last minute, last hour,  hash=a612a6e0:
>>  > 2018-02-07T00:13:00.431Z|01935|coverage|INFO|bridge_reconfigure
>>     0.8/sec     0.067/sec        0.0067/sec   total: 33
>>  > 2018-02-07T00:13:00.431Z|01936|coverage|INFO|ofproto_flush
>>    0.0/sec     0.000/sec        0.0000/sec   total: 1
>>  > 2018-02-07T00:13:00.431Z|01937|coverage|INFO|ofproto_packet_out
>>     0.2/sec     0.017/sec        0.0114/sec   total: 92
>>  > 2018-02-07T00:13:00.431Z|01938|coverage|INFO|ofproto_recv_openflow
>>   32.2/sec     2.717/sec        0.5306/sec   total: 6935
>>  > 2018-02-07T00:13:00.431Z|01939|coverage|INFO|ofproto_update_port
>>  808.8/sec    67.400/sec        6.7117/sec   total: 32303
>>  > 2018-02-07T00:13:00.431Z|01940|coverage|INFO|rev_reconfigure
>>    0.8/sec     0.067/sec        0.0067/sec   total: 36
>>  > 2018-02-07T00:13:00.431Z|01941|coverage|INFO|rev_port_toggled
>>     0.0/sec     0.000/sec        0.0011/sec   total: 7
>>  > 2018-02-07T00:13:00.431Z|01942|coverage|INFO|rev_flow_table
>>     0.4/sec     0.033/sec        0.0083/sec   total: 126
>>  > 2018-02-07T00:13:00.431Z|01943|coverage|INFO|rev_mac_learning
>>     0.0/sec     0.000/sec        0.0036/sec   total: 13
>>  > 2018-02-07T00:13:00.431Z|01944|coverage|INFO|xlate_actions
>>    0.2/sec     0.017/sec        0.0114/sec   total: 92
>>  > 2018-02-07T00:13:00.431Z|01945|coverage|INFO|ccmap_expand
>>     0.0/sec     0.000/sec        0.0050/sec   total: 36
>>  > 2018-02-07T00:13:00.431Z|01946|coverage|INFO|ccmap_shrink
>>     0.0/sec     0.000/sec        0.0000/sec   total: 49
>>  > 2018-02-07T00:13:00.431Z|01947|coverage|INFO|cmap_expand
>>    2.0/sec     0.167/sec        0.0244/sec   total: 271
>>  > 2018-02-07T00:13:00.431Z|01948|coverage|INFO|cmap_shrink
>>    0.0/sec     0.000/sec        0.0000/sec   total: 141
>>  > 2018-02-07T00:13:00.431Z|01949|coverage|INFO|dpif_port_add
>>    0.4/sec     0.033/sec        0.0028/sec   total: 1021
>>  > 2018-02-07T00:13:00.431Z|01950|coverage|INFO|dpif_port_del
>>    0.0/sec     0.000/sec        0.0000/sec   total: 40
>>  > 2018-02-07T00:13:00.431Z|01951|coverage|INFO|dpif_flow_flush
>>    0.0/sec     0.000/sec        0.0000/sec   total: 2
>>  > 2018-02-07T00:13:00.431Z|01952|coverage|INFO|dpif_flow_get
>>    0.0/sec     0.000/sec        0.0000/sec   total: 20
>>  > 2018-02-07T00:13:00.431Z|01953|coverage|INFO|dpif_flow_put
>>    0.0/sec     0.000/sec        0.0000/sec   total: 21
>>  > 2018-02-07T00:13:00.431Z|01954|coverage|INFO|dpif_flow_del
>>    0.0/sec     0.000/sec        0.0000/sec   total: 20
>>  > 2018-02-07T00:13:00.431Z|01955|coverage|INFO|dpif_execute
>>     0.0/sec     0.000/sec        0.0100/sec   total: 72
>>  > 2018-02-07T00:13:00.431Z|01956|coverage|INFO|flow_extract
>>     0.0/sec     0.000/sec        0.0000/sec   total: 4
>>  > 2018-02-07T00:13:00.431Z|01957|coverage|INFO|miniflow_malloc
>>   30.8/sec     2.567/sec        0.4789/sec   total: 6689
>>  > 2018-02-07T00:13:00.431Z|01958|coverage|INFO|hindex_pathological
>>    0.0/sec     0.000/sec        0.0000/sec   total: 17
>>  > 2018-02-07T00:13:00.431Z|01959|coverage|INFO|hindex_expand
>>    0.0/sec     0.000/sec        0.0000/sec   total: 9
>>  > 2018-02-07T00:13:00.431Z|01960|coverage|INFO|hmap_pathological
>>   76.8/sec     6.400/sec        0.9197/sec   total: 14149
>>  > 2018-02-07T00:13:00.431Z|01961|coverage|INFO|hmap_expand
>>  1637509.8/sec 136476.267/sec    13527.3358/sec   total: 64098893
>>  > 2018-02-07T00:13:00.431Z|01962|coverage|INFO|hmap_shrink
>>    0.4/sec     0.033/sec        0.0028/sec   total: 1030
>>  > 2018-02-07T00:13:00.431Z|01963|coverage|INFO|mac_learning_learned
>>     0.0/sec     0.000/sec        0.0022/sec   total: 19
>>  > 2018-02-07T00:13:00.431Z|01964|coverage|INFO|mac_learning_expired
>>     0.0/sec     0.000/sec        0.0017/sec   total: 6
>>  > 2018-02-07T00:13:00.431Z|01965|coverage|INFO|netdev_sent
>>    0.0/sec     0.000/sec        0.0400/sec   total: 359
>>  > 2018-02-07T00:13:00.431Z|01966|coverage|INFO|netdev_get_stats
>>  204.4/sec   203.483/sec      198.7817/sec   total: 799543
>>  > 2018-02-07T00:13:00.431Z|01967|coverage|INFO|txn_unchanged
>>    0.2/sec     0.200/sec        0.1914/sec   total: 777
>>  > 2018-02-07T00:13:00.431Z|01968|coverage|INFO|txn_incomplete
>>     1.4/sec     0.117/sec        0.0186/sec   total: 113
>>  > 2018-02-07T00:13:00.431Z|01969|coverage|INFO|txn_success
>>    0.6/sec     0.050/sec        0.0119/sec   total: 51
>>  > 2018-02-07T00:13:00.431Z|01970|coverage|INFO|poll_create_node
>>  241.8/sec   164.833/sec      156.7022/sec   total: 637792
>>  > 2018-02-07T00:13:00.431Z|01971|coverage|INFO|poll_zero_timeout
>>    1.8/sec     0.367/sec        0.4589/sec   total: 1944
>>  > 2018-02-07T00:13:00.431Z|01972|coverage|INFO|rconn_queued
>>     1.2/sec     0.133/sec        0.0469/sec   total: 1219
>>  > 2018-02-07T00:13:00.431Z|01973|coverage|INFO|rconn_sent
>>     1.2/sec     0.133/sec        0.0469/sec   total: 1219
>>  > 2018-02-07T00:13:00.431Z|01974|coverage|INFO|seq_change
>>  2679.2/sec  1230.183/sec     1101.2081/sec   total: 4481090
>>  > 2018-02-07T00:13:00.431Z|01975|coverage|INFO|pstream_open
>>     0.0/sec     0.000/sec        0.0000/sec   total: 5
>>  > 2018-02-07T00:13:00.431Z|01976|coverage|INFO|stream_open
>>    0.0/sec     0.000/sec        0.0000/sec   total: 1
>>  > 2018-02-07T00:13:00.431Z|01977|coverage|INFO|util_xalloc
>>  6573732.0/sec 553875.117/sec    60700.1733/sec   total: 284890464
>>  > 2018-02-07T00:13:00.431Z|01978|coverage|INFO|vconn_received
>>    32.2/sec     2.717/sec        0.5306/sec   total: 6937
>>  > 2018-02-07T00:13:00.431Z|01979|coverage|INFO|vconn_sent
>>     1.2/sec     0.133/sec        0.0469/sec   total: 1221
>>  > 2018-02-07T00:13:00.431Z|01980|coverage|INFO|netlink_received
>>     0.0/sec     0.000/sec        0.0000/sec   total: 3
>>  > 2018-02-07T00:13:00.431Z|01981|coverage|INFO|netlink_sent
>>     0.0/sec     0.000/sec        0.0000/sec   total: 1
>>  > 2018-02-07T00:13:00.431Z|01982|coverage|INFO|57 events never hit
>>  > 2018-02-07T00:13:00.431Z|01983|poll_loop|INFO|Dropped 6 log messages
>> in last 217 seconds (most recently, 216 seconds ago) due to excessive rate
>>  > 2018-02-07T00:13:00.431Z|01984|poll_loop|INFO|wakeup due to [POLLIN]
>> on fd 112 (/root/sandbox-192.168.64.0/br-int.mgmt<->) at
>> ../lib/stream-fd.c:157 (90% CPU usage)
>>  >
>>  > I managed to capture a perf record when a ovs-vswitchd is spiking, not
>> sure if it helps:
>>  > Samples: 6K of event 'cycles:pp', Event count (approx.):
>> 118132588562209
>>  >   Children      Self  Command        Shared Object       Symbol
>>>>  > +   66.01%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] _start
>>>>  > +   66.01%     0.00%  ovs-vswitchd libc-2.23.so <http://libc-2.23.so>
>>        [.] __libc_start_main
>>>>  > +   66.01%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] main
>>>>  > +   66.01%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> bridge_run
>>>>  > +   66.01%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> bridge_run__
>>>>  > +   41.88%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> ofproto_type_run
>>>>  > +   41.88%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] type_run
>>>>  > +   24.13%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> bridge_reconfigure
>>>>  > +   24.13%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> ofproto_run
>>>>  > +   24.13%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> update_port
>>>>  > +   23.31%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> update_mtu
>>>>  > +   23.31%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> update_mtu_ofproto
>>>>  > +   23.31%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> ofport_is_mtu_overridden
>>>>  > +   23.27%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> xlate_txn_start
>>>>  > +   23.27%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> xlate_xport_copy
>>>>  > +   23.27%     0.00%  ovs-vswitchd   libjemalloc.so.1    [.] calloc
>>>>  > +   23.27%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] xcalloc
>>>>  > +   23.27%    23.27%  ovs-vswitchd libc-2.23.so <http://libc-2.23.so>
>>        [.] 0x000000000008f294
>>>>  > +   22.38%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> ofproto_class_find__
>>>>  > +   22.38%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> ofproto_port_open_type
>>>>  > +   20.96%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> dp_enumerate_types
>>>>  > +   20.14%    20.14%  ovs-vswitchd   libjemalloc.so.1    [.] malloc
>>>>  > +   19.43%     0.81%  ovs-vswitchd   ovs-vswitchd        [.]
>> ovs_mutex_lock_at
>>>>  > +   19.33%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> sset_add__
>>>>  > +   19.33%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] xmalloc
>>>>  > +   18.62%    18.62%  ovs-vswitchd libpthread-2.23.so <
>> http://libpthread-2.23.so>  [.] pthread_mutex_lock
>>>>  > +   18.61%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> dpif_netdev_run
>>>>  > +   18.61%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> dp_netdev_process_rxq_port
>>>>  > +   18.61%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> netdev_rxq_recv
>>>>  > +   18.61%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> netdev_dummy_rxq_recv
>>>>  > +   13.03%     0.00%  revalidator66  [kernel.kallsyms]   [k]
>> entry_SYSCALL_64_fastpath
>>>>  > +   13.03%     0.00%  revalidator66 libc-2.23.so <http://libc-2.23.so>
>>        [.] __clone
>>>>  > +   13.03%     0.00%  revalidator66 libpthread-2.23.so <
>> http://libpthread-2.23.so>  [.] start_thread
>>>>  >
>>  > Thanks,
>>  > Han
>>
>> Interestingly, I located the change that slows down the port-binding:
>> ===
>> commit 2d4beba14ae1075a7baf34fa57424edaf4eb7697
>> Author: Numan Siddique <nusiddiq at redhat.com <mailto:nusiddiq at redhat.com>>
>> Date:   Tue Sep 12 14:22:03 2017 +0530
>>
>>      ofproto: Include patch ports in mtu overriden check
>>
>>      When a patch port is deleted from the bridge (with no other ports
>>      in the bridge) and if the bridge was set to an MTU by the user
>> earlier, the
>>      MTU of the bridge is overriden to 1500. Please see the below link
>> for the
>>      steps to reproduce the issue.
>>
>>      This patch fixes this issue.
>>
>>      Reported-at: https://mail.openvswitch.org/p
>> ipermail/ovs-dev/2017-September/338665.html
>>      Signed-off-by: Numan Siddique <nusiddiq at redhat.com <mailto:
>> nusiddiq at redhat.com>>
>>      Signed-off-by: Ben Pfaff <blp at ovn.org <mailto:blp at ovn.org>>
>> ===
>>
>> It perfectly matches the perf output shared above when ovs-vswitchd is
>> running hot.
>>  > +   24.13%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> ofproto_run     ▒
>>  > +   24.13%     0.00%  ovs-vswitchd   ovs-vswitchd  [.] update_port
>>>>  > +   23.31%     0.00%  ovs-vswitchd   ovs-vswitchd      [.] update_mtu
>>>>  > +   23.31%     0.00%  ovs-vswitchd ovs-vswitchd        [.]
>> update_mtu_ofproto                              ▒
>>  > +   23.31%     0.00%  ovs-vswitchd   ovs-vswitchd        [.]
>> ofport_is_mtu_overridden                                              ▒
>> ...
>>
>> I will study more on the details of how it is triggered and look at how
>> to optimize it. Any suggestions are welcome.
>> cc Numan & Ben.
>>
>> Thanks,
>> Han
>>
>
> Hi Han,
>
> If you investigate the patch you referenced, it's fairly small. It adds an
> extra strcmp() call and an extra call to ofproto_port_open_type(). It's
> most likely the extra call to ofproto_port_open_type() is causing the extra
> CPU usage. Most of the processing done by calling it a second time is
> redundant.
>
> Patch one to optimize the behavior would be to factor out the common parts
> of ofproto_port_open_type() so that it may be called once. Then call the
> parts that differ for each port type. This should be simple. It would be
> worth testing again with this patch alone to see how much of an impact this
> makes.
>
> Patch two would be to start caching results of ofproto_port_open_type()
> locally since the result is not likely to differ between repeated calls.
> This would be a bit trickier to make 100% correct because you would need to
> be able to reliably detect when your cached value is "dirty". This patch
> would be worth pursuing if patch one does not do enough on its own.
>
> Mark!
>
> _______________________________________________
> discuss mailing list
> discuss at openvswitch.org
> https://mail.openvswitch.org/mailman/listinfo/ovs-discuss
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openvswitch.org/pipermail/ovs-discuss/attachments/20180219/1cd294a4/attachment-0001.html>


More information about the discuss mailing list