<div dir="ltr">Nice findings Han!<div>Looking back at the patch that Numan sent I answered this to the report:</div><div><br></div><div>&quot;Yes, thanks Numan for the patch :)<br><br>Another option would be that ovn-controller sets explicitly the MTU to 1450.<br>Not sure which of the two is the best or would have less side effects.<br><br>Cheers,<br>Daniel<br>&quot;<br></div><div><br></div><div>Would that be an option? We&#39;d be closing the loop around OVN but maybe</div><div>we still need it fixed wider at OVS level. Thoughts?</div><div><br></div><div>Daniel</div></div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, Feb 9, 2018 at 2:55 AM, Han Zhou <span dir="ltr">&lt;<a href="mailto:zhouhan@gmail.com" target="_blank">zhouhan@gmail.com</a>&gt;</span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div><div><div><div><div><div><div class="h5"><div><br><br>On Wed, Feb 7, 2018 at 12:47 PM, Han Zhou &lt;<a href="mailto:zhouhan@gmail.com" target="_blank">zhouhan@gmail.com</a>&gt; wrote:<br>&gt;<br>&gt; When doing scale testing for OVN (using <a href="https://github.com/openvswitch/ovn-scale-test" target="_blank">https://github.com/<wbr>openvswitch/ovn-scale-test</a>), we had some interesting findings, and need some help here.<br>&gt;<br>&gt; We ran the test &quot;create and bind lports&quot; 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.<br>&gt;<br>&gt; 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:<br>&gt;<br>&gt; 1. Create 5 new LSs in NB (so that the LSs will not be shared with any of HVs on other farm nodes)<br>&gt; 2. create 100 lports in NB on a LS<br>&gt; 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 &lt;port 1&gt; -- set Interface external-ids:...  -- add-port &lt;port 2&gt; -- set Interface external-ids:... (the script didn&#39;t set type to internal, but I hope it is not an issue for this test).<br>&gt; 4. wait the port stated changed to up in NB for all the 100 lports (with a single ovn-nbctl command)<br>&gt;<br>&gt; 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).<br>&gt;<br>&gt; 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.<br>&gt;<br>&gt; 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).<br>&gt;<br>&gt; 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:<br>&gt;<br>&gt; ======<br>&gt; 2018-02-07T00:12:54.558Z|<wbr>01767|bridge|INFO|bridge br-int: added interface lport_bc65cd_QFOU3v on port 1028<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01768|timeval|WARN|<wbr>Unreasonably long 1112ms poll interval (1016ms user, 4ms system)<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01769|timeval|WARN|faults: 336 minor, 0 major<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01770|timeval|WARN|context switches: 0 voluntary, 13 involuntary<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01771|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour,  hash=b256889c:<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01772|coverage|INFO|bridge_<wbr>reconfigure         0.0/sec     0.000/sec        0.0056/sec   total: 29<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01773|coverage|INFO|ofproto_<wbr>flush              0.0/sec     0.000/sec        0.0000/sec   total: 1<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01774|coverage|INFO|ofproto_<wbr>packet_out         0.0/sec     0.000/sec        0.0111/sec   total: 90<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01775|coverage|INFO|ofproto_<wbr>recv_openflow      0.2/sec     0.033/sec        0.4858/sec   total: 6673<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01776|coverage|INFO|ofproto_<wbr>update_port        0.0/sec     0.000/sec        5.5883/sec   total: 28258<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01777|coverage|INFO|rev_<wbr>reconfigure            0.0/sec     0.000/sec        0.0056/sec   total: 32<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01778|coverage|INFO|rev_port_<wbr>toggled           0.0/sec     0.000/sec        0.0011/sec   total: 6<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01779|coverage|INFO|rev_flow_<wbr>table             0.0/sec     0.000/sec        0.0078/sec   total: 124<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01780|coverage|INFO|rev_mac_<wbr>learning           0.0/sec     0.000/sec        0.0036/sec   total: 13<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01781|coverage|INFO|xlate_<wbr>actions              0.0/sec     0.000/sec        0.0111/sec   total: 90<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01782|coverage|INFO|ccmap_<wbr>expand               0.0/sec     0.000/sec        0.0050/sec   total: 36<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01783|coverage|INFO|ccmap_<wbr>shrink               0.0/sec     0.000/sec        0.0000/sec   total: 49<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01784|coverage|INFO|cmap_<wbr>expand                0.0/sec     0.000/sec        0.0217/sec   total: 257<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01785|coverage|INFO|cmap_<wbr>shrink                0.0/sec     0.000/sec        0.0000/sec   total: 141<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01786|coverage|INFO|dpif_port_<wbr>add              0.0/sec     0.000/sec        0.0022/sec   total: 1020<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01787|coverage|INFO|dpif_port_<wbr>del              0.0/sec     0.000/sec        0.0000/sec   total: 40<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01788|coverage|INFO|dpif_flow_<wbr>flush            0.0/sec     0.000/sec        0.0000/sec   total: 2<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01789|coverage|INFO|dpif_flow_<wbr>get              0.0/sec     0.000/sec        0.0000/sec   total: 20<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01790|coverage|INFO|dpif_flow_<wbr>put              0.0/sec     0.000/sec        0.0000/sec   total: 21<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01791|coverage|INFO|dpif_flow_<wbr>del              0.0/sec     0.000/sec        0.0000/sec   total: 20<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01792|coverage|INFO|dpif_<wbr>execute               0.0/sec     0.000/sec        0.0100/sec   total: 71<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01793|coverage|INFO|flow_<wbr>extract               0.0/sec     0.000/sec        0.0000/sec   total: 4<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01794|coverage|INFO|miniflow_<wbr>malloc            0.0/sec     0.000/sec        0.4361/sec   total: 6435<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01795|coverage|INFO|hindex_<wbr>pathological        0.0/sec     0.000/sec        0.0000/sec   total: 17<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01796|coverage|INFO|hindex_<wbr>expand              0.0/sec     0.000/sec        0.0000/sec   total: 9<br>&gt; 2018-02-07T00:12:55.629Z|<wbr>01797|coverage|INFO|hmap_<wbr>pathological          0.0/sec     0.000/sec        0.8131/sec   total: 13752<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01798|coverage|INFO|hmap_<wbr>expand               21.0/sec    18.333/sec    11253.0167/sec   total: 55905271<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01799|coverage|INFO|hmap_<wbr>shrink                0.0/sec     0.000/sec        0.0022/sec   total: 1029<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01800|coverage|INFO|mac_<wbr>learning_learned       0.0/sec     0.000/sec        0.0022/sec   total: 18<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01801|coverage|INFO|mac_<wbr>learning_expired       0.0/sec     0.000/sec        0.0017/sec   total: 6<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01802|coverage|INFO|netdev_<wbr>sent                0.0/sec     0.000/sec        0.0400/sec   total: 350<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01803|coverage|INFO|netdev_<wbr>get_stats         203.4/sec   203.400/sec      198.4978/sec   total: 798522<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01804|coverage|INFO|txn_<wbr>unchanged              0.2/sec     0.200/sec        0.1911/sec   total: 776<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01805|coverage|INFO|txn_<wbr>incomplete             0.0/sec     0.000/sec        0.0167/sec   total: 106<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01806|coverage|INFO|txn_<wbr>success                0.0/sec     0.000/sec        0.0111/sec   total: 48<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01807|coverage|INFO|poll_<wbr>create_node         162.6/sec   157.267/sec      156.3664/sec   total: 636465<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01808|coverage|INFO|poll_zero_<wbr>timeout          0.2/sec     0.250/sec        0.4564/sec   total: 1936<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01809|coverage|INFO|rconn_<wbr>queued               0.2/sec     0.033/sec        0.0453/sec   total: 1214<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01810|coverage|INFO|rconn_sent                 0.2/sec     0.033/sec        0.0453/sec   total: 1214<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01811|coverage|INFO|seq_change               1098.8/sec  1099.167/sec     1097.4869/sec   total: 4468823<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01812|coverage|INFO|pstream_<wbr>open               0.0/sec     0.000/sec        0.0000/sec   total: 5<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01813|coverage|INFO|stream_<wbr>open                0.0/sec     0.000/sec        0.0000/sec   total: 1<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01814|coverage|INFO|util_<wbr>xalloc              7223.8/sec  6527.317/sec    51569.9900/sec   total: 251999059<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01815|coverage|INFO|vconn_<wbr>received             0.2/sec     0.033/sec        0.4858/sec   total: 6675<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01816|coverage|INFO|vconn_sent                 0.2/sec     0.033/sec        0.0453/sec   total: 1216<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01817|coverage|INFO|netlink_<wbr>received           0.0/sec     0.000/sec        0.0000/sec   total: 3<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01818|coverage|INFO|netlink_<wbr>sent               0.0/sec     0.000/sec        0.0000/sec   total: 1<br>&gt; 2018-02-07T00:12:55.630Z|<wbr>01819|coverage|INFO|57 events never hit<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01820|timeval|WARN|<wbr>Unreasonably long 1112ms poll interval (948ms user, 4ms system)<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01821|timeval|WARN|faults: 7 minor, 0 major<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01822|timeval|WARN|context switches: 2 voluntary, 17 involuntary<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01823|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour,  hash=fcc57021:<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01824|coverage|INFO|bridge_<wbr>reconfigure         0.0/sec     0.000/sec        0.0056/sec   total: 30<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01825|coverage|INFO|ofproto_<wbr>flush              0.0/sec     0.000/sec        0.0000/sec   total: 1<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01826|coverage|INFO|ofproto_<wbr>packet_out         0.0/sec     0.000/sec        0.0111/sec   total: 90<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01827|coverage|INFO|ofproto_<wbr>recv_openflow      0.2/sec     0.033/sec        0.4858/sec   total: 6683<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01828|coverage|INFO|ofproto_<wbr>update_port        0.0/sec     0.000/sec        5.5883/sec   total: 29268<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01829|coverage|INFO|rev_<wbr>reconfigure            0.0/sec     0.000/sec        0.0056/sec   total: 33<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01830|coverage|INFO|rev_port_<wbr>toggled           0.0/sec     0.000/sec        0.0011/sec   total: 6<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01831|coverage|INFO|rev_flow_<wbr>table             0.0/sec     0.000/sec        0.0078/sec   total: 124<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01832|coverage|INFO|rev_mac_<wbr>learning           0.0/sec     0.000/sec        0.0036/sec   total: 13<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01833|coverage|INFO|xlate_<wbr>actions              0.0/sec     0.000/sec        0.0111/sec   total: 90<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01834|coverage|INFO|ccmap_<wbr>expand               0.0/sec     0.000/sec        0.0050/sec   total: 36<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01835|coverage|INFO|ccmap_<wbr>shrink               0.0/sec     0.000/sec        0.0000/sec   total: 49<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01836|coverage|INFO|cmap_<wbr>expand                0.0/sec     0.000/sec        0.0217/sec   total: 257<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01837|coverage|INFO|cmap_<wbr>shrink                0.0/sec     0.000/sec        0.0000/sec   total: 141<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01838|coverage|INFO|dpif_port_<wbr>add              0.0/sec     0.000/sec        0.0022/sec   total: 1020<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01839|coverage|INFO|dpif_port_<wbr>del              0.0/sec     0.000/sec        0.0000/sec   total: 40<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01840|coverage|INFO|dpif_flow_<wbr>flush            0.0/sec     0.000/sec        0.0000/sec   total: 2<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01841|coverage|INFO|dpif_flow_<wbr>get              0.0/sec     0.000/sec        0.0000/sec   total: 20<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01842|coverage|INFO|dpif_flow_<wbr>put              0.0/sec     0.000/sec        0.0000/sec   total: 21<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01843|coverage|INFO|dpif_flow_<wbr>del              0.0/sec     0.000/sec        0.0000/sec   total: 20<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01844|coverage|INFO|dpif_<wbr>execute               0.0/sec     0.000/sec        0.0100/sec   total: 71<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01845|coverage|INFO|flow_<wbr>extract               0.0/sec     0.000/sec        0.0000/sec   total: 4<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01846|coverage|INFO|miniflow_<wbr>malloc            0.0/sec     0.000/sec        0.4361/sec   total: 6440<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01847|coverage|INFO|hindex_<wbr>pathological        0.0/sec     0.000/sec        0.0000/sec   total: 17<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01848|coverage|INFO|hindex_<wbr>expand              0.0/sec     0.000/sec        0.0000/sec   total: 9<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01849|coverage|INFO|hmap_<wbr>pathological          0.0/sec     0.000/sec        0.8131/sec   total: 13825<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01850|coverage|INFO|hmap_<wbr>expand               21.0/sec    18.333/sec    11253.0167/sec   total: 57949607<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01851|coverage|INFO|hmap_<wbr>shrink                0.0/sec     0.000/sec        0.0022/sec   total: 1029<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01852|coverage|INFO|mac_<wbr>learning_learned       0.0/sec     0.000/sec        0.0022/sec   total: 18<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01853|coverage|INFO|mac_<wbr>learning_expired       0.0/sec     0.000/sec        0.0017/sec   total: 6<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01854|coverage|INFO|netdev_<wbr>sent                0.0/sec     0.000/sec        0.0400/sec   total: 350<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01855|coverage|INFO|netdev_<wbr>get_stats         203.4/sec   203.400/sec      198.4978/sec   total: 799540<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01856|coverage|INFO|txn_<wbr>unchanged              0.2/sec     0.200/sec        0.1911/sec   total: 777<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01857|coverage|INFO|txn_<wbr>incomplete             0.0/sec     0.000/sec        0.0167/sec   total: 108<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01858|coverage|INFO|txn_<wbr>success                0.0/sec     0.000/sec        0.0111/sec   total: 49<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01859|coverage|INFO|poll_<wbr>create_node         162.6/sec   157.267/sec      156.3664/sec   total: 636681<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01860|coverage|INFO|poll_zero_<wbr>timeout          0.2/sec     0.250/sec        0.4564/sec   total: 1937<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01861|coverage|INFO|rconn_<wbr>queued               0.2/sec     0.033/sec        0.0453/sec   total: 1216<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01862|coverage|INFO|rconn_sent                 0.2/sec     0.033/sec        0.0453/sec   total: 1216<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01863|coverage|INFO|seq_change               1098.8/sec  1099.167/sec     1097.4869/sec   total: 4471434<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01864|coverage|INFO|pstream_<wbr>open               0.0/sec     0.000/sec        0.0000/sec   total: 5<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01865|coverage|INFO|stream_<wbr>open                0.0/sec     0.000/sec        0.0000/sec   total: 1<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01866|coverage|INFO|util_<wbr>xalloc              7223.8/sec  6527.317/sec    51569.9900/sec   total: 260206006<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01867|coverage|INFO|vconn_<wbr>received             0.2/sec     0.033/sec        0.4858/sec   total: 6685<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01868|coverage|INFO|vconn_sent                 0.2/sec     0.033/sec        0.0453/sec   total: 1218<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01869|coverage|INFO|netlink_<wbr>received           0.0/sec     0.000/sec        0.0000/sec   total: 3<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01870|coverage|INFO|netlink_<wbr>sent               0.0/sec     0.000/sec        0.0000/sec   total: 1<br>&gt; 2018-02-07T00:12:56.761Z|<wbr>01871|coverage|INFO|57 events never hit<br>&gt; 2018-02-07T00:12:57.054Z|<wbr>01872|bridge|INFO|bridge br-int: added interface lport_bc65cd_lykjnm on port 1029<br>&gt; 2018-02-07T00:12:58.202Z|<wbr>01873|timeval|WARN|<wbr>Unreasonably long 1179ms poll interval (1032ms user, 0ms system)<br>&gt; 2018-02-07T00:12:58.202Z|<wbr>01874|timeval|WARN|faults: 41 minor, 0 major<br>&gt; 2018-02-07T00:12:58.202Z|<wbr>01875|timeval|WARN|context switches: 0 voluntary, 19 involuntary<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01876|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour,  hash=668121b0:<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01877|coverage|INFO|bridge_<wbr>reconfigure         0.0/sec     0.000/sec        0.0056/sec   total: 31<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01878|coverage|INFO|ofproto_<wbr>flush              0.0/sec     0.000/sec        0.0000/sec   total: 1<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01879|coverage|INFO|ofproto_<wbr>packet_out         0.0/sec     0.000/sec        0.0111/sec   total: 90<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01880|coverage|INFO|ofproto_<wbr>recv_openflow      0.2/sec     0.033/sec        0.4858/sec   total: 6733<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01881|coverage|INFO|ofproto_<wbr>update_port        0.0/sec     0.000/sec        5.5883/sec   total: 30279<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01882|coverage|INFO|rev_<wbr>reconfigure            0.0/sec     0.000/sec        0.0056/sec   total: 34<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01883|coverage|INFO|rev_port_<wbr>toggled           0.0/sec     0.000/sec        0.0011/sec   total: 6<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01884|coverage|INFO|rev_flow_<wbr>table             0.0/sec     0.000/sec        0.0078/sec   total: 125<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01885|coverage|INFO|rev_mac_<wbr>learning           0.0/sec     0.000/sec        0.0036/sec   total: 13<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01886|coverage|INFO|xlate_<wbr>actions              0.0/sec     0.000/sec        0.0111/sec   total: 90<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01887|coverage|INFO|ccmap_<wbr>expand               0.0/sec     0.000/sec        0.0050/sec   total: 36<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01888|coverage|INFO|ccmap_<wbr>shrink               0.0/sec     0.000/sec        0.0000/sec   total: 49<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01889|coverage|INFO|cmap_<wbr>expand                0.0/sec     0.000/sec        0.0217/sec   total: 260<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01890|coverage|INFO|cmap_<wbr>shrink                0.0/sec     0.000/sec        0.0000/sec   total: 141<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01891|coverage|INFO|dpif_port_<wbr>add              0.0/sec     0.000/sec        0.0022/sec   total: 1021<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01892|coverage|INFO|dpif_port_<wbr>del              0.0/sec     0.000/sec        0.0000/sec   total: 40<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01893|coverage|INFO|dpif_flow_<wbr>flush            0.0/sec     0.000/sec        0.0000/sec   total: 2<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01894|coverage|INFO|dpif_flow_<wbr>get              0.0/sec     0.000/sec        0.0000/sec   total: 20<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01895|coverage|INFO|dpif_flow_<wbr>put              0.0/sec     0.000/sec        0.0000/sec   total: 21<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01896|coverage|INFO|dpif_flow_<wbr>del              0.0/sec     0.000/sec        0.0000/sec   total: 20<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01897|coverage|INFO|dpif_<wbr>execute               0.0/sec     0.000/sec        0.0100/sec   total: 71<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01898|coverage|INFO|flow_<wbr>extract               0.0/sec     0.000/sec        0.0000/sec   total: 4<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01899|coverage|INFO|miniflow_<wbr>malloc            0.0/sec     0.000/sec        0.4361/sec   total: 6489<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01900|coverage|INFO|hindex_<wbr>pathological        0.0/sec     0.000/sec        0.0000/sec   total: 17<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01901|coverage|INFO|hindex_<wbr>expand              0.0/sec     0.000/sec        0.0000/sec   total: 9<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01902|coverage|INFO|hmap_<wbr>pathological          0.0/sec     0.000/sec        0.8131/sec   total: 13945<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01903|coverage|INFO|hmap_<wbr>expand               21.0/sec    18.333/sec    11253.0167/sec   total: 59998044<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01904|coverage|INFO|hmap_<wbr>shrink                0.0/sec     0.000/sec        0.0022/sec   total: 1030<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01905|coverage|INFO|mac_<wbr>learning_learned       0.0/sec     0.000/sec        0.0022/sec   total: 18<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01906|coverage|INFO|mac_<wbr>learning_expired       0.0/sec     0.000/sec        0.0017/sec   total: 6<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01907|coverage|INFO|netdev_<wbr>sent                0.0/sec     0.000/sec        0.0400/sec   total: 350<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01908|coverage|INFO|netdev_<wbr>get_stats         203.4/sec   203.400/sec      198.4978/sec   total: 799541<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01909|coverage|INFO|txn_<wbr>unchanged              0.2/sec     0.200/sec        0.1911/sec   total: 777<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01910|coverage|INFO|txn_<wbr>incomplete             0.0/sec     0.000/sec        0.0167/sec   total: 110<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01911|coverage|INFO|txn_<wbr>success                0.0/sec     0.000/sec        0.0111/sec   total: 50<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01912|coverage|INFO|poll_<wbr>create_node         162.6/sec   157.267/sec      156.3664/sec   total: 636974<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01913|coverage|INFO|poll_zero_<wbr>timeout          0.2/sec     0.250/sec        0.4564/sec   total: 1939<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01914|coverage|INFO|rconn_<wbr>queued               0.2/sec     0.033/sec        0.0453/sec   total: 1217<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01915|coverage|INFO|rconn_sent                 0.2/sec     0.033/sec        0.0453/sec   total: 1217<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01916|coverage|INFO|seq_change               1098.8/sec  1099.167/sec     1097.4869/sec   total: 4474605<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01917|coverage|INFO|pstream_<wbr>open               0.0/sec     0.000/sec        0.0000/sec   total: 5<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01918|coverage|INFO|stream_<wbr>open                0.0/sec     0.000/sec        0.0000/sec   total: 1<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01919|coverage|INFO|util_<wbr>xalloc              7223.8/sec  6527.317/sec    51569.9900/sec   total: 268435993<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01920|coverage|INFO|vconn_<wbr>received             0.2/sec     0.033/sec        0.4858/sec   total: 6735<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01921|coverage|INFO|vconn_sent                 0.2/sec     0.033/sec        0.0453/sec   total: 1219<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01922|coverage|INFO|netlink_<wbr>received           0.0/sec     0.000/sec        0.0000/sec   total: 3<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01923|coverage|INFO|netlink_<wbr>sent               0.0/sec     0.000/sec        0.0000/sec   total: 1<br>&gt; 2018-02-07T00:12:58.203Z|<wbr>01924|coverage|INFO|57 events never hit<br>&gt; 2018-02-07T00:12:58.221Z|<wbr>01925|bridge|INFO|bridge br-int: added interface patch-br-int-to-provnet-<wbr>lswitch_bc65cd_Y7sqEw on port 1030<br>&gt; 2018-02-07T00:12:58.221Z|<wbr>01926|bridge|INFO|bridge br0: added interface patch-provnet-lswitch_bc65cd_<wbr>Y7sqEw-to-br-int on port 15<br>&gt; 2018-02-07T00:12:59.313Z|<wbr>01927|timeval|WARN|<wbr>Unreasonably long 1111ms poll interval (1092ms user, 0ms system)<br>&gt; 2018-02-07T00:12:59.313Z|<wbr>01928|timeval|WARN|faults: 45 minor, 0 major<br>&gt; 2018-02-07T00:12:59.313Z|<wbr>01929|timeval|WARN|context switches: 6 voluntary, 59 involuntary<br>&gt; 2018-02-07T00:12:59.313Z|<wbr>01930|coverage|INFO|Skipping details of duplicate event coverage for hash=668121b0<br>&gt; 2018-02-07T00:13:00.430Z|<wbr>01931|timeval|WARN|<wbr>Unreasonably long 1117ms poll interval (1112ms user, 0ms system)<br>&gt; 2018-02-07T00:13:00.430Z|<wbr>01932|timeval|WARN|faults: 34 minor, 0 major<br>&gt; 2018-02-07T00:13:00.430Z|<wbr>01933|timeval|WARN|context switches: 2 voluntary, 11 involuntary<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01934|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour,  hash=a612a6e0:<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01935|coverage|INFO|bridge_<wbr>reconfigure         0.8/sec     0.067/sec        0.0067/sec   total: 33<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01936|coverage|INFO|ofproto_<wbr>flush              0.0/sec     0.000/sec        0.0000/sec   total: 1<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01937|coverage|INFO|ofproto_<wbr>packet_out         0.2/sec     0.017/sec        0.0114/sec   total: 92<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01938|coverage|INFO|ofproto_<wbr>recv_openflow     32.2/sec     2.717/sec        0.5306/sec   total: 6935<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01939|coverage|INFO|ofproto_<wbr>update_port      808.8/sec    67.400/sec        6.7117/sec   total: 32303<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01940|coverage|INFO|rev_<wbr>reconfigure            0.8/sec     0.067/sec        0.0067/sec   total: 36<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01941|coverage|INFO|rev_port_<wbr>toggled           0.0/sec     0.000/sec        0.0011/sec   total: 7<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01942|coverage|INFO|rev_flow_<wbr>table             0.4/sec     0.033/sec        0.0083/sec   total: 126<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01943|coverage|INFO|rev_mac_<wbr>learning           0.0/sec     0.000/sec        0.0036/sec   total: 13<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01944|coverage|INFO|xlate_<wbr>actions              0.2/sec     0.017/sec        0.0114/sec   total: 92<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01945|coverage|INFO|ccmap_<wbr>expand               0.0/sec     0.000/sec        0.0050/sec   total: 36<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01946|coverage|INFO|ccmap_<wbr>shrink               0.0/sec     0.000/sec        0.0000/sec   total: 49<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01947|coverage|INFO|cmap_<wbr>expand                2.0/sec     0.167/sec        0.0244/sec   total: 271<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01948|coverage|INFO|cmap_<wbr>shrink                0.0/sec     0.000/sec        0.0000/sec   total: 141<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01949|coverage|INFO|dpif_port_<wbr>add              0.4/sec     0.033/sec        0.0028/sec   total: 1021<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01950|coverage|INFO|dpif_port_<wbr>del              0.0/sec     0.000/sec        0.0000/sec   total: 40<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01951|coverage|INFO|dpif_flow_<wbr>flush            0.0/sec     0.000/sec        0.0000/sec   total: 2<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01952|coverage|INFO|dpif_flow_<wbr>get              0.0/sec     0.000/sec        0.0000/sec   total: 20<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01953|coverage|INFO|dpif_flow_<wbr>put              0.0/sec     0.000/sec        0.0000/sec   total: 21<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01954|coverage|INFO|dpif_flow_<wbr>del              0.0/sec     0.000/sec        0.0000/sec   total: 20<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01955|coverage|INFO|dpif_<wbr>execute               0.0/sec     0.000/sec        0.0100/sec   total: 72<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01956|coverage|INFO|flow_<wbr>extract               0.0/sec     0.000/sec        0.0000/sec   total: 4<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01957|coverage|INFO|miniflow_<wbr>malloc           30.8/sec     2.567/sec        0.4789/sec   total: 6689<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01958|coverage|INFO|hindex_<wbr>pathological        0.0/sec     0.000/sec        0.0000/sec   total: 17<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01959|coverage|INFO|hindex_<wbr>expand              0.0/sec     0.000/sec        0.0000/sec   total: 9<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01960|coverage|INFO|hmap_<wbr>pathological         76.8/sec     6.400/sec        0.9197/sec   total: 14149<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01961|coverage|INFO|hmap_<wbr>expand              1637509.8/sec 136476.267/sec    13527.3358/sec   total: 64098893<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01962|coverage|INFO|hmap_<wbr>shrink                0.4/sec     0.033/sec        0.0028/sec   total: 1030<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01963|coverage|INFO|mac_<wbr>learning_learned       0.0/sec     0.000/sec        0.0022/sec   total: 19<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01964|coverage|INFO|mac_<wbr>learning_expired       0.0/sec     0.000/sec        0.0017/sec   total: 6<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01965|coverage|INFO|netdev_<wbr>sent                0.0/sec     0.000/sec        0.0400/sec   total: 359<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01966|coverage|INFO|netdev_<wbr>get_stats         204.4/sec   203.483/sec      198.7817/sec   total: 799543<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01967|coverage|INFO|txn_<wbr>unchanged              0.2/sec     0.200/sec        0.1914/sec   total: 777<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01968|coverage|INFO|txn_<wbr>incomplete             1.4/sec     0.117/sec        0.0186/sec   total: 113<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01969|coverage|INFO|txn_<wbr>success                0.6/sec     0.050/sec        0.0119/sec   total: 51<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01970|coverage|INFO|poll_<wbr>create_node         241.8/sec   164.833/sec      156.7022/sec   total: 637792<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01971|coverage|INFO|poll_zero_<wbr>timeout          1.8/sec     0.367/sec        0.4589/sec   total: 1944<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01972|coverage|INFO|rconn_<wbr>queued               1.2/sec     0.133/sec        0.0469/sec   total: 1219<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01973|coverage|INFO|rconn_sent                 1.2/sec     0.133/sec        0.0469/sec   total: 1219<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01974|coverage|INFO|seq_change               2679.2/sec  1230.183/sec     1101.2081/sec   total: 4481090<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01975|coverage|INFO|pstream_<wbr>open               0.0/sec     0.000/sec        0.0000/sec   total: 5<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01976|coverage|INFO|stream_<wbr>open                0.0/sec     0.000/sec        0.0000/sec   total: 1<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01977|coverage|INFO|util_<wbr>xalloc              6573732.0/sec 553875.117/sec    60700.1733/sec   total: 284890464<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01978|coverage|INFO|vconn_<wbr>received            32.2/sec     2.717/sec        0.5306/sec   total: 6937<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01979|coverage|INFO|vconn_sent                 1.2/sec     0.133/sec        0.0469/sec   total: 1221<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01980|coverage|INFO|netlink_<wbr>received           0.0/sec     0.000/sec        0.0000/sec   total: 3<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01981|coverage|INFO|netlink_<wbr>sent               0.0/sec     0.000/sec        0.0000/sec   total: 1<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01982|coverage|INFO|57 events never hit<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01983|poll_loop|INFO|Dropped 6 log messages in last 217 seconds (most recently, 216 seconds ago) due to excessive rate<br>&gt; 2018-02-07T00:13:00.431Z|<wbr>01984|poll_loop|INFO|wakeup due to [POLLIN] on fd 112 (/root/sandbox-192.168.64.0/<wbr>br-int.mgmt&lt;-&gt;) at ../lib/stream-fd.c:157 (90% CPU usage)<br>&gt;<br>&gt; I managed to capture a perf record when a ovs-vswitchd is spiking, not sure if it helps:<br>&gt; Samples: 6K of event &#39;cycles:pp&#39;, Event count (approx.): 118132588562209<br>&gt;   Children      Self  Command        Shared Object       Symbol                                                                            ◆<br>&gt; +   66.01%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] _start                                                                        ▒<br>&gt; +   66.01%     0.00%  ovs-vswitchd   <a href="http://libc-2.23.so" target="_blank">libc-2.23.so</a>        [.] __libc_start_main                                                             ▒<br>&gt; +   66.01%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] main                                                                          ▒<br>&gt; +   66.01%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] bridge_run                                                                    ▒<br>&gt; +   66.01%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] bridge_run__                                                                  ▒<br>&gt; +   41.88%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] ofproto_type_run                                                              ▒<br>&gt; +   41.88%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] type_run                                                                      ▒<br>&gt; +   24.13%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] bridge_reconfigure                                                            ▒<br>&gt; +   24.13%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] ofproto_run                                                                   ▒<br>&gt; +   24.13%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] update_port                                                                   ▒<br>&gt; +   23.31%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] update_mtu                                                                    ▒<br>&gt; +   23.31%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] update_mtu_ofproto                                                            ▒<br>&gt; +   23.31%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] ofport_is_mtu_overridden                                                      ▒<br>&gt; +   23.27%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] xlate_txn_start                                                               ▒<br>&gt; +   23.27%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] xlate_xport_copy                                                              ▒<br>&gt; +   23.27%     0.00%  ovs-vswitchd   libjemalloc.so.1    [.] calloc                                                                        ▒<br>&gt; +   23.27%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] xcalloc                                                                       ▒<br>&gt; +   23.27%    23.27%  ovs-vswitchd   <a href="http://libc-2.23.so" target="_blank">libc-2.23.so</a>        [.] 0x000000000008f294                                                            ▒<br>&gt; +   22.38%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] ofproto_class_find__                                                          ▒<br>&gt; +   22.38%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] ofproto_port_open_type                                                        ▒<br>&gt; +   20.96%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] dp_enumerate_types                                                            ▒<br>&gt; +   20.14%    20.14%  ovs-vswitchd   libjemalloc.so.1    [.] malloc                                                                        ▒<br>&gt; +   19.43%     0.81%  ovs-vswitchd   ovs-vswitchd        [.] ovs_mutex_lock_at                                                             ▒<br>&gt; +   19.33%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] sset_add__                                                                    ▒<br>&gt; +   19.33%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] xmalloc                                                                       ▒<br>&gt; +   18.62%    18.62%  ovs-vswitchd   <a href="http://libpthread-2.23.so" target="_blank">libpthread-2.23.so</a>  [.] pthread_mutex_lock                                                            ▒<br>&gt; +   18.61%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] dpif_netdev_run                                                               ▒<br>&gt; +   18.61%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] dp_netdev_process_rxq_port                                                    ▒<br>&gt; +   18.61%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] netdev_rxq_recv                                                               ▒<br>&gt; +   18.61%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] netdev_dummy_rxq_recv                                                         ▒<br>&gt; +   13.03%     0.00%  revalidator66  [kernel.kallsyms]   [k] entry_SYSCALL_64_fastpath                                                     ▒<br>&gt; +   13.03%     0.00%  revalidator66  <a href="http://libc-2.23.so" target="_blank">libc-2.23.so</a>        [.] __clone                                                                       ▒<br>&gt; +   13.03%     0.00%  revalidator66  <a href="http://libpthread-2.23.so" target="_blank">libpthread-2.23.so</a>  [.] start_thread                                                                  ▒<br>&gt;<br>&gt; Thanks,<br>&gt; Han<br><br></div></div></div>Interestingly, I located the change that slows down the port-binding:<br>===<br>commit 2d4beba14ae1075a7baf34fa57424e<wbr>daf4eb7697<br>Author: Numan Siddique &lt;<a href="mailto:nusiddiq@redhat.com" target="_blank">nusiddiq@redhat.com</a>&gt;<br>Date:   Tue Sep 12 14:22:03 2017 +0530<br><br>    ofproto: Include patch ports in mtu overriden check<br>    <br>    When a patch port is deleted from the bridge (with no other ports<br>    in the bridge) and if the bridge was set to an MTU by the user earlier, the<br>    MTU of the bridge is overriden to 1500. Please see the below link for the<br>    steps to reproduce the issue.<br>    <br>    This patch fixes this issue.<br>    <br>    Reported-at: <a href="https://mail.openvswitch.org/pipermail/ovs-dev/2017-September/338665.html" target="_blank">https://mail.openvswitch.org/<wbr>pipermail/ovs-dev/2017-<wbr>September/338665.html</a><br>    Signed-off-by: Numan Siddique &lt;<a href="mailto:nusiddiq@redhat.com" target="_blank">nusiddiq@redhat.com</a>&gt;<br>    Signed-off-by: Ben Pfaff &lt;<a href="mailto:blp@ovn.org" target="_blank">blp@ovn.org</a>&gt;<br>===<br><br></div>It perfectly matches the perf output shared above when ovs-vswitchd is running hot.<span class=""><br>&gt; +   24.13%     0.00%  ovs-vswitchd   ovs-vswitchd        [.] 
ofproto_run                                                              
     ▒<br>&gt; +   24.13%     0.00%  ovs-vswitchd   ovs-vswitchd       
 [.] update_port                                                        
           ▒<br>&gt; +   23.31%     0.00%  ovs-vswitchd   ovs-vswitchd  
      [.] update_mtu                                                    
                ▒<br>&gt; +   23.31%     0.00%  ovs-vswitchd   
ovs-vswitchd        [.] update_mtu_ofproto                              
                              ▒<br>&gt; +   23.31%     0.00% 
 ovs-vswitchd   ovs-vswitchd        [.] ofport_is_mtu_overridden        
                                              ▒<br></span>...<br><br></div>I will study more on the details of how it is triggered and look at how to optimize it. Any suggestions are welcome.<br></div>cc Numan &amp; Ben.<br><br></div>Thanks,<br></div>Han<br><div><div><div><br></div></div></div></div>
<br>______________________________<wbr>_________________<br>
discuss mailing list<br>
<a href="mailto:discuss@openvswitch.org">discuss@openvswitch.org</a><br>
<a href="https://mail.openvswitch.org/mailman/listinfo/ovs-discuss" rel="noreferrer" target="_blank">https://mail.openvswitch.org/<wbr>mailman/listinfo/ovs-discuss</a><br>
<br></blockquote></div><br></div>