[ovs-discuss] OVS bad performance on lower packet size

Rahul Arora rahul1991.arora at gmail.com
Wed Dec 10 06:49:16 UTC 2014


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.arora at 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 <alexw at nicira.com> wrote:
>
>>
>> I believe it has 16 cores, with hyperthreading disabled,
>>
>> On Tue, Dec 9, 2014 at 9:37 PM, Rahul Arora <rahul1991.arora at 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 <alexw at 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.arora at 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 <alexw at 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.arora at 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
>>>>>>> discuss at openvswitch.org
>>>>>>> http://openvswitch.org/mailman/listinfo/discuss
>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://openvswitch.org/pipermail/ovs-discuss/attachments/20141210/884a8b8a/attachment-0002.html>


More information about the discuss mailing list