Attachment 1557924 Details for Bug 1691682 – ovs log

ovs log

ovs-vswitchd.log (text/plain), 13.86 KB, created by qding on 2019-04-24 01:29:48 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: qding

Created: 2019-04-24 01:29:48 UTC

Size: 13.86 KB

patch

obsolete

>2019-04-24T01:25:34.873Z|00001|vlog|INFO|opened log file /var/log/openvswitch/ovs-vswitchd.log
>2019-04-24T01:25:34.878Z|00002|ovs_numa|INFO|Discovered 24 CPU cores on NUMA node 0
>2019-04-24T01:25:34.878Z|00003|ovs_numa|INFO|Discovered 24 CPU cores on NUMA node 1
>2019-04-24T01:25:34.878Z|00004|ovs_numa|INFO|Discovered 2 NUMA nodes and 48 CPU cores
>2019-04-24T01:25:34.878Z|00005|reconnect|INFO|unix:/var/run/openvswitch/db.sock: connecting...
>2019-04-24T01:25:34.878Z|00006|reconnect|INFO|unix:/var/run/openvswitch/db.sock: connected
>2019-04-24T01:25:34.879Z|00007|dpdk|INFO|Using DPDK 17.11.0
>2019-04-24T01:25:34.879Z|00008|dpdk|INFO|DPDK Enabled - initializing...
>2019-04-24T01:25:34.879Z|00009|dpdk|INFO|No vhost-sock-dir provided - defaulting to /var/run/openvswitch
>2019-04-24T01:25:34.879Z|00010|dpdk|INFO|IOMMU support for vhost-user-client disabled.
>2019-04-24T01:25:34.879Z|00011|dpdk|INFO|EAL ARGS: ovs-vswitchd -c 0x2 --socket-mem 1024,1024
>2019-04-24T01:25:34.881Z|00012|dpdk|INFO|EAL: Detected 48 lcore(s)
>2019-04-24T01:25:34.913Z|00013|dpdk|INFO|EAL: Probing VFIO support...
>2019-04-24T01:25:34.913Z|00014|dpdk|INFO|EAL: VFIO support initialized
>2019-04-24T01:25:39.644Z|00015|dpdk|INFO|EAL: PCI device 0000:06:00.0 on NUMA socket 0
>2019-04-24T01:25:39.644Z|00016|dpdk|INFO|EAL:   probe driver: 8086:154d net_ixgbe
>2019-04-24T01:25:39.644Z|00017|dpdk|INFO|EAL: PCI device 0000:06:00.1 on NUMA socket 0
>2019-04-24T01:25:39.644Z|00018|dpdk|INFO|EAL:   probe driver: 8086:154d net_ixgbe
>2019-04-24T01:25:39.644Z|00019|dpdk|INFO|EAL: PCI device 0000:82:00.0 on NUMA socket 1
>2019-04-24T01:25:39.644Z|00020|dpdk|INFO|EAL:   probe driver: 19ee:4000 net_nfp_pf
>2019-04-24T01:25:39.644Z|00021|dpdk|INFO|EAL: PCI device 0000:84:00.0 on NUMA socket 1
>2019-04-24T01:25:39.644Z|00022|dpdk|INFO|EAL:   probe driver: 8086:1572 net_i40e
>2019-04-24T01:25:39.644Z|00023|dpdk|INFO|EAL: PCI device 0000:84:00.1 on NUMA socket 1
>2019-04-24T01:25:39.644Z|00024|dpdk|INFO|EAL:   probe driver: 8086:1572 net_i40e
>2019-04-24T01:25:39.646Z|00025|dpdk|INFO|DPDK Enabled - initialized
>2019-04-24T01:25:39.648Z|00026|bridge|INFO|ovs-vswitchd (Open vSwitch) 2.9.0
>2019-04-24T01:25:39.648Z|00027|timeval|WARN|Unreasonably long 4769ms poll interval (3ms user, 4665ms system)
>2019-04-24T01:25:39.648Z|00028|timeval|WARN|faults: 16577 minor, 0 major
>2019-04-24T01:25:39.648Z|00029|timeval|WARN|context switches: 1 voluntary, 7 involuntary
>2019-04-24T01:25:39.648Z|00030|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour,  hash=736a30e5:
>2019-04-24T01:25:39.648Z|00031|coverage|INFO|bridge_reconfigure         0.0/sec     0.000/sec        0.0000/sec   total: 1
>2019-04-24T01:25:39.648Z|00032|coverage|INFO|cmap_expand                0.0/sec     0.000/sec        0.0000/sec   total: 8
>2019-04-24T01:25:39.648Z|00033|coverage|INFO|miniflow_malloc            0.0/sec     0.000/sec        0.0000/sec   total: 8
>2019-04-24T01:25:39.648Z|00034|coverage|INFO|hmap_pathological          0.0/sec     0.000/sec        0.0000/sec   total: 1
>2019-04-24T01:25:39.648Z|00035|coverage|INFO|hmap_expand                0.0/sec     0.000/sec        0.0000/sec   total: 380
>2019-04-24T01:25:39.648Z|00036|coverage|INFO|txn_unchanged              0.0/sec     0.000/sec        0.0000/sec   total: 3
>2019-04-24T01:25:39.648Z|00037|coverage|INFO|poll_create_node           0.0/sec     0.000/sec        0.0000/sec   total: 40
>2019-04-24T01:25:39.648Z|00038|coverage|INFO|seq_change                 0.0/sec     0.000/sec        0.0000/sec   total: 57
>2019-04-24T01:25:39.648Z|00039|coverage|INFO|pstream_open               0.0/sec     0.000/sec        0.0000/sec   total: 1
>2019-04-24T01:25:39.648Z|00040|coverage|INFO|stream_open                0.0/sec     0.000/sec        0.0000/sec   total: 1
>2019-04-24T01:25:39.648Z|00041|coverage|INFO|util_xalloc                0.0/sec     0.000/sec        0.0000/sec   total: 7379
>2019-04-24T01:25:39.648Z|00042|coverage|INFO|netdev_get_hwaddr          0.0/sec     0.000/sec        0.0000/sec   total: 1
>2019-04-24T01:25:39.648Z|00043|coverage|INFO|netlink_received           0.0/sec     0.000/sec        0.0000/sec   total: 3
>2019-04-24T01:25:39.648Z|00044|coverage|INFO|netlink_sent               0.0/sec     0.000/sec        0.0000/sec   total: 1
>2019-04-24T01:25:39.648Z|00045|coverage|INFO|90 events never hit
>2019-04-24T01:25:57.729Z|00046|memory|INFO|50852 kB peak resident set size after 22.9 seconds
>2019-04-24T01:26:00.187Z|00001|vlog|INFO|opened log file /var/log/openvswitch/ovs-vswitchd.log
>2019-04-24T01:26:00.192Z|00002|ovs_numa|INFO|Discovered 24 CPU cores on NUMA node 0
>2019-04-24T01:26:00.192Z|00003|ovs_numa|INFO|Discovered 24 CPU cores on NUMA node 1
>2019-04-24T01:26:00.192Z|00004|ovs_numa|INFO|Discovered 2 NUMA nodes and 48 CPU cores
>2019-04-24T01:26:00.192Z|00005|reconnect|INFO|unix:/var/run/openvswitch/db.sock: connecting...
>2019-04-24T01:26:00.192Z|00006|reconnect|INFO|unix:/var/run/openvswitch/db.sock: connected
>2019-04-24T01:26:00.193Z|00007|dpdk|INFO|Using DPDK 17.11.0
>2019-04-24T01:26:00.193Z|00008|dpdk|INFO|DPDK Enabled - initializing...
>2019-04-24T01:26:00.193Z|00009|dpdk|INFO|No vhost-sock-dir provided - defaulting to /var/run/openvswitch
>2019-04-24T01:26:00.193Z|00010|dpdk|INFO|IOMMU support for vhost-user-client disabled.
>2019-04-24T01:26:00.193Z|00011|dpdk|INFO|EAL ARGS: ovs-vswitchd -c 0x2 --socket-mem 1024,1024
>2019-04-24T01:26:00.195Z|00012|dpdk|INFO|EAL: Detected 48 lcore(s)
>2019-04-24T01:26:00.229Z|00013|dpdk|INFO|EAL: Probing VFIO support...
>2019-04-24T01:26:00.229Z|00014|dpdk|INFO|EAL: VFIO support initialized
>2019-04-24T01:26:05.070Z|00015|dpdk|INFO|EAL: PCI device 0000:06:00.0 on NUMA socket 0
>2019-04-24T01:26:05.070Z|00016|dpdk|INFO|EAL:   probe driver: 8086:154d net_ixgbe
>2019-04-24T01:26:05.070Z|00017|dpdk|INFO|EAL: PCI device 0000:06:00.1 on NUMA socket 0
>2019-04-24T01:26:05.070Z|00018|dpdk|INFO|EAL:   probe driver: 8086:154d net_ixgbe
>2019-04-24T01:26:05.070Z|00019|dpdk|INFO|EAL: PCI device 0000:82:00.0 on NUMA socket 1
>2019-04-24T01:26:05.070Z|00020|dpdk|INFO|EAL:   probe driver: 19ee:4000 net_nfp_pf
>2019-04-24T01:26:05.070Z|00021|dpdk|INFO|EAL: PCI device 0000:84:00.0 on NUMA socket 1
>2019-04-24T01:26:05.070Z|00022|dpdk|INFO|EAL:   probe driver: 8086:1572 net_i40e
>2019-04-24T01:26:05.070Z|00023|dpdk|INFO|EAL: PCI device 0000:84:00.1 on NUMA socket 1
>2019-04-24T01:26:05.070Z|00024|dpdk|INFO|EAL:   probe driver: 8086:1572 net_i40e
>2019-04-24T01:26:05.070Z|00025|dpdk|INFO|EAL: PCI device 0000:84:02.0 on NUMA socket 1
>2019-04-24T01:26:05.070Z|00026|dpdk|INFO|EAL:   probe driver: 8086:154c net_i40e_vf
>2019-04-24T01:26:05.071Z|00027|dpdk|INFO|EAL:   using IOMMU type 1 (Type 1)
>2019-04-24T01:26:06.058Z|00028|dpdk|INFO|EAL: PCI device 0000:84:02.1 on NUMA socket 1
>2019-04-24T01:26:06.058Z|00029|dpdk|INFO|EAL:   probe driver: 8086:154c net_i40e_vf
>2019-04-24T01:26:07.023Z|00030|dpdk|INFO|DPDK Enabled - initialized
>2019-04-24T01:26:07.025Z|00031|bridge|INFO|ovs-vswitchd (Open vSwitch) 2.9.0
>2019-04-24T01:26:07.025Z|00032|timeval|WARN|Unreasonably long 6832ms poll interval (1378ms user, 4847ms system)
>2019-04-24T01:26:07.025Z|00033|timeval|WARN|faults: 16738 minor, 0 major
>2019-04-24T01:26:07.025Z|00034|timeval|WARN|context switches: 5 voluntary, 33 involuntary
>2019-04-24T01:26:07.025Z|00035|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour,  hash=736a30e5:
>2019-04-24T01:26:07.025Z|00036|coverage|INFO|bridge_reconfigure         0.2/sec     0.017/sec        0.0003/sec   total: 1
>2019-04-24T01:26:07.025Z|00037|coverage|INFO|cmap_expand                1.6/sec     0.133/sec        0.0022/sec   total: 8
>2019-04-24T01:26:07.025Z|00038|coverage|INFO|miniflow_malloc            1.6/sec     0.133/sec        0.0022/sec   total: 8
>2019-04-24T01:26:07.025Z|00039|coverage|INFO|hmap_pathological          0.2/sec     0.017/sec        0.0003/sec   total: 1
>2019-04-24T01:26:07.025Z|00040|coverage|INFO|hmap_expand               76.0/sec     6.333/sec        0.1056/sec   total: 380
>2019-04-24T01:26:07.025Z|00041|coverage|INFO|txn_unchanged              0.6/sec     0.050/sec        0.0008/sec   total: 3
>2019-04-24T01:26:07.025Z|00042|coverage|INFO|poll_create_node           8.0/sec     0.667/sec        0.0111/sec   total: 40
>2019-04-24T01:26:07.025Z|00043|coverage|INFO|seq_change                11.4/sec     0.950/sec        0.0158/sec   total: 57
>2019-04-24T01:26:07.025Z|00044|coverage|INFO|pstream_open               0.2/sec     0.017/sec        0.0003/sec   total: 1
>2019-04-24T01:26:07.025Z|00045|coverage|INFO|stream_open                0.2/sec     0.017/sec        0.0003/sec   total: 1
>2019-04-24T01:26:07.025Z|00046|coverage|INFO|util_xalloc              1477.8/sec   123.150/sec        2.0525/sec   total: 7389
>2019-04-24T01:26:07.025Z|00047|coverage|INFO|netdev_get_hwaddr          0.2/sec     0.017/sec        0.0003/sec   total: 1
>2019-04-24T01:26:07.025Z|00048|coverage|INFO|netlink_received           0.6/sec     0.050/sec        0.0008/sec   total: 3
>2019-04-24T01:26:07.025Z|00049|coverage|INFO|netlink_sent               0.2/sec     0.017/sec        0.0003/sec   total: 1
>2019-04-24T01:26:07.025Z|00050|coverage|INFO|90 events never hit
>2019-04-24T01:26:07.049Z|00051|poll_loop|INFO|wakeup due to [POLLIN] on fd 11 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (91% CPU usage)
>2019-04-24T01:26:07.049Z|00052|poll_loop|INFO|wakeup due to [POLLIN] on fd 11 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (91% CPU usage)
>2019-04-24T01:26:07.053Z|00053|poll_loop|INFO|wakeup due to [POLLIN] on fd 11 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (91% CPU usage)
>2019-04-24T01:26:07.053Z|00054|poll_loop|INFO|wakeup due to [POLLIN] on fd 11 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (91% CPU usage)
>2019-04-24T01:26:07.057Z|00055|poll_loop|INFO|wakeup due to [POLLIN] on fd 11 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (91% CPU usage)
>2019-04-24T01:26:07.057Z|00056|poll_loop|INFO|wakeup due to [POLLIN] on fd 11 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (91% CPU usage)
>2019-04-24T01:26:07.061Z|00057|poll_loop|INFO|wakeup due to [POLLIN] on fd 11 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (91% CPU usage)
>2019-04-24T01:26:07.061Z|00058|poll_loop|INFO|wakeup due to [POLLIN] on fd 11 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (91% CPU usage)
>2019-04-24T01:26:07.065Z|00059|poll_loop|INFO|wakeup due to [POLLIN] on fd 11 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (91% CPU usage)
>2019-04-24T01:26:07.065Z|00060|poll_loop|INFO|wakeup due to [POLLIN] on fd 11 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (91% CPU usage)
>2019-04-24T01:26:07.091Z|00061|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports recirculation
>2019-04-24T01:26:07.091Z|00062|ofproto_dpif|INFO|netdev@ovs-netdev: VLAN header stack length probed as 1
>2019-04-24T01:26:07.091Z|00063|ofproto_dpif|INFO|netdev@ovs-netdev: MPLS label stack length probed as 3
>2019-04-24T01:26:07.091Z|00064|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports truncate action
>2019-04-24T01:26:07.091Z|00065|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports unique flow ids
>2019-04-24T01:26:07.091Z|00066|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports clone action
>2019-04-24T01:26:07.091Z|00067|ofproto_dpif|INFO|netdev@ovs-netdev: Max sample nesting level probed as 10
>2019-04-24T01:26:07.091Z|00068|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports eventmask in conntrack action
>2019-04-24T01:26:07.091Z|00069|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_clear action
>2019-04-24T01:26:07.091Z|00070|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_state
>2019-04-24T01:26:07.091Z|00071|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_zone
>2019-04-24T01:26:07.091Z|00072|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_mark
>2019-04-24T01:26:07.091Z|00073|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_label
>2019-04-24T01:26:07.091Z|00074|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_state_nat
>2019-04-24T01:26:07.091Z|00075|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_orig_tuple
>2019-04-24T01:26:07.091Z|00076|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_orig_tuple6
>2019-04-24T01:26:07.196Z|00077|bridge|INFO|bridge br0: added interface br0 on port 65534
>2019-04-24T01:26:07.197Z|00078|bridge|INFO|bridge br0: using datapath ID 00002a7774e42148
>2019-04-24T01:26:07.197Z|00079|connmgr|INFO|br0: added service controller "punix:/var/run/openvswitch/br0.mgmt"
>2019-04-24T01:26:07.291Z|00080|dpif_netdev|INFO|PMD thread on numa_id: 1, core id: 17 created.
>2019-04-24T01:26:07.294Z|00081|dpif_netdev|INFO|PMD thread on numa_id: 1, core id: 23 created.
>2019-04-24T01:26:07.298Z|00082|dpif_netdev|INFO|PMD thread on numa_id: 1, core id: 15 created.
>2019-04-24T01:26:07.302Z|00083|dpif_netdev|INFO|PMD thread on numa_id: 1, core id: 11 created.
>2019-04-24T01:26:07.305Z|00084|dpif_netdev|INFO|PMD thread on numa_id: 1, core id:  9 created.
>2019-04-24T01:26:07.309Z|00085|dpif_netdev|INFO|PMD thread on numa_id: 1, core id: 21 created.
>2019-04-24T01:26:07.312Z|00086|dpif_netdev|INFO|PMD thread on numa_id: 1, core id: 13 created.
>2019-04-24T01:26:07.316Z|00087|dpif_netdev|INFO|PMD thread on numa_id: 1, core id: 19 created.
>2019-04-24T01:26:07.316Z|00088|dpif_netdev|INFO|There are 8 pmd threads on numa node 1
>2019-04-24T01:26:07.447Z|00089|netdev_dpdk|INFO|Virtual function detected, HW_CRC_STRIP will be enabled
>2019-04-24T01:26:07.927Z|00090|netdev_dpdk|INFO|Port 0: 00:00:00:00:00:01
>2019-04-24T01:26:07.928Z|00091|dpif_netdev|INFO|Core 17 on numa node 1 assigned port 'dpdk0' rx queue 0 (measured processing cycles 0).
>2019-04-24T01:26:07.928Z|00092|bridge|INFO|bridge br0: added interface dpdk0 on port 10
>2019-04-24T01:26:08.088Z|00093|bridge|INFO|bridge br0: using datapath ID 0000000000000001
>2019-04-24T01:26:10.390Z|00094|memory|INFO|598848 kB peak resident set size after 10.2 seconds
>2019-04-24T01:26:10.390Z|00095|memory|INFO|handlers:35 ports:2 revalidators:13 rules:5 udpif keys:4

Actions: View

Attachments on bug 1691682: 1546803 | 1557924