On 3/1/23 12:42, Brendan Doyle via discuss wrote: > Hi Folks, > > Whilst launching a lot (150+) of VMs on a hypervisor we occasionally > see errors like > "libvirt: error : internal error: Unable to add port vnet114 to OVS bridge > br-int" > > in var/log/messages, for example: > > > Feb 25 04:13:15 pcacn001 ovs-vsctl: ovs|00001|vsctl|INFO|Called as ovs-vsctl > --timeout=5 -- --may-exist add-port br-int vnet87 -- set Interface vnet87 > "external-ids:attached-mac=\"00:13:97:42:ff:5d\"" -- set Interface vnet87 > "external-ids:iface-id=\"b652aef0-b4c2-11ed-9fba-a8698c05eb74\"" -- set > Interface vnet87 > "external-ids:vm-id=\"ba70d0b3-9b47-48e8-9ed4-a8bf04bae901\"" -- set > Interface vnet87 external-ids:iface-status=active > > Feb 25 04:13:20 pcacn001 journal: internal error: Child process (ovs-vsctl > --timeout=5 -- --may-exist add-port br-int vnet87 -- set Interface vnet87 > 'external-ids:attached-mac="00:13:97:42:ff:5d"' -- set Interface vnet87 > 'external-ids:iface-id="b652aef0-b4c2-11ed-9fba-a8698c05eb74"' -- set > Interface vnet87 'external-ids:vm-id="ba70d0b3-9b47-48e8-9ed4-a8bf04bae901"' > -- set Interface vnet87 external-ids:iface-status=active) unexpected fatal > signal 14: 2023-02-25T04:13:20Z|00002|fatal_signal|WARN|terminating with > signal 14 (Alarm clock) > Feb 25 04:13:20 pcacn001 journal: internal error: Unable to add port vnet87 > to OVS bridge br-int > > > There is nothing suspicious in ovn-controller log, but the ovsdb-server and > ovs-vswitchd logs for this time period do contain WARNs > > ovsdb-server.log > ================ > 2023-02-25T04:13:08.896Z|108756|jsonrpc|WARN|unix#84848: receive error: > Connection reset by peer > 2023-02-25T04:13:08.896Z|108757|reconnect|WARN|unix#84848: connection dropped > (Connection reset by peer) > 2023-02-25T04:13:08.910Z|108758|reconnect|WARN|unix#84850: connection dropped > (Connection reset by peer) > 2023-02-25T04:13:08.918Z|108759|reconnect|WARN|unix#84851: connection dropped > (Connection reset by peer) > 2023-02-25T04:13:08.925Z|108760|reconnect|WARN|unix#84852: connection dropped > (Connection reset by peer) > 2023-02-25T04:13:08.932Z|108761|reconnect|WARN|unix#84853: connection dropped > (Connection reset by peer) > 2023-02-25T04:13:08.938Z|108762|reconnect|WARN|unix#84854: connection dropped > (Connection reset by peer) > 2023-02-25T04:13:09.238Z|108763|reconnect|WARN|unix#84855: connection dropped > (Connection reset by peer) > 2023-02-25T04:13:09.277Z|108764|reconnect|WARN|unix#84856: connection dropped > (Connection reset by peer) > 2023-02-25T04:13:09.284Z|108765|reconnect|WARN|unix#84857: connection dropped > (Connection reset by peer) > 2023-02-25T04:13:09.300Z|108766|reconnect|WARN|unix#84859: connection dropped > (Connection reset by peer) > 2023-02-25T04:13:09.308Z|108767|reconnect|WARN|unix#84860: connection dropped > (Connection reset by peer) > 2023-02-25T04:13:09.323Z|108768|reconnect|WARN|unix#84862: connection dropped > (Connection reset by peer) > 2023-02-25T04:14:46.220Z|108769|jsonrpc|WARN|Dropped 11 log messages in last > 97 seconds (most recently, 97 seconds ago) due to excessive rate > 2023-02-25T04:14:46.220Z|108770|jsonrpc|WARN|unix#84870: receive error: > Connection reset by peer > > ovs-vswitchd.log > ================= > 2023-02-25T04:13:00.849Z|00258|ovs_rcu(urcu9)|WARN|blocked 1000 ms waiting > for main to quiesce > 2023-02-25T04:13:01.694Z|04014|timeval|WARN|Unreasonably long 1910ms poll > interval (902ms user, 1007ms system) > 2023-02-25T04:13:01.694Z|04015|timeval|WARN|faults: 21 minor, 0 major > 2023-02-25T04:13:01.694Z|04016|timeval|WARN|context switches: 0 voluntary, 2 > involuntary > 2023-02-25T04:13:01.694Z|04017|coverage|INFO|Dropped 12 log messages in last > 65 seconds (most recently, 40 seconds ago) due to excessive rate > 2023-02-25T04:13:01.694Z|04018|coverage|INFO|Skipping details of duplicate > event coverage for hash=ce7b9f83 > 2023-02-25T04:13:01.722Z|04019|bridge|INFO|bridge br-int: added interface > vnet86 on port 204 > 2023-02-25T04:13:02.695Z|00259|ovs_rcu(urcu9)|WARN|blocked 1000 ms waiting > for main to quiesce > 2023-02-25T04:13:03.676Z|04020|timeval|WARN|Unreasonably long 1982ms poll > interval (895ms user, 1084ms system) > 2023-02-25T04:13:03.676Z|04021|timeval|WARN|faults: 1 minor, 0 major > 2023-02-25T04:13:03.676Z|04022|timeval|WARN|context switches: 0 voluntary, 5 > involuntary > 2023-02-25T04:13:04.676Z|00260|ovs_rcu(urcu9)|WARN|blocked 1000 ms waiting > for main to quiesce > 2023-02-25T04:13:05.658Z|04023|timeval|WARN|Unreasonably long 1982ms poll > interval (922ms user, 1059ms system) > 2023-02-25T04:13:05.658Z|04024|timeval|WARN|faults: 18 minor, 0 major > 2023-02-25T04:13:05.658Z|04025|timeval|WARN|context switches: 2 voluntary, 5 > involuntary > 2023-02-25T04:13:05.658Z|04026|poll_loop|INFO|wakeup due to [POLLIN] on fd 15 > (<->/var/run/openvswitch/db.sock) at lib/stream-fd.c:157 (101% CPU usage) > 2023-02-25T04:13:06.672Z|00261|ovs_rcu(urcu9)|WARN|blocked 1000 ms waiting > for main to quiesce > 2023-02-25T04:13:07.616Z|04027|timeval|WARN|Unreasonably long 1958ms poll > interval (916ms user, 1025ms system) > 2023-02-25T04:13:07.616Z|04028|timeval|WARN|context switches: 3 voluntary, 6 > involuntary > 2023-02-25T04:13:07.616Z|04029|poll_loop|INFO|wakeup due to [POLLIN] on fd 15 > (<->/var/run/openvswitch/db.sock) at lib/stream-fd.c:157 (101% CPU usage) > 2023-02-25T04:13:08.616Z|00262|ovs_rcu(urcu9)|WARN|blocked 1000 ms waiting > for main to quiesce > 2023-02-25T04:13:09.536Z|04030|timeval|WARN|Unreasonably long 1920ms poll > interval (919ms user, 999ms system) > 2023-02-25T04:13:09.536Z|04031|timeval|WARN|faults: 2 minor, 0 major > 2023-02-25T04:13:09.536Z|04032|timeval|WARN|context switches: 4 voluntary, 3 > involuntary > 2023-02-25T04:13:09.536Z|04033|poll_loop|INFO|wakeup due to [POLLIN] on fd 14 > (NETLINK_ROUTE<->NETLINK_ROUTE) at lib/netlink-socket.c:1401 (101% CPU usage) > 2023-02-25T04:13:09.537Z|04034|poll_loop|INFO|wakeup due to [POLLIN] on fd 22 > (FIFO pipe:[52276]) at vswitchd/bridge.c:423 (101% CPU usage) > 2023-02-25T04:13:09.537Z|04035|poll_loop|INFO|wakeup due to [POLLIN] on fd > 529 (/var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:157 (101% CPU > usage) > 2023-02-25T04:13:10.538Z|00263|ovs_rcu(urcu9)|WARN|blocked 1001 ms waiting > for main to quiesce > 2023-02-25T04:13:11.512Z|04036|timeval|WARN|Unreasonably long 1976ms poll > interval (918ms user, 1023ms system) > 2023-02-25T04:13:11.512Z|04037|timeval|WARN|faults: 3 minor, 0 major > 2023-02-25T04:13:11.512Z|04038|timeval|WARN|context switches: 8 voluntary, 5 > involuntary > 2023-02-25T04:13:11.512Z|04039|poll_loop|INFO|wakeup due to [POLLIN] on fd > 529 (/var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:157 (101% CPU > usage) > 2023-02-25T04:13:11.522Z|04040|poll_loop|INFO|wakeup due to 0-ms timeout at > ofproto/ofproto-dpif.c:1976 (101% CPU usage) > 2023-02-25T04:13:11.972Z|04041|poll_loop|INFO|Dropped 1 log messages in last > 1 seconds (most recently, 1 seconds ago) due to excessive rate > 2023-02-25T04:13:11.972Z|04042|poll_loop|INFO|wakeup due to [POLLIN] on fd 22 > (FIFO pipe:[52276]) at vswitchd/bridge.c:423 (101% CPU usage) > 2023-02-25T04:13:16.472Z|00264|ovs_rcu(urcu9)|WARN|blocked 1000 ms waiting > for main to quiesce > 2023-02-25T04:13:17.472Z|00265|ovs_rcu(urcu9)|WARN|blocked 2000 ms waiting > for main to quiesce > 2023-02-25T04:13:18.405Z|04043|connmgr|INFO|br-int<->unix#1: 60 flow_mods in > the 16 s starting 25 s ago (58 adds, 2 deletes) > 2023-02-25T04:13:18.487Z|04044|timeval|WARN|Unreasonably long 3303ms poll > interval (1569ms user, 1731ms system) > 2023-02-25T04:13:18.487Z|04045|timeval|WARN|faults: 11 minor, 0 major > 2023-02-25T04:13:18.487Z|04046|timeval|WARN|context switches: 1 voluntary, 8 > involuntary > 2023-02-25T04:13:18.487Z|04047|poll_loop|INFO|Dropped 10 log messages in last > 6 seconds (most recently, 3 seconds ago) due to excessive rate > 2023-02-25T04:13:18.487Z|04048|poll_loop|INFO|wakeup due to [POLLIN] on fd 14 > (NETLINK_ROUTE<->NETLINK_ROUTE) at lib/netlink-socket.c:1401 (57% CPU usage) > 2023-02-25T04:13:18.518Z|04049|bridge|INFO|bridge br-int: added interface > vnet87 on port 205 > 2023-02-25T04:13:19.487Z|00266|ovs_rcu(urcu9)|WARN|blocked 1000 ms waiting > for main to quiesce > 2023-02-25T04:13:20.475Z|04050|ofproto|WARN|br-int: cannot get STP status on > nonexistent port 205 > 2023-02-25T04:13:20.475Z|04051|ofproto|WARN|br-int: cannot get RSTP status on > nonexistent port 205 > 2023-02-25T04:13:20.547Z|04052|timeval|WARN|Unreasonably long 2060ms poll > interval (910ms user, 1092ms system) > 2023-02-25T04:13:20.548Z|04053|timeval|WARN|faults: 9 minor, 0 major > 2023-02-25T04:13:20.548Z|04054|timeval|WARN|context switches: 8 voluntary, 4 > involuntary > 2023-02-25T04:13:20.578Z|04055|bridge|INFO|bridge br-int: deleted interface > vnet87 on port 205 > 2023-02-25T04:13:20.581Z|04056|bridge|WARN|could not open network device > vnet87 (No such device) > 2023-02-25T04:13:21.550Z|00267|ovs_rcu(urcu9)|WARN|blocked 1000 ms waiting > for main to quiesce > 2023-02-25T04:13:22.509Z|04057|timeval|WARN|Unreasonably long 1961ms poll > interval (908ms user, 1048ms system) > 2023-02-25T04:13:22.509Z|04058|timeval|WARN|faults: 1 minor, 0 major > 2023-02-25T04:13:22.509Z|04059|timeval|WARN|context switches: 6 voluntary, 7 > involuntary > 2023-02-25T04:13:24.026Z|04060|poll_loop|INFO|Dropped 12 log messages in last > 6 seconds (most recently, 1 seconds ago) due to excessive rate > > > > Any idea what's going on here? Should it be that ovs-vsctl timeout should be > longer? > Who is sending the SIG 14 to it and why?
ovs-vsctl sends SIGALRM to itself after 5 seconds, because it is started with --timeout=5. > > What does thisovs-vswitchd WARN mean: > 2023-02-25T04:13:02.695Z|00259|ovs_rcu(urcu9)|WARN|blocked 1000 ms waiting > for main to quiesce That means that the main thread is busy doing some work for at least one second without entering quiescent state. basically means that one iteration in the main thread took a lot of time. Looking at this: Unreasonably long 2060ms poll interval (910ms user, 1092ms system) ovs-vswitchd is likely stuck somewhere inside the syscall in the kernel for 1092ms. That is a lot of time. > > It seems that eventually the port is added even though ovs-vsctl cmd failed : > ovs-vsctl list-ports br-int | grep vnet87 > vnet87 Database is fine, so the port was added to it without issues, but ovs-vsctl waits for ovs-vswitchd to act on database update. That didn't happen within 5 seconds, so ovs-vsctl reported an error. 'ovs-vsctl list-ports' is a pure database command, it shows the database content. It's also likely that ovs-vswitch will actually add the port eventually when it gets out from being stuck in the kernel. But it's too late for ovs-vsctl. You need to investigate what is going on with ovs-vswitchd, i.e. what holds it inside the kernel for so long, of it it makes way too many syscalls for some reason. Not sure how many cores you have or what OVS version you're using, but this might be one of the possible causes of being stuck in syscalls for a long time on systems with large number of cores with big number of ports: https://github.com/openvswitch/ovs/commit/c0e053f6d Best regards, Ilya Maximets. _______________________________________________ discuss mailing list disc...@openvswitch.org https://mail.openvswitch.org/mailman/listinfo/ovs-discuss
