Re: [dpdk-dev] Fwd: Fwd: high latency detected in IP pipeline example

[Olivier Matz <olivier.matz@6wind.com>]

Hi Victor,

I have no experience with ip_pipeline. I can at least say that this
latency is much higher that what you should get.

My initial thought was that you were using several pthreads bound to the
same core, but from what I read in your first mail, this is not the
case.

Do you have a simple way to reproduce your issue with the original
example app?


Olivier

On Wed, Feb 19, 2020 at 11:37:21AM +0100, Victor Huertas wrote:
> Hi ,
> 
> I put some maintainers as destination that could provide some extra
> information on this issue.
> I hope they can shed some light on this.
> 
> Regards
> 
> El mié., 19 feb. 2020 a las 9:29, Victor Huertas (<vhuertas@gmail.com>)
> escribió:
> 
> > OK James,
> > Thanks for sharing your own experience.
> > What I would need right now is to know from maintainers if this latency
> > behaviour is something inherent in DPDK  in the particular case we are
> > talking about. Furthermore, I would also appreciate it if some maintainer
> > could tell us if there is some workaround or special configuration that
> > completely mitigate this latency. I guess that there is one mitigation
> > mechanism, which is the approach that the new ip_pipeline app example
> > exposes: if two or more pipelines are in the same core the "connection"
> > between them is not a software queue but a "direct table connection".
> >
> > This proposed approach has a big impact on my application and I would like
> > to know if there is other mitigation approach taking into account the "old"
> > version of ip_pipeline example.
> >
> > Thanks for your attention
> >
> >
> > El mar., 18 feb. 2020 a las 23:09, James Huang (<jamsphon@gmail.com>)
> > escribió:
> >
> >> No. I didn't notice the RTT bouncing symptoms.
> >> In high throughput scenario, if multiple pipelines runs in a single cpu
> >> core, it does increase the latency.
> >>
> >>
> >> Regards,
> >> James Huang
> >>
> >>
> >> On Tue, Feb 18, 2020 at 1:50 AM Victor Huertas <vhuertas@gmail.com>
> >> wrote:
> >>
> >>> Dear James,
> >>>
> >>> I have done two different tests with the following configuration:
> >>> [PIPELINE 0 MASTER core =0]
> >>> [PIPELINE 1 core=1] --- SWQ1--->[PIPELINE 2 core=1] -----SWQ2---->
> >>> [PIPELINE 3 core=1]
> >>>
> >>> The first test (sending a single ping to cross all the pipelines to
> >>> measure RTT) has been done by setting the burst_write to 32 in SWQ1 and
> >>> SWQ2. NOTE: All the times we use rte_ring_enqueue_burst in the pipelines 1
> >>> and 2 we set the number of packets to write to 1.
> >>>
> >>> The result of this first test is as shown subsquently:
> >>> 64 bytes from 192.168.0.101: icmp_seq=343 ttl=63 time=59.8 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=344 ttl=63 time=59.4 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=345 ttl=63 time=59.2 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=346 ttl=63 time=59.0 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=347 ttl=63 time=59.0 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=348 ttl=63 time=59.2 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=349 ttl=63 time=59.3 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=350 ttl=63 time=59.1 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=351 ttl=63 time=58.9 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=352 ttl=63 time=58.5 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=353 ttl=63 time=58.4 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=354 ttl=63 time=58.0 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=355 ttl=63 time=58.4 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=356 ttl=63 time=57.7 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=357 ttl=63 time=56.9 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=358 ttl=63 time=57.2 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=359 ttl=63 time=57.5 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=360 ttl=63 time=57.3 ms
> >>>
> >>> As you can see, the RTT is quite high and the range of values is more or
> >>> less stable.
> >>>
> >>> The second test is the same as the first one but setting burst_write to
> >>> 1 for all SWQs. The result is this one:
> >>>
> >>> 64 bytes from 192.168.0.101: icmp_seq=131 ttl=63 time=10.6 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=132 ttl=63 time=10.6 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=133 ttl=63 time=10.5 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=134 ttl=63 time=10.7 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=135 ttl=63 time=10.8 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=136 ttl=63 time=10.4 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=137 ttl=63 time=10.7 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=138 ttl=63 time=10.5 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=139 ttl=63 time=10.4 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=140 ttl=63 time=10.2 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=141 ttl=63 time=10.4 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=142 ttl=63 time=10.9 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=143 ttl=63 time=11.4 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=144 ttl=63 time=11.3 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=145 ttl=63 time=11.5 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=146 ttl=63 time=11.6 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=147 ttl=63 time=11.0 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=148 ttl=63 time=11.3 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=149 ttl=63 time=12.0 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=150 ttl=63 time=12.6 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=151 ttl=63 time=12.4 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=152 ttl=63 time=12.3 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=153 ttl=63 time=12.8 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=154 ttl=63 time=12.4 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=155 ttl=63 time=12.8 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=156 ttl=63 time=12.7 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=157 ttl=63 time=12.6 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=158 ttl=63 time=12.9 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=159 ttl=63 time=13.4 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=160 ttl=63 time=13.8 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=161 ttl=63 time=13.4 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=162 ttl=63 time=13.3 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=163 ttl=63 time=13.3 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=164 ttl=63 time=13.7 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=165 ttl=63 time=13.7 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=166 ttl=63 time=13.8 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=167 ttl=63 time=14.7 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=168 ttl=63 time=14.7 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=169 ttl=63 time=14.7 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=170 ttl=63 time=14.7 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=171 ttl=63 time=14.6 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=172 ttl=63 time=14.6 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=173 ttl=63 time=14.5 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=174 ttl=63 time=14.5 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=175 ttl=63 time=15.1 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=176 ttl=63 time=15.6 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=177 ttl=63 time=16.0 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=178 ttl=63 time=16.9 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=179 ttl=63 time=17.7 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=180 ttl=63 time=17.6 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=181 ttl=63 time=17.9 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=182 ttl=63 time=17.9 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=183 ttl=63 time=18.5 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=184 ttl=63 time=18.9 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=185 ttl=63 time=19.8 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=186 ttl=63 time=19.8 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=187 ttl=63 time=10.7 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=188 ttl=63 time=10.5 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=189 ttl=63 time=10.4 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=190 ttl=63 time=10.3 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=191 ttl=63 time=10.5 ms
> >>> 64 bytes from 192.168.0.101: icmp_seq=192 ttl=63 time=10.7 ms
> >>> As you mentioned, the delay has decreased a lot but it is still
> >>> considerably high (in a normal router this delay is less than 1 ms).
> >>> A second strange behaviour is seen in the evolution of the RTT detected.
> >>> It begins in 10 ms and goes increasing little by litttle to reach a peak of
> >>> 20 ms aprox and then it suddely comes back to 10 ms again to increase again
> >>> till 20 ms.
> >>>
> >>> Is this the behaviour you have in your case when the burst_write is set
> >>> to 1?
> >>>
> >>> Regards,
> >>>
> >>> El mar., 18 feb. 2020 a las 8:18, James Huang (<jamsphon@gmail.com>)
> >>> escribió:
> >>>
> >>>> No. We didn't see noticable throughput difference in our test.
> >>>>
> >>>> On Mon., Feb. 17, 2020, 11:04 p.m. Victor Huertas <vhuertas@gmail.com>
> >>>> wrote:
> >>>>
> >>>>> Thanks James for your quick answer.
> >>>>> I guess that this configuration modification implies that the packets
> >>>>> must be written one by one in the sw ring. Did you notice loose of
> >>>>> performance (in throughput) in your aplicación because of that?
> >>>>>
> >>>>> Regards
> >>>>>
> >>>>> El mar., 18 feb. 2020 0:10, James Huang <jamsphon@gmail.com> escribió:
> >>>>>
> >>>>>> Yes, I experienced similar issue in my application. In a short
> >>>>>> answer, set the swqs write burst value to 1 may reduce the latency
> >>>>>> significantly. The default write burst value is 32.
> >>>>>>
> >>>>>> On Mon., Feb. 17, 2020, 8:41 a.m. Victor Huertas <vhuertas@gmail.com>
> >>>>>> wrote:
> >>>>>>
> >>>>>>> Hi all,
> >>>>>>>
> >>>>>>> I am developing my own DPDK application basing it in the dpdk-stable
> >>>>>>> ip_pipeline example.
> >>>>>>> At this moment I am using the 17.11 LTS version of DPDK and I amb
> >>>>>>> observing
> >>>>>>> some extrange behaviour. Maybe it is an old issue that can be solved
> >>>>>>> quickly so I would appreciate it if some expert can shade a light on
> >>>>>>> this.
> >>>>>>>
> >>>>>>> The ip_pipeline example allows you to develop Pipelines that perform
> >>>>>>> specific packet processing functions (ROUTING, FLOW_CLASSIFYING,
> >>>>>>> etc...).
> >>>>>>> The thing is that I am extending some of this pipelines with my own.
> >>>>>>> However I want to take advantage of the built-in ip_pipeline
> >>>>>>> capability of
> >>>>>>> arbitrarily assigning the logical core where the pipeline (f_run()
> >>>>>>> function) must be executed so that i can adapt the packet processing
> >>>>>>> power
> >>>>>>> to the amount of the number of cores available.
> >>>>>>> Taking this into account I have observed something strange. I show
> >>>>>>> you this
> >>>>>>> simple example below.
> >>>>>>>
> >>>>>>> Case 1:
> >>>>>>> [PIPELINE 0 MASTER core =0]
> >>>>>>> [PIPELINE 1 core=1] --- SWQ1--->[PIPELINE 2 core=2] -----SWQ2---->
> >>>>>>> [PIPELINE 3 core=3]
> >>>>>>>
> >>>>>>> Case 2:
> >>>>>>> [PIPELINE 0 MASTER core =0]
> >>>>>>> [PIPELINE 1 core=1] --- SWQ1--->[PIPELINE 2 core=1] -----SWQ2---->
> >>>>>>> [PIPELINE 3 core=1]
> >>>>>>>
> >>>>>>> I send a ping between two hosts connected at both sides of the
> >>>>>>> pipeline
> >>>>>>> model which allows these pings to cross all the pipelines (from 1 to
> >>>>>>> 3).
> >>>>>>> What I observe in Case 1 (each pipeline has its own thread in
> >>>>>>> different
> >>>>>>> core) is that the reported RTT is less than 1 ms, whereas in Case 2
> >>>>>>> (all
> >>>>>>> pipelines except MASTER are run in the same thread) is 20 ms.
> >>>>>>> Furthermore,
> >>>>>>> in Case 2, if I increase a lot (hundreds of Mbps) the packet rate
> >>>>>>> this RTT
> >>>>>>> decreases to 3 or 4 ms.
> >>>>>>>
> >>>>>>> Has somebody observed this behaviour in the past? Can it be solved
> >>>>>>> somehow?
> >>>>>>>
> >>>>>>> Thanks a lot for your attention
> >>>>>>> --
> >>>>>>> Victor
> >>>>>>>
> >>>>>>>
> >>>>>>> --
> >>>>>>> Victor
> >>>>>>>
> >>>>>>
> >>>
> >>> --
> >>> Victor
> >>>
> >>
> >
> > --
> > Victor
> >
> 
> 
> -- 
> Victor