These logs are coming from *lib/timeval.c *under the function *log_poll_interval* in OVS source code.
On Wed, Dec 10, 2014 at 12:17 PM, Rahul Arora <rahul1991.ar...@gmail.com> wrote: > Alex, > > I am getting these logs when i am getting 100% CPU usage. > > Please have a look on the RED part. > > ====================================== > 2014-11-25T06:04:37.604Z|00095|timeval(handler5)|WARN|Unreasonably long > 16127ms poll interval (260ms user, 17320ms system) > 2014-11-25T06:04:37.604Z|00096|timeval(handler5)|WARN|faults: 8062 minor, > 0 major > 2014-11-25T06:04:37.604Z|00097|timeval(handler5)|WARN|context switches: > 2424 voluntary, 670 involuntary > 2014-11-25T06:04:37.604Z|00098|coverage(handler5)|INFO|Event coverage, avg > rate over last: 5 seconds, last minute, last hour, hash=9b29cbda: > 2014-11-25T06:04:37.604Z|00099|coverage(handler5)|INFO|netlink_sent > 211.0/sec 77.300/sec 3.8958/sec total: 15051 > 2014-11-25T06:04:37.604Z|00100|coverage(handler5)|INFO|netlink_recv_jumbo > 0.4/sec 0.400/sec 0.0536/sec total: 195 > 2014-11-25T06:04:37.604Z|00101|coverage(handler5)|INFO|netlink_received > 213.0/sec 78.983/sec 4.1219/sec total: 15873 > 2014-11-25T06:04:37.604Z|00102|coverage(handler5)|INFO|netlink_overflow > 0.0/sec 0.033/sec 0.0011/sec total: 4 > 2014-11-25T06:04:37.604Z|00103|coverage(handler5)|INFO|netdev_set_ethtool > 0.0/sec 0.000/sec 0.0006/sec total: 2 > 2014-11-25T06:04:37.604Z|00104|coverage(handler5)|INFO|netdev_get_ethtool > 0.0/sec 0.000/sec 0.0028/sec total: 10 > 2014-11-25T06:04:37.605Z|00105|coverage(handler5)|INFO|netdev_set_hwaddr > 0.0/sec 0.000/sec 0.0008/sec total: 3 > 2014-11-25T06:04:37.605Z|00106|coverage(handler5)|INFO|netdev_get_hwaddr > 0.0/sec 0.000/sec 0.0008/sec total: 3 > 2014-11-25T06:04:37.605Z|00107|coverage(handler5)|INFO|netdev_get_ifindex > 0.0/sec 0.000/sec 0.0008/sec total: 3 > 2014-11-25T06:04:37.605Z|00108|coverage(handler5)|INFO|netdev_set_policing > 0.0/sec 0.000/sec 0.0017/sec total: 6 > 2014-11-25T06:04:37.605Z|00109|coverage(handler5)|INFO|vconn_sent > 0.0/sec 0.000/sec 0.0014/sec total: 5 > 2014-11-25T06:04:37.605Z|00110|coverage(handler5)|INFO|vconn_received > 0.0/sec 0.000/sec 0.0019/sec total: 7 > 2014-11-25T06:04:37.605Z|00111|coverage(handler5)|INFO|util_xalloc > 396.6/sec 367.317/sec 50.7611/sec total: 184603 > 2014-11-25T06:04:37.605Z|00112|coverage(handler5)|INFO|stream_open > 0.0/sec 0.000/sec 0.0003/sec total: 1 > 2014-11-25T06:04:37.605Z|00113|coverage(handler5)|INFO|pstream_open > 0.0/sec 0.000/sec 0.0008/sec total: 3 > 2014-11-25T06:04:37.605Z|00114|coverage(handler5)|INFO|rconn_sent > 0.0/sec 0.000/sec 0.0008/sec total: 3 > 2014-11-25T06:04:37.605Z|00115|coverage(handler5)|INFO|rconn_queued > 0.0/sec 0.000/sec 0.0008/sec total: 3 > 2014-11-25T06:04:37.605Z|00116|coverage(handler5)|INFO|poll_zero_timeout > 0.0/sec 0.000/sec 0.0031/sec total: 11 > 2014-11-25T06:04:37.605Z|00117|coverage(handler5)|INFO|poll_fd_wait > 30.0/sec 29.617/sec 4.1908/sec total: 15201 > 2014-11-25T06:04:37.605Z|00118|coverage(handler5)|INFO|txn_success > 0.0/sec 0.000/sec 0.0017/sec total: 6 > 2014-11-25T06:04:37.605Z|00119|coverage(handler5)|INFO|txn_incomplete > 0.2/sec 0.183/sec 0.0278/sec total: 101 > 2014-11-25T06:04:37.605Z|00120|coverage(handler5)|INFO|txn_unchanged > 0.0/sec 0.017/sec 0.0075/sec total: 27 > 2014-11-25T06:04:37.605Z|00121|coverage(handler5)|INFO|netdev_get_stats > 0.6/sec 0.600/sec 0.0811/sec total: 295 > 2014-11-25T06:04:37.605Z|00122|coverage(handler5)|INFO|mac_learning_expired > 0.0/sec 0.000/sec 0.0003/sec total: 1 > 2014-11-25T06:04:37.605Z|00123|coverage(handler5)|INFO|mac_learning_learned > 0.0/sec 0.000/sec 0.0003/sec total: 1 > 2014-11-25T06:04:37.605Z|00124|coverage(handler5)|INFO|hmap_expand > 18.4/sec 17.883/sec 2.5731/sec total: 9337 > 2014-11-25T06:04:37.605Z|00125|coverage(handler5)|INFO|hmap_pathological > 0.0/sec 0.000/sec 0.0053/sec total: 19 > 2014-11-25T06:04:37.605Z|00126|coverage(handler5)|INFO|flow_extract > 200.0/sec 70.417/sec 3.1047/sec total: 12150 > 2014-11-25T06:04:37.605Z|00127|coverage(handler5)|INFO|dpif_execute > 0.0/sec 0.000/sec 0.0003/sec total: 1 > 2014-11-25T06:04:37.605Z|00128|coverage(handler5)|INFO|dpif_flow_put > 0.0/sec 0.000/sec 0.0006/sec total: 2 > 2014-11-25T06:04:37.605Z|00129|coverage(handler5)|INFO|dpif_flow_flush > 0.0/sec 0.000/sec 0.0006/sec total: 2 > 2014-11-25T06:04:37.605Z|00130|coverage(handler5)|INFO|dpif_port_add > 0.0/sec 0.000/sec 0.0008/sec total: 3 > 2014-11-25T06:04:37.605Z|00131|coverage(handler5)|INFO|xlate_actions > 4.0/sec 1.433/sec 0.0656/sec total: 256 > 2014-11-25T06:04:37.605Z|00132|coverage(handler5)|INFO|rev_mac_learning > 0.0/sec 0.000/sec 0.0006/sec total: 2 > 2014-11-25T06:04:37.605Z|00133|coverage(handler5)|INFO|rev_flow_table > 0.0/sec 0.000/sec 0.0006/sec total: 2 > 2014-11-25T06:04:37.605Z|00134|coverage(handler5)|INFO|rev_port_toggled > 0.0/sec 0.000/sec 0.0003/sec total: 1 > 2014-11-25T06:04:37.605Z|00135|coverage(handler5)|INFO|rev_reconfigure > 0.0/sec 0.000/sec 0.0008/sec total: 3 > 2014-11-25T06:04:37.605Z|00136|coverage(handler5)|INFO|ofproto_update_port > 0.0/sec 0.000/sec 0.0025/sec total: 9 > 2014-11-25T06:04:37.605Z|00137|coverage(handler5)|INFO|ofproto_recv_openflow > 0.0/sec 0.000/sec 0.0014/sec total: 5 > 2014-11-25T06:04:37.605Z|00138|coverage(handler5)|INFO|ofproto_flush > 0.0/sec 0.000/sec 0.0003/sec total: 1 > 2014-11-25T06:04:37.605Z|00139|coverage(handler5)|INFO|bridge_reconfigure > 0.0/sec 0.000/sec 0.0011/sec total: 4 > 2014-11-25T06:04:37.605Z|00140|coverage(handler5)|INFO|49 events never hit > ======================================================================== > > > Do you have some idea how i can optimize it? > > On Wed, Dec 10, 2014 at 11:41 AM, Alex Wang <al...@nicira.com> wrote: > >> >> I believe it has 16 cores, with hyperthreading disabled, >> >> On Tue, Dec 9, 2014 at 9:37 PM, Rahul Arora <rahul1991.ar...@gmail.com> >> wrote: >> >>> Hi Alex, >>> >>> The platform which you are using for your performance testing is of how >>> many cores?? >>> >>> On Tue, Dec 9, 2014 at 10:45 PM, Alex Wang <al...@nicira.com> wrote: >>> >>>> Hey Rahul, >>>> >>>> The kernel version should not make a difference, >>>> >>>> I'm curious, since ovs-2.3.0 is multithreaded, not sure how do you >>>> measure >>>> the cpu usage to be 100%? >>>> >>>> Also, could you post the full `mpstat -P ALL` output, so we can see the >>>> distribution of cpu usage, >>>> >>>> >>>> Thanks, >>>> Alex Wang, >>>> >>>> >>>> >>>> On Tue, Dec 9, 2014 at 1:49 AM, Rahul Arora <rahul1991.ar...@gmail.com> >>>> wrote: >>>> >>>>> Hi Alex, >>>>> >>>>> Thanks for your help. >>>>> >>>>> I am using the following command to test CPU usage. >>>>> >>>>> mpstat -P ALL 1 >>>>> >>>>> I was using 3.12 kernel version and you are using 3.13.0-30-generic >>>>> version.Please let me know if this can be the issue?? >>>>> >>>>> >>>>> >>>>> On Sat, Dec 6, 2014 at 5:04 AM, Alex Wang <al...@nicira.com> wrote: >>>>> >>>>>> Hey Rahul, >>>>>> >>>>>> Could you help confirm the following: >>>>>> >>>>>> 1. did you use vm or bare metal machine for testing? >>>>>> >>>>>> 2. how do you measure the cpu utilization of ovs and kernel bridge? >>>>>> >>>>>> >>>>>> We ran some throughput tests, and we observed constant better >>>>>> performance over the Linux bridge. >>>>>> >>>>>> Below is a set of our own throughput test result using ovs branch-2.3. >>>>>> >>>>>> Plateform: >>>>>> Server Dell R620, running Ubuntu 14.04 (3.13.0-30-generic), NIC is >>>>>> Intel X540. >>>>>> >>>>>> Flow: >>>>>> Single flow, "in_port=1,actions:output=2" >>>>>> >>>>>> Traffic type: >>>>>> - unidirectional TCP throughput using Spirent (1 flow and 128 flows). >>>>>> >>>>>> >>>>>> *Throughput view (unit: Gbit/s):* >>>>>> >>>>>> Linux Bridge, >>>>>> Frame Size1 flow128 flow780.6021.5121280.9812.1892561.8155.433512 >>>>>> 3.2525.29910246.65810.015149.6849.98790009.92110.0 >>>>>> >>>>>> OVS Branch-2.3: >>>>>> Frame Size1 flow128 flow780.78.2581281.09810.02561.89810.05123.694 >>>>>> 10.010247.1910.015149.8849.98790009.89910.0 >>>>>> >>>>>> >>>>>> >>>>>> *Frame Per Second view (unit: Frames/s):* >>>>>> >>>>>> Linux Bridge, >>>>>> Frame Size1 flow128 flow7876805719290121288289121849112256822070 >>>>>> 246063051276405812450201024797193119731815147891418138029000137491 >>>>>> 138581 >>>>>> >>>>>> OVS Branch-2.3: >>>>>> Frame Size1 flow128 flow78892857105337071289272998445946256859386 >>>>>> 452898551286805523496241024860881119731815148054128138029000137181 >>>>>> 138581 >>>>>> >>>>>> >>>>>> Thanks, >>>>>> Alex Wang, >>>>>> >>>>>> On Wed, Nov 26, 2014 at 10:35 PM, Rahul Arora < >>>>>> rahul1991.ar...@gmail.com> wrote: >>>>>> >>>>>>> Hi Team, >>>>>>> >>>>>>> We are doing comparison of throughput and CPU consumption between >>>>>>> OVS 2.3.0 and kernel bridge with different packet size. >>>>>>> >>>>>>> We are observing huge difference in performance. With frame size 64 >>>>>>> and 128 bytes unidirectional traffic from port1 to port2 below are the >>>>>>> numbers. >>>>>>> >>>>>>> >>>>>>> *OVS 2.3.0 (Dual core with matching flow in kernel space, kernel >>>>>>> 3.12)* >>>>>>> >>>>>>> * kernel bridge(Dual Core System, kernel 3.12) * *FRAME SIZE* >>>>>>> *Throughput >>>>>>> unidirectional (Mbps)* *CPU Usage %* *VS* *FRAME SIZE* *Throughput >>>>>>> (Mbps)* *CPU Usage %* 64 375 100 64 487 100 128 747 100 128 864 40 >>>>>>> 256 927 10 256 927 5 320 941 8 320 941 4 384 950 6 384 950 4 448 >>>>>>> 957 4 448 957 3 512 962 3 512 962 3 1024 980 1 1024 980 1 1500 >>>>>>> 986 1 1500 986 1 >>>>>>> We have matching flow in kernel space with in_port=1 and >>>>>>> action=output:2 and flow is matching in kernel space >>>>>>> >>>>>>> How we can improve the performance of OVS i.e. increasing the >>>>>>> throughput and decrease CPU consumption with lower frame size. >>>>>>> >>>>>>> _______________________________________________ >>>>>>> discuss mailing list >>>>>>> disc...@openvswitch.org >>>>>>> http://openvswitch.org/mailman/listinfo/discuss >>>>>>> >>>>>>> >>>>>> >>>>> >>>> >>> >> >
_______________________________________________ openflow-discuss mailing list openflow-discuss@lists.stanford.edu https://mailman.stanford.edu/mailman/listinfo/openflow-discuss
