<html><head><meta http-equiv="Content-Type" content="text/html; charset=utf-8"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; line-break: after-white-space;" class=""><div dir="auto" style="word-wrap: break-word; -webkit-nbsp-mode: space; line-break: after-white-space;" class="">Hi <span style="orphans: 2; white-space: pre-wrap; widows: 2;" class="">OVS-team,</span><div class=""><br class=""></div><div class="">We <span style="orphans: 2; white-space: pre-wrap; widows: 2;" class="">had just met a problem in our customer environments, Neutron HA router active/standby had switched after high ovs-vswitchd cpu usage.</span></div><div class=""><span style="orphans: 2; white-space: pre-wrap; widows: 2;" class=""><br class=""></span></div><div class=""><span style="orphans: 2; white-space: pre-wrap; widows: 2;" class="">From the ovs-vswitchd log:</span></div><div class=""><span style="orphans: 2; widows: 2; white-space: pre-wrap;" class="">2021-07-22T23:35:00.282Z|420006320|bridge|INFO|bridge br-int: deleted interface tapb3eee529-02 on port 1017
2021-07-22T23:35:00.318Z|420006321|bridge|INFO|bridge br-int: added interface tapc257bed3-fc on port 1024
2021-07-22T23:35:00.366Z|420006322|bridge|INFO|bridge br-int: added interface tap7c1963c9-32 on port 934
2021-07-22T23:35:00.403Z|420006323|bridge|INFO|bridge br-int: added interface tap5de0f4ed-70 on port 1094
2021-07-22T23:35:00.441Z|420006324|bridge|INFO|bridge br-int: added interface tap76421ff2-e1 on port 990
2021-07-22T23:35:00.487Z|420006325|bridge|INFO|bridge br-int: added interface tap71a4dae8-75 on port 1084
2021-07-22T23:35:00.516Z|420006326|bridge|INFO|bridge br-int: added interface tapd3177fe4-19 on port 956
2021-07-22T23:35:00.558Z|420006327|bridge|INFO|bridge br-int: added interface tapb3eee529-02 on port 1017
2021-07-22T23:35:00.880Z|420006328|bridge|INFO|bridge br-int: deleted interface tap64c1f4fe-8b on port 1024
2021-07-22T23:35:00.881Z|420006329|bridge|INFO|bridge br-int: deleted interface tap29b6ec20-65 on port 990
2021-07-22T23:35:00.882Z|420006330|bridge|INFO|bridge br-int: deleted interface tap7f5e65fd-59 on port 1084
2021-07-22T23:35:00.883Z|420006331|bridge|INFO|bridge br-int: deleted interface tape3046139-8c on port 934
2021-07-22T23:35:00.884Z|420006332|bridge|INFO|bridge br-int: deleted interface tap9eba01c2-54 on port 1017
2021-07-22T23:35:00.885Z|420006333|bridge|INFO|bridge br-int: deleted interface tap26652576-4e on port 1094
2021-07-22T23:35:00.885Z|420006334|bridge|INFO|bridge br-int: deleted interface tap7799343f-22 on port 956
2021-07-22T23:35:00.983Z|420006335|bridge|INFO|bridge br-int: added interface tap64c1f4fe-8b on port 1024
2021-07-22T23:35:01.056Z|420006336|bridge|INFO|bridge br-int: added interface tap29b6ec20-65 on port 990
2021-07-22T23:35:01.101Z|420006337|bridge|INFO|bridge br-int: added interface tap7f5e65fd-59 on port 1084
2021-07-22T23:35:01.206Z|420006338|bridge|INFO|bridge br-int: added interface tape3046139-8c on port 934
2021-07-22T23:35:01.297Z|420006339|bridge|INFO|bridge br-int: added interface tap9eba01c2-54 on port 1017
2021-07-22T23:35:01.657Z|420006340|bridge|INFO|bridge br-int: added interface tap26652576-4e on port 1094
2021-07-22T23:35:01.733Z|02155|ofproto_dpif_upcall(handler228)|WARN|Dropped 9793 log messages in last 62 seconds (most recently, 2 seconds ago) due to excessive rate
2021-07-22T23:35:01.733Z|02156|ofproto_dpif_upcall(handler228)|WARN|upcall: datapath flow limit reached
2021-07-22T23:35:02.395Z|420006341|bridge|INFO|bridge br-int: added interface tap7799343f-22 on port 956
2021-07-22T23:35:03.363Z|00328|ovs_rcu(urcu9)|WARN|blocked 1000 ms waiting for handler196 to quiesce
2021-07-22T23:35:03.398Z|420006342|ovs_rcu|WARN|blocked 1000 ms waiting for handler196 to quiesce
2021-07-22T23:35:03.413Z|138790|timeval(handler196)|WARN|Unreasonably long 1049ms poll interval (0ms user, 763ms system)
2021-07-22T23:35:03.413Z|138791|timeval(handler196)|WARN|context switches: 236 voluntary, 107 involuntary
2021-07-22T23:35:03.413Z|138792|coverage(handler196)|INFO|Skipping details of duplicate event coverage for hash=ec24845d
2021-07-22T23:35:05.222Z|420006343|ovs_rcu|WARN|blocked 1000 ms waiting for handler196 to quiesce
2021-07-22T23:35:05.224Z|00329|ovs_rcu(urcu9)|WARN|blocked 1001 ms waiting for handler196 to quiesce
2021-07-22T23:35:05.492Z|138793|timeval(handler196)|WARN|Unreasonably long 1272ms poll interval (0ms user, 982ms system)
2021-07-22T23:35:05.492Z|138794|timeval(handler196)|WARN|context switches: 240 voluntary, 104 involuntary
2021-07-22T23:35:05.492Z|138795|coverage(handler196)|INFO|Skipping details of duplicate event coverage for hash=ec24845d
2021-07-22T23:35:05.492Z|138796|poll_loop(handler196)|INFO|Dropped 1088 log messages in last 6 seconds (most recently, 4 seconds ago) due to excessive rate
2021-07-22T23:35:05.492Z|138797|poll_loop(handler196)|INFO|wakeup due to 0-ms timeout at ofproto/ofproto-dpif-upcall.c:752 (79% CPU usage)
2021-07-22T23:35:09.472Z|138798|poll_loop(handler196)|INFO|Dropped 6 log messages in last 4 seconds (most recently, 1 seconds ago) due to excessive rate
2021-07-22T23:35:09.473Z|138799|poll_loop(handler196)|INFO|wakeup due to 0-ms timeout at ofproto/ofproto-dpif-upcall.c:752 (78% CPU usage)
2021-07-22T23:35:09.473Z|138800|dpif_netlink(handler196)|WARN|system@ovs-system: lost packet on port channel 44 of handler 2
2021-07-22T23:35:09.501Z|420006344|bridge|INFO|bridge br-int: deleted interface tapc257bed3-fc on port 1024
2021-07-22T23:35:10.473Z|00330|ovs_rcu(urcu9)|WARN|blocked 1000 ms waiting for handler196 to quiesce
2021-07-22T23:35:10.501Z|420006345|ovs_rcu|WARN|blocked 1000 ms waiting for handler196 to quiesce
2021-07-22T23:35:11.473Z|00331|ovs_rcu(urcu9)|WARN|blocked 2000 ms waiting for handler196 to quiesce</span></div><div class=""><span style="orphans: 2; widows: 2; white-space: pre-wrap;" class=""><br class=""></span></div><div class=""><span style="orphans: 2; widows: 2; white-space: pre-wrap;" class="">In the time </span><span style="orphans: 2; white-space: pre-wrap; widows: 2;" class="">23:35:05(UTC time), the </span><span style="orphans: 2; widows: 2;" class=""><span style="white-space: pre-wrap;" class="">handler196 thread cpu usage has high value 79%. Before that time the </span></span><span style="color: rgb(37, 37, 37); orphans: 2; widows: 2; background-color: rgb(255, 255, 255);" class="">log displays blocked handler threads and involuntary context switches.</span></div><div class=""><span style="color: rgb(37, 37, 37); orphans: 2; widows: 2; background-color: rgb(255, 255, 255);" class="">Also there is </span><font color="#252525" class=""><span style="caret-color: rgb(37, 37, 37);" class="">strange behavior, different tap devices added or deleted on the same ovs ofport, the same tap device occurs 50+ times in 1 minutes:</span></font></div><div class=""><span style="orphans: 2; white-space: pre-wrap; widows: 2;" class="">bridge br-int: added interface tapc257bed3-fc on port 1024</span></div><div class=""><span style="orphans: 2; white-space: pre-wrap; widows: 2;" class="">bridge br-int: deleted interface tap64c1f4fe-8b on port 1024</span></div><div class=""><span style="orphans: 2; white-space: pre-wrap; widows: 2;" class=""><br class=""></span></div><div class="">It’s no cule to find why the tap device continually added and deleted on the same ovs ofport, it seems had lasted for more than one month.</div><div class=""><span style="orphans: 2; widows: 2;" class=""><span style="white-space: pre-wrap;" class=""><br class=""></span></span></div><div class=""><span style="orphans: 2; widows: 2;" class=""><span style="white-space: pre-wrap;" class=""><br class=""></span></span></div><div class=""><span style="orphans: 2; widows: 2;" class=""><span style="white-space: pre-wrap;" class="">And then we </span></span><span style="white-space: pre-wrap;" class="">observed in /var/log/messages, the keepalived VRRP switched:</span></div><div class=""><div class="">Jul 23 07:35:06 NFDW5-TSTACK-NET-01 Keepalived_vrrp[64451]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:06 NFDW5-TSTACK-NET-01 Keepalived_vrrp[69471]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:06 NFDW5-TSTACK-NET-01 Keepalived_vrrp[66825]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:06 NFDW5-TSTACK-NET-01 Keepalived_vrrp[55727]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:06 NFDW5-TSTACK-NET-01 Keepalived_vrrp[55735]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:06 NFDW5-TSTACK-NET-01 Keepalived_vrrp[55709]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[66784]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[68081]: VRRP_Instance(VR_192) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[69471]: VRRP_Instance(VR_1) Received advert with higher priority 50, ours 50</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[69471]: VRRP_Instance(VR_1) Entering BACKUP STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[53128]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[64102]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[72616]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[66712]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[70117]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[64451]: VRRP_Instance(VR_1) Received advert with higher priority 50, ours 50</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[64451]: VRRP_Instance(VR_1) Entering BACKUP STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[63906]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[58249]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[186176]: VRRP_Instance(VR_220) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[67535]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[58302]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[61177]: VRRP_Instance(VR_1) Transition to MASTER STATE</div><div class="">Jul 23 07:35:07 NFDW5-TSTACK-NET-01 Keepalived_vrrp[72059]: VRRP_Instance(VR_1) Transition to MASTER STATE</div></div><div class=""><br class=""></div><div class=""><br class=""></div><div class="">After <span style="white-space: pre-wrap;" class="">keepalived VRRP switched, there are losts of lost packet and flow limit reached logs:</span></div><div class=""><span style="orphans: 2; white-space: pre-wrap; widows: 2;" class="">|WARN|system@ovs-system: lost packet on port channel</span></div><div class=""><span style="orphans: 2; widows: 2; white-space: pre-wrap;" class="">|WARN|upcall: datapath flow limit reached </span></div><div class=""><br class=""></div><div class=""><br class=""></div><div class=""><br class=""></div><div class=""><br class=""></div></div></body></html>