Hello,
I migrated all instanced from “high cpu usage ovs” node to another node to
avoid unexpected packet drop.
When migration was finished, ovs-vswitchd was crashed suddenly.
==== console logs when ovs-vswitchd was crashed ====
/usr/local/bin/start-ovs: line 2: 16 Segmentation fault (core dumped)
/usr/sbin/ovs-vswitchd unix:/run/openvswitch/db.sock -vconsole:emer
-vsyslog:err -vfile:info --mlockall
--log-file=/var/log/kolla/openvswitch/ovs-vswitchd.log
====================================
Please see attached file: ovs-vswitchd.log2.txt
From: 우병열 [woobee]
Sent: Friday, October 19, 2018 2:13 PM
To: 'b...@openvswitch.org' <b...@openvswitch.org>
Subject: ovs-vswitchd high CPU usage after attaching new port
Hello,
I want to report an issue that ovs-vswitchd high CPU usage after attaching new
port.
Please see following informations.
The most important parts of your bug report are the following:
* What you did that make the problem appear.
* Neutron openvswitch agent added 4 ports on OVS Bridge.
* What you expected to happen.
* They were added successfully and nothing happened.
* What actually happened.
* Cpu usage became over 100% and ovs-vswitchd makes huge amount of logs.
(please see attached file: ovs-vswitchd.log.txt)
Please also include the following information:
* The Open vSwitch version number (as output by ovs-vswitchd --version).
* ovs-vswitchd (Open vSwitch) 2.10.0
* The Git commit number (as output by git rev-parse HEAD), if you built
from a Git snapshot.
* none
* Any local patches or changes you have applied (if any).
* none
The following are also handy sometimes:
* The kernel version on which Open vSwitch is running (from /proc/version)
and the distribution and version number of your OS (e.g. “Centos 5.0”).
* Linux version 4.15.0-34-generic (buildd@lgw01-amd64-047) (gcc version
7.3.0 (Ubuntu 7.3.0-16ubuntu3)) #37-Ubuntu SMP Mon Aug 27 15:21:48 UTC 2018
* The contents of the vswitchd configuration database (usually
/etc/openvswitch/conf.db).
* Please see attached file: conf.db.txt
* The output of ovs-dpctl show.
* Please see attached file: ovs-dpctl-ofctl.txt
* If you have Open vSwitch configured to connect to an OpenFlow controller,
the output of ovs-ofctl show <bridge> for each <bridge> configured in the
vswitchd configuration database.
* Please see attached file: ovs-dpctl-ofctl.txt
2018-10-19T06:57:12.586Z|04727|poll_loop(handler140)|INFO|Dropped 1605325 log
messages in last 6 seconds (most recently, 0 seconds ago) due to excessive rate
2018-10-19T06:57:12.586Z|04728|poll_loop(handler140)|INFO|wakeup due to
[POLLIN] on fd 42 (unknown anon_inode:[eventpoll]) at
../lib/dpif-netlink.c:2786 (99% CPU usage)
2018-10-19T06:57:18.586Z|04729|poll_loop(handler140)|INFO|Dropped 1613830 log
messages in last 6 seconds (most recently, 0 seconds ago) due to excessive rate
2018-10-19T06:57:18.586Z|04730|poll_loop(handler140)|INFO|wakeup due to
[POLLIN] on fd 42 (unknown anon_inode:[eventpoll]) at
../lib/dpif-netlink.c:2786 (99% CPU usage)
2018-10-19T06:57:24.586Z|04731|poll_loop(handler140)|INFO|Dropped 1594444 log
messages in last 6 seconds (most recently, 0 seconds ago) due to excessive rate
2018-10-19T06:57:24.586Z|04732|poll_loop(handler140)|INFO|wakeup due to
[POLLIN] on fd 42 (unknown anon_inode:[eventpoll]) at
../lib/dpif-netlink.c:2786 (99% CPU usage)
2018-10-19T06:57:30.586Z|04733|poll_loop(handler140)|INFO|Dropped 1605681 log
messages in last 6 seconds (most recently, 0 seconds ago) due to excessive rate
2018-10-19T06:57:30.586Z|04734|poll_loop(handler140)|INFO|wakeup due to
[POLLIN] on fd 42 (unknown anon_inode:[eventpoll]) at
../lib/dpif-netlink.c:2786 (99% CPU usage)
2018-10-19T06:57:36.586Z|04735|poll_loop(handler140)|INFO|Dropped 1541293 log
messages in last 6 seconds (most recently, 0 seconds ago) due to excessive rate
2018-10-19T06:57:36.586Z|04736|poll_loop(handler140)|INFO|wakeup due to
[POLLIN] on fd 42 (unknown anon_inode:[eventpoll]) at
../lib/dpif-netlink.c:2786 (99% CPU usage)
2018-10-19T06:57:42.586Z|04737|poll_loop(handler140)|INFO|Dropped 1601181 log
messages in last 6 seconds (most recently, 0 seconds ago) due to excessive rate
2018-10-19T06:57:42.586Z|04738|poll_loop(handler140)|INFO|wakeup due to
[POLLIN] on fd 42 (unknown anon_inode:[eventpoll]) at
../lib/dpif-netlink.c:2786 (99% CPU usage)
2018-10-19T06:57:48.586Z|04739|poll_loop(handler140)|INFO|Dropped 1527392 log
messages in last 6 seconds (most recently, 0 seconds ago) due to excessive rate
2018-10-19T06:57:48.586Z|04740|poll_loop(handler140)|INFO|wakeup due to
[POLLIN] on fd 42 (unknown anon_inode:[eventpoll]) at
../lib/dpif-netlink.c:2786 (99% CPU usage)
2018-10-19T06:57:54.586Z|04741|poll_loop(handler140)|INFO|Dropped 1518579 log
messages in last 6 seconds (most recently, 0 seconds ago) due to excessive rate
2018-10-19T06:57:54.586Z|04742|poll_loop(handler140)|INFO|wakeup due to
[POLLIN] on fd 42 (unknown anon_inode:[eventpoll]) at
../lib/dpif-netlink.c:2786 (99% CPU usage)
2018-10-19T06:57:55.174Z|00695|connmgr|INFO|br-int<->tcp:127.0.0.1:6633: 16
flow_mods in the 2 s starting 10 s ago (12 adds, 4 deletes)
2018-10-19T06:57:56.604Z|00696|connmgr|INFO|br-tun<->tcp:127.0.0.1:6633: 129
flow_mods in the 2 s starting 10 s ago (129 adds)
2018-10-19T06:57:56.944Z|00697|bridge|INFO|bridge br-int: deleted interface
qvoc1d4aa42-b9 on port 38
2018-10-19T06:57:59.920Z|00698|bridge|INFO|bridge br-tun: deleted interface
vxlan-0aa80ca8 on port 32
2018-10-19T06:57:59.939Z|00699|bridge|INFO|bridge br-tun: deleted interface
vxlan-0aa80ca9 on port 2
2018-10-19T06:57:59.941Z|00009|tunnel(revalidator151)|WARN|receive tunnel port
not found
(arp,tun_id=0x3c,tun_src=10.168.12.169,tun_dst=10.168.12.171,tun_ipv6_src=::,tun_ipv6_dst=::,tun_gbp_id=0,tun_gbp_flags=0,tun_tos=0,tun_ttl=64,tun_erspan_ver=0,tun_flags=key,in_port=1,vlan_tci=0x0000,dl_src=fa:16:3e:81:e8:51,dl_dst=ff:ff:ff:ff:ff:ff,arp_spa=10.168.240.27,arp_tpa=10.168.240.27,arp_op=1,arp_sha=fa:16:3e:81:e8:51,arp_tha=ff:ff:ff:ff:ff:ff)
2018-10-19T06:57:59.956Z|00700|bridge|INFO|bridge br-tun: deleted interface
vxlan-0aa80cac on port 4
2018-10-19T06:57:59.960Z|00010|tunnel(revalidator151)|WARN|receive tunnel port
not found
(tcp,tun_id=0x3c,tun_src=10.168.12.172,tun_dst=10.168.12.171,tun_ipv6_src=::,tun_ipv6_dst=::,tun_gbp_id=0,tun_gbp_flags=0,tun_tos=0,tun_ttl=64,tun_erspan_ver=0,tun_flags=key,in_port=1,vlan_tci=0x0000,dl_src=fa:16:3e:9e:ef:46,dl_dst=fa:16:3e:ee:02:fd,nw_src=10.168.240.17,nw_dst=10.168.240.20,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=59889,tp_dst=80,tcp_flags=syn)
2018-10-19T06:57:59.960Z|00011|tunnel(revalidator151)|WARN|receive tunnel port
not found
(arp,tun_id=0x3c,tun_src=10.168.12.172,tun_dst=10.168.12.171,tun_ipv6_src=::,tun_ipv6_dst=::,tun_gbp_id=0,tun_gbp_flags=0,tun_tos=0,tun_ttl=64,tun_erspan_ver=0,tun_flags=key,in_port=1,vlan_tci=0x0000,dl_src=fa:16:3e:9e:ef:46,dl_dst=ff:ff:ff:ff:ff:ff,arp_spa=10.168.240.5,arp_tpa=10.168.240.5,arp_op=1,arp_sha=fa:16:3e:9e:ef:46,arp_tha=ff:ff:ff:ff:ff:ff)
2018-10-19T06:57:59.972Z|00701|bridge|INFO|bridge br-tun: deleted interface
vxlan-0aa80ca2 on port 37
2018-10-19T06:57:59.989Z|00702|bridge|INFO|bridge br-tun: deleted interface
vxlan-0aa80ca5 on port 38
2018-10-19T06:58:00.004Z|00703|bridge|INFO|bridge br-tun: deleted interface
vxlan-0aa80ca6 on port 39
2018-10-19T06:58:00.006Z|00001|tunnel(revalidator161)|WARN|receive tunnel port
not found
(arp,tun_id=0x3c,tun_src=10.168.12.166,tun_dst=10.168.12.171,tun_ipv6_src=::,tun_ipv6_dst=::,tun_gbp_id=0,tun_gbp_flags=0,tun_tos=0,tun_ttl=64,tun_erspan_ver=0,tun_flags=key,in_port=1,vlan_tci=0x0000,dl_src=fa:16:3e:f3:8b:20,dl_dst=ff:ff:ff:ff:ff:ff,arp_spa=10.168.240.40,arp_tpa=10.168.240.40,arp_op=1,arp_sha=fa:16:3e:f3:8b:20,arp_tha=ff:ff:ff:ff:ff:ff)
2018-10-19T06:58:00.020Z|00704|bridge|INFO|bridge br-tun: deleted interface
vxlan-0aa80caa on port 21
2018-10-19T06:58:00.023Z|00012|tunnel(revalidator151)|WARN|receive tunnel port
not found
(tcp,tun_id=0x3c,tun_src=10.168.12.170,tun_dst=10.168.12.171,tun_ipv6_src=::,tun_ipv6_dst=::,tun_gbp_id=0,tun_gbp_flags=0,tun_tos=0,tun_ttl=64,tun_erspan_ver=0,tun_flags=key,in_port=1,vlan_tci=0x0000,dl_src=fa:16:3e:e5:b9:58,dl_dst=fa:16:3e:ee:02:fd,nw_src=10.168.240.12,nw_dst=10.168.240.20,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=35615,tp_dst=80,tcp_flags=syn)
2018-10-19T06:58:00.033Z|00705|bridge|INFO|bridge br-tun: deleted interface
vxlan-0aa80c88 on port 22
2018-10-19T06:58:00.038Z|00013|tunnel(revalidator151)|WARN|receive tunnel port
not found
(arp,tun_id=0x3c,tun_src=10.168.12.136,tun_dst=10.168.12.171,tun_ipv6_src=::,tun_ipv6_dst=::,tun_gbp_id=0,tun_gbp_flags=0,tun_tos=0,tun_ttl=64,tun_erspan_ver=0,tun_flags=key,in_port=1,vlan_tci=0x0000,dl_src=fa:16:3e:4d:65:72,dl_dst=fa:16:3e:ee:02:fd,arp_spa=10.168.240.11,arp_tpa=10.168.240.20,arp_op=1,arp_sha=fa:16:3e:4d:65:72,arp_tha=00:00:00:00:00:00)
2018-10-19T06:58:00.038Z|00014|tunnel(revalidator151)|WARN|receive tunnel port
not found
(tcp,tun_id=0x3c,tun_src=10.168.12.136,tun_dst=10.168.12.171,tun_ipv6_src=::,tun_ipv6_dst=::,tun_gbp_id=0,tun_gbp_flags=0,tun_tos=0,tun_ttl=64,tun_erspan_ver=0,tun_flags=key,in_port=1,vlan_tci=0x0000,dl_src=fa:16:3e:4d:65:72,dl_dst=fa:16:3e:ee:02:fd,nw_src=192.168.52.41,nw_dst=10.168.240.20,nw_tos=0,nw_ecn=0,nw_ttl=126,tp_src=51967,tp_dst=39154,tcp_flags=psh|ack)
2018-10-19T06:58:00.048Z|00706|bridge|INFO|bridge br-tun: deleted interface
vxlan-0aa80c86 on port 23
2018-10-19T06:58:00.066Z|00707|bridge|INFO|bridge br-tun: deleted interface
vxlan-0aa80c87 on port 24
2018-10-19T06:58:00.079Z|00708|bridge|INFO|bridge br-tun: deleted interface
vxlan-0aa80ca7 on port 30
2018-10-19T06:58:00.084Z|00015|tunnel(revalidator151)|WARN|receive tunnel port
not found
(tcp,tun_id=0x3c,tun_src=10.168.12.167,tun_dst=10.168.12.171,tun_ipv6_src=::,tun_ipv6_dst=::,tun_gbp_id=0,tun_gbp_flags=0,tun_tos=0,tun_ttl=64,tun_erspan_ver=0,tun_flags=key,in_port=1,vlan_tci=0x0000,dl_src=fa:16:3e:22:a8:0d,dl_dst=fa:16:3e:82:a6:f3,nw_src=10.168.240.7,nw_dst=192.168.181.90,nw_tos=0,nw_ecn=0,nw_ttl=64,tp_src=15945,tp_dst=8085,tcp_flags=syn)
2018-10-19T06:58:00.115Z|00709|dpif|WARN|system@ovs-system: port_del failed (No
such device)
2018-10-19T06:58:02.032Z|00001|vlog|INFO|opened log file
/var/log/kolla/openvswitch/ovs-vswitchd.log
2018-10-19T06:58:02.035Z|00002|ovs_numa|INFO|Discovered 20 CPU cores on NUMA
node 0
2018-10-19T06:58:02.035Z|00003|ovs_numa|INFO|Discovered 20 CPU cores on NUMA
node 1
2018-10-19T06:58:02.035Z|00004|ovs_numa|INFO|Discovered 2 NUMA nodes and 40 CPU
cores
2018-10-19T06:58:02.035Z|00005|reconnect|INFO|unix:/run/openvswitch/db.sock:
connecting...
2018-10-19T06:58:02.035Z|00006|reconnect|INFO|unix:/run/openvswitch/db.sock:
connected
2018-10-19T06:58:02.043Z|00007|ofproto_dpif|INFO|system@ovs-system: Datapath
supports recirculation
2018-10-19T06:58:02.043Z|00008|ofproto_dpif|INFO|system@ovs-system: VLAN header
stack length probed as 2
2018-10-19T06:58:02.043Z|00009|ofproto_dpif|INFO|system@ovs-system: MPLS label
stack length probed as 1
2018-10-19T06:58:02.043Z|00010|ofproto_dpif|INFO|system@ovs-system: Datapath
supports truncate action
2018-10-19T06:58:02.044Z|00011|ofproto_dpif|INFO|system@ovs-system: Datapath
supports unique flow ids
2018-10-19T06:58:02.044Z|00012|ofproto_dpif|INFO|system@ovs-system: Datapath
does not support clone action
2018-10-19T06:58:02.044Z|00013|ofproto_dpif|INFO|system@ovs-system: Max sample
nesting level probed as 10
2018-10-19T06:58:02.044Z|00014|ofproto_dpif|INFO|system@ovs-system: Datapath
supports eventmask in conntrack action
2018-10-19T06:58:02.044Z|00015|ofproto_dpif|INFO|system@ovs-system: Datapath
supports ct_clear action
2018-10-19T06:58:02.044Z|00016|ofproto_dpif|INFO|system@ovs-system: Max dp_hash
algorithm probed to be 0
2018-10-19T06:58:02.044Z|00017|ofproto_dpif|INFO|system@ovs-system: Datapath
supports ct_state
2018-10-19T06:58:02.044Z|00018|ofproto_dpif|INFO|system@ovs-system: Datapath
supports ct_zone
2018-10-19T06:58:02.044Z|00019|ofproto_dpif|INFO|system@ovs-system: Datapath
supports ct_mark
2018-10-19T06:58:02.044Z|00020|ofproto_dpif|INFO|system@ovs-system: Datapath
supports ct_label
2018-10-19T06:58:02.044Z|00021|ofproto_dpif|INFO|system@ovs-system: Datapath
supports ct_state_nat
2018-10-19T06:58:02.044Z|00022|ofproto_dpif|INFO|system@ovs-system: Datapath
supports ct_orig_tuple
2018-10-19T06:58:02.044Z|00023|ofproto_dpif|INFO|system@ovs-system: Datapath
supports ct_orig_tuple6
2018-10-19T06:58:02.205Z|00024|dpif_netlink|INFO|dpif_netlink_meter_transact
get failed
2018-10-19T06:58:02.205Z|00025|dpif_netlink|INFO|The kernel module has a broken
meter implementation.
2018-10-19T06:58:02.207Z|00026|bridge|INFO|bridge br-tun: added interface
patch-int on port 1
2018-10-19T06:58:02.208Z|00027|bridge|INFO|bridge br-tun: added interface
br-tun on port 65534
2018-10-19T06:58:02.208Z|00028|bridge|INFO|bridge br-int: added interface
br-int on port 65534
2018-10-19T06:58:02.208Z|00029|bridge|INFO|bridge br-int: added interface
int-br-ex on port 1
2018-10-19T06:58:02.208Z|00030|bridge|INFO|bridge br-int: added interface
patch-tun on port 2
2018-10-19T06:58:02.208Z|00031|bridge|INFO|bridge br-ex: added interface br-ex
on port 65534
2018-10-19T06:58:02.209Z|00032|bridge|INFO|bridge br-ex: added interface
phy-br-ex on port 2
2018-10-19T06:58:02.209Z|00033|bridge|INFO|bridge br-ex: added interface bond0
on port 1
2018-10-19T06:58:02.209Z|00034|bridge|INFO|bridge br-tun: using datapath ID
000066e0d84ea54e
2018-10-19T06:58:02.209Z|00035|connmgr|INFO|br-tun: added service controller
"punix:/var/run/openvswitch/br-tun.mgmt"
2018-10-19T06:58:02.209Z|00036|connmgr|INFO|br-tun: added primary controller
"tcp:127.0.0.1:6633"
2018-10-19T06:58:02.209Z|00037|rconn|INFO|br-tun<->tcp:127.0.0.1:6633:
connecting...
2018-10-19T06:58:02.371Z|00038|bridge|INFO|bridge br-int: using datapath ID
0000b69320a7db47
2018-10-19T06:58:02.371Z|00039|connmgr|INFO|br-int: added service controller
"punix:/var/run/openvswitch/br-int.mgmt"
2018-10-19T06:58:02.371Z|00040|connmgr|INFO|br-int: added primary controller
"tcp:127.0.0.1:6633"
2018-10-19T06:58:02.371Z|00041|rconn|INFO|br-int<->tcp:127.0.0.1:6633:
connecting...
2018-10-19T06:58:02.518Z|00042|bridge|INFO|bridge br-ex: using datapath ID
00006ecda300a74b
2018-10-19T06:58:02.518Z|00043|connmgr|INFO|br-ex: added service controller
"punix:/var/run/openvswitch/br-ex.mgmt"
2018-10-19T06:58:02.518Z|00044|connmgr|INFO|br-ex: added primary controller
"tcp:127.0.0.1:6633"
2018-10-19T06:58:02.518Z|00045|rconn|INFO|br-ex<->tcp:127.0.0.1:6633:
connecting...
2018-10-19T06:58:02.681Z|00046|rconn|INFO|br-tun<->tcp:127.0.0.1:6633: connected
2018-10-19T06:58:02.681Z|00047|rconn|INFO|br-int<->tcp:127.0.0.1:6633: connected
2018-10-19T06:58:02.682Z|00048|rconn|INFO|br-ex<->tcp:127.0.0.1:6633: connected
2018-10-19T06:58:02.683Z|00049|bridge|INFO|ovs-vswitchd (Open vSwitch) 2.10.0
2018-10-19T06:58:12.100Z|00050|memory|INFO|354036 kB peak resident set size
after 10.1 seconds
2018-10-19T06:58:12.100Z|00051|memory|INFO|handlers:29 ofconns:3 ports:8
revalidators:11 rules:95 udpif keys:6
2018-10-19T06:58:20.141Z|00052|connmgr|INFO|br-int<->tcp:127.0.0.1:6633: 37
flow_mods 10 s ago (37 adds)
2018-10-19T06:58:20.182Z|00053|connmgr|INFO|br-ex<->tcp:127.0.0.1:6633: 21
flow_mods 10 s ago (21 adds)
2018-10-19T06:58:20.223Z|00054|connmgr|INFO|br-tun<->tcp:127.0.0.1:6633: 29
flow_mods 10 s ago (29 adds)
_______________________________________________
discuss mailing list
disc...@openvswitch.org
https://mail.openvswitch.org/mailman/listinfo/ovs-discuss
