[dpdk-dev] phantom old packets received in new mbuf

[dpdk-dev] phantom old packets received in new mbuf

[Helmut Sim]

Hi All,

I face a very strange behavior.
I do:
rte_eth_rx_burst(port[i].portid, 0, pkts_burst, MAX_PKT_BURST)

then I reassemble the received UDP segments into one packet (i used the
ip_reassembly example), manipulate its content and send it back to the
network after fragmenting the packet.
This works great, ...well only most of the time it works great...

sometimes it happens that a packet is reassembled and retransmitted to the
network, and after a while I receive one of its segment instead of a a
segment of a totally different packet...

i.e.
rx seg 1 of pkt.id x
rx seg 2 of pkt.id x
rx seg 3 of pkt.id x
rx seg 4 of pkt.id x

packet is reassembled and sent to the network.

then i get:
rx seg 1 of pkt.id y
rx seg 2 of pkt.id y
rx seg 3 of pkt.id y
rx seg 2 of pkt.id x

....

it looks like the pmd gives me a mbuf that points to an old  freed buffer
instead of a new allocated buffer with the new segment data.
or alternatively, the pmd allocates the buffer but doesn't copy the rx data
into it...

the input packets were checked with a wireshark and it fits my description
above.

I checked it with different level of delay between the packets, but it
still happens.

I am using dpdk 1.6.0 r2.
specifically running over an ubuntu 14.04 server on a xen hypervisor using
the NIC 82576 as pci passthrough mode.
using one single port and one single queue.

obviously I suspect that the problem is at my side, but couldn't find it,
...yet.

Any idea or known issue?

Thanks
Sim

Re: [dpdk-dev] phantom old packets received in new mbuf

[Helmut Sim]

Hi,

I still can't get over this issue and need some help here.

in order to investigate this issue i wrote a very simple app that do:
        rte_eth_rx_burst(port[i].portid, 0, pkts_burst, MAX_PKT_BURST)
        printf the udp pkt content
        rte_pktmbuf_free(pkts_burst[j]);

on my host i wrote a simple udp app:
        for i=0 to n, do
            sprintf(buf, "PKT %d", i++);
            send buf over udp (i tried several lengths)
            sleep(i have tried delay values from 0 to 1000 us)
        end

then i see that from time to time i get a packet that was already received
earlier instead of receiving the expected packet.
the output is:
PKT 12201
PKT 12202
PKT 12203
PKT 12204
PKT 12205
PKT 12206
PKT 12202
PKT 12208

total received pkts is identical to the total delivered pkts, but part of
the pkts are being received twice...
the testpmd application doens't give me tools to check it as there are no
content aware tests.

as smaller is the delay between pkts the probability to see this behaviour
is higher.
I've tried this with other NIC as well (82575) but got similar behavior.
I've tried it over my desktop as well as over a VM on my XEON, same
behaviour...

i've printed the pktmbuf pointer values and found that the duplicated pkts
use different pktmbufs.

My question is what tools do I have to start investigating it.

I've played with the rte_eth_rxconf possible values but it didn't help.

Since it looks like a basic issue I'm pretty sure it is a kind of
configuration problem.

any idea?


Thanks in advance,




On Sun, Jul 6, 2014 at 6:19 PM, Helmut Sim <simhelmut@gmail.com> wrote:

> Hi All,
>
> I face a very strange behavior.
> I do:
> rte_eth_rx_burst(port[i].portid, 0, pkts_burst, MAX_PKT_BURST)
>
> then I reassemble the received UDP segments into one packet (i used the
> ip_reassembly example), manipulate its content and send it back to the
> network after fragmenting the packet.
> This works great, ...well only most of the time it works great...
>
> sometimes it happens that a packet is reassembled and retransmitted to the
> network, and after a while I receive one of its segment instead of a a
> segment of a totally different packet...
>
> i.e.
> rx seg 1 of pkt.id x
> rx seg 2 of pkt.id x
> rx seg 3 of pkt.id x
> rx seg 4 of pkt.id x
>
> packet is reassembled and sent to the network.
>
> then i get:
> rx seg 1 of pkt.id y
> rx seg 2 of pkt.id y
> rx seg 3 of pkt.id y
> rx seg 2 of pkt.id x
>
> ....
>
> it looks like the pmd gives me a mbuf that points to an old  freed buffer
> instead of a new allocated buffer with the new segment data.
> or alternatively, the pmd allocates the buffer but doesn't copy the rx
> data into it...
>
> the input packets were checked with a wireshark and it fits my description
> above.
>
> I checked it with different level of delay between the packets, but it
> still happens.
>
> I am using dpdk 1.6.0 r2.
> specifically running over an ubuntu 14.04 server on a xen hypervisor using
> the NIC 82576 as pci passthrough mode.
> using one single port and one single queue.
>
> obviously I suspect that the problem is at my side, but couldn't find it,
> ...yet.
>
> Any idea or known issue?
>
>  Thanks
> Sim
>

Re: [dpdk-dev] phantom old packets received in new mbuf

[Thomas Monjalon]

Hi,

2014-07-16 13:56, Helmut Sim:
> then i see that from time to time i get a packet that was already received
> earlier instead of receiving the expected packet.
> the output is:
> PKT 12201
> PKT 12202
> PKT 12203
> PKT 12204
> PKT 12205
> PKT 12206
> PKT 12202
> PKT 12208
> 
> total received pkts is identical to the total delivered pkts, but part of
> the pkts are being received twice...

It's an interesting issue. Could you list drivers and NICs you have tested?
Are you using a virtualized environment?

I think the best tools you can use are logs and gdb.
But maybe someone will have an idea of the cause when you'll describe impacted 
PMDs and environment.

-- 
Thomas

Re: [dpdk-dev] phantom old packets received in new mbuf

[Olivier MATZ]

Hello Helmut,

2014-07-16 13:56, Helmut Sim:
>> then i see that from time to time i get a packet that was already received
>> earlier instead of receiving the expected packet.
>> the output is:
>> PKT 12201
>> PKT 12202
>> PKT 12203
>> PKT 12204
>> PKT 12205
>> PKT 12206
>> PKT 12202
>> PKT 12208
>>
>> total received pkts is identical to the total delivered pkts, but part of
>> the pkts are being received twice...

Enabling CONFIG_RTE_LIBRTE_MEMPOOL_DEBUG and
CONFIG_RTE_LIBRTE_MBUF_DEBUG could help you to track
double free or corruptions.

Regards,
Olivier

Re: [dpdk-dev] phantom old packets received in new mbuf

[Helmut Sim]

I will try it though I hope the amount of logs won't affect the result.
while analyzing the wireshark captures I noted that the packet i supposed
to capture arrives in a short time after the one before.
for example, here is a time between the consecutive transmitted packets:
0.000050000 PKT 12201
0.000050000 PKT 12202
0.000050000 PKT 12203
0.000050000 PKT 12204
0.000050000 PKT 12205
0.000050000 PKT 12206
0.000020000 PKT 12207 ==> though this one was received at the app as "PKT
12202"
0.000050000 PKT 12208

note that the problematic case was transmitted in a very short time after
its previous one. this is also the case in other problematic cases.

is there any way to configure ethernet IFG (Interf Frame Gap)?

Thanks,


On Wed, Jul 16, 2014 at 3:18 PM, Olivier MATZ <olivier.matz@6wind.com>
wrote:

> Hello Helmut,
>
>
> 2014-07-16 13:56, Helmut Sim:
>
>> then i see that from time to time i get a packet that was already received
>>> earlier instead of receiving the expected packet.
>>> the output is:
>>> PKT 12201
>>> PKT 12202
>>> PKT 12203
>>> PKT 12204
>>> PKT 12205
>>> PKT 12206
>>> PKT 12202
>>> PKT 12208
>>>
>>> total received pkts is identical to the total delivered pkts, but part of
>>> the pkts are being received twice...
>>>
>>
> Enabling CONFIG_RTE_LIBRTE_MEMPOOL_DEBUG and
> CONFIG_RTE_LIBRTE_MBUF_DEBUG could help you to track
> double free or corruptions.
>
> Regards,
> Olivier
>
>

Re: [dpdk-dev] phantom old packets received in new mbuf

[Helmut Sim]

The CONFIG_RTE_LIBRTE_MEMPOOL_DEBUG and CONFIG_RTE_LIBRTE_MBUF_DEBUG didn't
provide any input, so I also added the CONFIG_RTE_LIBRTE_ETHDEV_DEBUG and
CONFIG_RTE_LIBRTE_IGB_PMD.

below is a sample log showing the problem, though I don't see any clue in
the logs.
in this case pkt 58509 is placed at the place of pkt 58637...
I also noted that the diff between the two packets is 128, and this is the
case in most of the cases where it happens...
the rx_id of the phantom pkt (58509) is 141 (port_id=0 queue_id=0 rx_id=141
staterr=0x3 pkt_len=146)

.....still digging

port_id=0 queue_id=0 rx_id=264 staterr=0x3 pkt_len=146


PMD: eth_igb_recv_pkts():

port_id=0 queue_id=0 rx_id=265 staterr=0x3 pkt_len=146


PMD: eth_igb_recv_pkts():

port_id=0 queue_id=0 rx_id=266 staterr=0x3 pkt_len=146


PMD: eth_igb_recv_pkts():

port_id=0 queue_id=0 rx_id=267 staterr=0x3 pkt_len=146


PMD: eth_igb_recv_pkts(): port_id=0 queue_id=0 rx_tail=268 nb_hold=4 nb_rx=4


IM_LOG_VFLOWCOM: input: START_10 58632

IM_LOG_VFLOWCOM: input: START_10 58633

IM_LOG_VFLOWCOM: input: START_10 58634

IM_LOG_VFLOWCOM: input: START_10 58635

PMD: eth_igb_recv_pkts():

port_id=0 queue_id=0 rx_id=268 staterr=0x3 pkt_len=146


PMD: eth_igb_recv_pkts():

port_id=0 queue_id=0 rx_id=269 staterr=0x3 pkt_len=146


PMD: eth_igb_recv_pkts():

port_id=0 queue_id=0 rx_id=270 staterr=0x3 pkt_len=146


PMD: eth_igb_recv_pkts():

port_id=0 queue_id=0 rx_id=271 staterr=0x3 pkt_len=146


PMD: eth_igb_recv_pkts(): port_id=0 queue_id=0 rx_tail=272 nb_hold=4 nb_rx=4


IM_LOG_VFLOWCOM: input: START_10 58636

IM_LOG_VFLOWCOM: input: START_10 58509

IM_LOG_VFLOWCOM: wrong pkt number arrived from burst 4, expected 58637 but
got 58509

IM_LOG_VFLOWCOM: input: START_10 58638

IM_LOG_VFLOWCOM: input: START_10 58639

PMD: eth_igb_recv_pkts():

port_id=0 queue_id=0 rx_id=272 staterr=0x3 pkt_len=146


PMD: eth_igb_recv_pkts():

port_id=0 queue_id=0 rx_id=273 staterr=0x3 pkt_len=146


PMD: eth_igb_recv_pkts():

port_id=0 queue_id=0 rx_id=274 staterr=0x3 pkt_len=146


PMD: eth_igb_recv_pkts():

port_id=0 queue_id=0 rx_id=275 staterr=0x3 pkt_len=146


PMD: eth_igb_recv_pkts(): port_id=0 queue_id=0 rx_tail=276 nb_hold=4 nb_rx=4


IM_LOG_VFLOWCOM: input: START_10 58640

IM_LOG_VFLOWCOM: input: START_10 58641

IM_LOG_VFLOWCOM: input: START_10 58642

IM_LOG_VFLOWCOM: input: START_10 58643



On Wed, Jul 16, 2014 at 3:36 PM, Helmut Sim <simhelmut@gmail.com> wrote:

> I will try it though I hope the amount of logs won't affect the result.
> while analyzing the wireshark captures I noted that the packet i supposed
> to capture arrives in a short time after the one before.
> for example, here is a time between the consecutive transmitted packets:
> 0.000050000 PKT 12201
> 0.000050000 PKT 12202
> 0.000050000 PKT 12203
> 0.000050000 PKT 12204
> 0.000050000 PKT 12205
> 0.000050000 PKT 12206
> 0.000020000 PKT 12207 ==> though this one was received at the app as "PKT
> 12202"
> 0.000050000 PKT 12208
>
> note that the problematic case was transmitted in a very short time after
> its previous one. this is also the case in other problematic cases.
>
> is there any way to configure ethernet IFG (Interf Frame Gap)?
>
> Thanks,
>
>
> On Wed, Jul 16, 2014 at 3:18 PM, Olivier MATZ <olivier.matz@6wind.com>
> wrote:
>
>> Hello Helmut,
>>
>>
>> 2014-07-16 13:56, Helmut Sim:
>>
>>> then i see that from time to time i get a packet that was already
>>>> received
>>>> earlier instead of receiving the expected packet.
>>>> the output is:
>>>> PKT 12201
>>>> PKT 12202
>>>> PKT 12203
>>>> PKT 12204
>>>> PKT 12205
>>>> PKT 12206
>>>> PKT 12202
>>>> PKT 12208
>>>>
>>>> total received pkts is identical to the total delivered pkts, but part
>>>> of
>>>> the pkts are being received twice...
>>>>
>>>
>> Enabling CONFIG_RTE_LIBRTE_MEMPOOL_DEBUG and
>> CONFIG_RTE_LIBRTE_MBUF_DEBUG could help you to track
>> double free or corruptions.
>>
>> Regards,
>> Olivier
>>
>>
>

Re: [dpdk-dev] phantom old packets received in new mbuf

[Helmut Sim]

Just to update, root cause is found...
the problem is not at the dpdk rx side but at the transmit side (using
sendto app).

when transmitting through NICs models 82575 or 82576 (sendto app), the
receiver reads it well using the DPDK rx program.
however when using NIC 82541gi as transmitter (sendto app), the DPDK
receiver reads it wrong.

I puted a first sniffer on the transmitting NIC and a second sniffer on the
cable between the two NICs and found out that: while the first sniffer
reads correct sequence of packets, the second sniffer reads wrong sequence
(in fact an old packet replaces a new packet...).

All of my six 82541gi NICs behaves at the same way... :(
maybe it is a driver issue (will look for it latter).

Thank for your advices and assistance,




On Wed, Jul 16, 2014 at 4:22 PM, Helmut Sim <simhelmut@gmail.com> wrote:

> The CONFIG_RTE_LIBRTE_MEMPOOL_DEBUG and CONFIG_RTE_LIBRTE_MBUF_DEBUG
> didn't provide any input, so I also added the
> CONFIG_RTE_LIBRTE_ETHDEV_DEBUG and CONFIG_RTE_LIBRTE_IGB_PMD.
>
> below is a sample log showing the problem, though I don't see any clue in
> the logs.
> in this case pkt 58509 is placed at the place of pkt 58637...
> I also noted that the diff between the two packets is 128, and this is the
> case in most of the cases where it happens...
> the rx_id of the phantom pkt (58509) is 141 (port_id=0 queue_id=0
> rx_id=141 staterr=0x3 pkt_len=146)
>
> .....still digging
>
> port_id=0 queue_id=0 rx_id=264 staterr=0x3 pkt_len=146
>
>
> PMD: eth_igb_recv_pkts():
>
> port_id=0 queue_id=0 rx_id=265 staterr=0x3 pkt_len=146
>
>
> PMD: eth_igb_recv_pkts():
>
> port_id=0 queue_id=0 rx_id=266 staterr=0x3 pkt_len=146
>
>
> PMD: eth_igb_recv_pkts():
>
> port_id=0 queue_id=0 rx_id=267 staterr=0x3 pkt_len=146
>
>
> PMD: eth_igb_recv_pkts(): port_id=0 queue_id=0 rx_tail=268 nb_hold=4
> nb_rx=4
>
>
> IM_LOG_VFLOWCOM: input: START_10 58632
>
> IM_LOG_VFLOWCOM: input: START_10 58633
>
> IM_LOG_VFLOWCOM: input: START_10 58634
>
> IM_LOG_VFLOWCOM: input: START_10 58635
>
> PMD: eth_igb_recv_pkts():
>
> port_id=0 queue_id=0 rx_id=268 staterr=0x3 pkt_len=146
>
>
> PMD: eth_igb_recv_pkts():
>
> port_id=0 queue_id=0 rx_id=269 staterr=0x3 pkt_len=146
>
>
> PMD: eth_igb_recv_pkts():
>
> port_id=0 queue_id=0 rx_id=270 staterr=0x3 pkt_len=146
>
>
> PMD: eth_igb_recv_pkts():
>
> port_id=0 queue_id=0 rx_id=271 staterr=0x3 pkt_len=146
>
>
> PMD: eth_igb_recv_pkts(): port_id=0 queue_id=0 rx_tail=272 nb_hold=4
> nb_rx=4
>
>
> IM_LOG_VFLOWCOM: input: START_10 58636
>
> IM_LOG_VFLOWCOM: input: START_10 58509
>
> IM_LOG_VFLOWCOM: wrong pkt number arrived from burst 4, expected 58637 but
> got 58509
>
> IM_LOG_VFLOWCOM: input: START_10 58638
>
> IM_LOG_VFLOWCOM: input: START_10 58639
>
> PMD: eth_igb_recv_pkts():
>
> port_id=0 queue_id=0 rx_id=272 staterr=0x3 pkt_len=146
>
>
> PMD: eth_igb_recv_pkts():
>
> port_id=0 queue_id=0 rx_id=273 staterr=0x3 pkt_len=146
>
>
> PMD: eth_igb_recv_pkts():
>
> port_id=0 queue_id=0 rx_id=274 staterr=0x3 pkt_len=146
>
>
> PMD: eth_igb_recv_pkts():
>
> port_id=0 queue_id=0 rx_id=275 staterr=0x3 pkt_len=146
>
>
> PMD: eth_igb_recv_pkts(): port_id=0 queue_id=0 rx_tail=276 nb_hold=4
> nb_rx=4
>
>
> IM_LOG_VFLOWCOM: input: START_10 58640
>
> IM_LOG_VFLOWCOM: input: START_10 58641
>
> IM_LOG_VFLOWCOM: input: START_10 58642
>
> IM_LOG_VFLOWCOM: input: START_10 58643
>
>
>
> On Wed, Jul 16, 2014 at 3:36 PM, Helmut Sim <simhelmut@gmail.com> wrote:
>
>> I will try it though I hope the amount of logs won't affect the result.
>> while analyzing the wireshark captures I noted that the packet i supposed
>> to capture arrives in a short time after the one before.
>> for example, here is a time between the consecutive transmitted packets:
>> 0.000050000 PKT 12201
>> 0.000050000 PKT 12202
>> 0.000050000 PKT 12203
>> 0.000050000 PKT 12204
>> 0.000050000 PKT 12205
>> 0.000050000 PKT 12206
>> 0.000020000 PKT 12207 ==> though this one was received at the app as "PKT
>> 12202"
>> 0.000050000 PKT 12208
>>
>> note that the problematic case was transmitted in a very short time after
>> its previous one. this is also the case in other problematic cases.
>>
>> is there any way to configure ethernet IFG (Interf Frame Gap)?
>>
>> Thanks,
>>
>>
>> On Wed, Jul 16, 2014 at 3:18 PM, Olivier MATZ <olivier.matz@6wind.com>
>> wrote:
>>
>>> Hello Helmut,
>>>
>>>
>>> 2014-07-16 13:56, Helmut Sim:
>>>
>>>> then i see that from time to time i get a packet that was already
>>>>> received
>>>>> earlier instead of receiving the expected packet.
>>>>> the output is:
>>>>> PKT 12201
>>>>> PKT 12202
>>>>> PKT 12203
>>>>> PKT 12204
>>>>> PKT 12205
>>>>> PKT 12206
>>>>> PKT 12202
>>>>> PKT 12208
>>>>>
>>>>> total received pkts is identical to the total delivered pkts, but part
>>>>> of
>>>>> the pkts are being received twice...
>>>>>
>>>>
>>> Enabling CONFIG_RTE_LIBRTE_MEMPOOL_DEBUG and
>>> CONFIG_RTE_LIBRTE_MBUF_DEBUG could help you to track
>>> double free or corruptions.
>>>
>>> Regards,
>>> Olivier
>>>
>>>
>>
>