Hello Alex, Thanks for your immediate reply.
Alex, Can you please test the same performance with the same flow by enabling 2 cores of the server only.And share the performance report with me of OVS VS Kernel Bridge. On Wed, Dec 10, 2014 at 1:10 PM, Alex Wang <al...@nicira.com> wrote: > Hey Rahul, > > The warning means the handler threads was busying running for 16 seconds > before calling time_poll() again (in other words, before trying to sleep > again). > > The log showed suspiciously long system running. Definitely not expected, > > Could you confirm the ovs kernel module version via 'modinfo openvswitch'? > Never seen such warning with 2.3 kernel module, > > Thanks, > Alex Wang, > > On Tue, Dec 9, 2014 at 10:47 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
