[Nfd-dev] Extremely high RTT on raspberry pi with the clean version

Tue Jan 2 10:22:21 PST 2018

Hello all,

I am working with NFD on the raspberry pi 3 model B system. Lately,
however, I have had a very strange issue. While using ndnping over 1 hop in
an adhoc environment over ethernet multicast faces, the round trip time can
be upwards of 10 minutes. I was working with a modified version when I
encountered this issue, however, after reinstalling the clean version from
github, the problem persisted. So, I used the trace level logging to see
what could be going on, but I am unable to find the issue. Does anyone have
an idea what could be causing this issue?

Below is the trace from each side, organized into the order that I believe
the events took place, however, I am unsure if this is actually the case,
as there is a chance that the producer responded to the interest after the
timeout took place on the consumer.

Thanks for your time,
Anthony Dowling

// first ping sent by consumer
1511037635.119663 DEBUG: [Forwarder] onIncomingInterest face=260
interest=/ping/ping/10324781016848213197
1511037635.119735 TRACE: [NameTree] lookup /ping/ping/10324781016848213197
1511037635.119793 TRACE: [NameTreeHashtable] found / hash=0 bucket=0
1511037635.119836 TRACE: [NameTreeHashtable] found /ping hash=3225558032
bucket=16
1511037635.119891 TRACE: [NameTreeHashtable] insert /ping/ping hash=0
bucket=0
1511037635.119943 TRACE: [NameTreeHashtable] insert
/ping/ping/10324781016848213197 hash=97694297 bucket=601
1511037635.120008 DEBUG: [ContentStore] find
/ping/ping/10324781016848213197 L
1511037635.120137 DEBUG: [ContentStore]   no-match
1511037635.120174 DEBUG: [Forwarder] onContentStoreMiss
interest=/ping/ping/10324781016848213197
1511037635.120251 TRACE: [Strategy] lookupFib noForwardingHint found=/ping
1511037635.120415 DEBUG: [Forwarder] onOutgoingInterest face=257
interest=/ping/ping/10324781016848213197
1511037635.120474 TRACE: [LinkService]
[id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] sendInterest
1511037635.120562 TRACE: [EthernetTransport]
[id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] doSend
1511037635.120759 TRACE: [EthernetTransport]
[id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] Successfully
sent: 52 bytes
1511037635.120828 DEBUG: [BestRouteStrategy2]
/ping/ping/10324781016848213197?ndn.MustBeFresh=1&ndn.InterestLifetime=10000&ndn.Nonce=1869174386
from=260 newPitEntry-to=257

// producer responding to data
1511037711.976099 TRACE: [EthernetTransport]
[id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] Received: 52
bytes from b8:27:eb:03:30:1a
1511037711.976325 TRACE: [LinkService]
[id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]]
receiveInterest
1511037711.976387 DEBUG: [Forwarder] onIncomingInterest face=257
interest=/ping/ping/10324781016848213197
1511037711.976470 TRACE: [NameTree] lookup /ping/ping/10324781016848213197
1511037711.976532 TRACE: [NameTreeHashtable] found / hash=0 bucket=0
1511037711.976578 TRACE: [NameTreeHashtable] found /ping hash=3225558032
bucket=16
1511037711.976626 TRACE: [NameTreeHashtable] found /ping/ping hash=0
bucket=0
1511037711.976682 TRACE: [NameTreeHashtable] insert
/ping/ping/10324781016848213197 hash=97694297 bucket=601
1511037711.976757 DEBUG: [ContentStore] find
/ping/ping/10324781016848213197 L
1511037711.976896 DEBUG: [ContentStore]   no-match
1511037711.976934 DEBUG: [Forwarder] onContentStoreMiss
interest=/ping/ping/10324781016848213197
1511037711.977005 TRACE: [Strategy] lookupFib noForwardingHint
found=/ping/ping
1511037711.977164 DEBUG: [Forwarder] onOutgoingInterest face=261
interest=/ping/ping/10324781016848213197
1511037711.977221 TRACE: [LinkService]
[id=261,local=unix:///run/nfd.sock,remote=fd://30] sendInterest
1511037711.977303 TRACE: [UnixStreamTransport]
[id=261,local=unix:///run/nfd.sock,remote=fd://30] doSend
1511037711.977448 DEBUG: [BestRouteStrategy2]
/ping/ping/10324781016848213197?ndn.MustBeFresh=1&ndn.InterestLifetime=10000&ndn.Nonce=1869174386
from=257 newPitEntry-to=261
1511037711.977635 TRACE: [UnixStreamTransport]
[id=261,local=unix:///run/nfd.sock,remote=fd://30] Successfully sent: 52
bytes
1511037711.978420 TRACE: [UnixStreamTransport]
[id=261,local=unix:///run/nfd.sock,remote=fd://30] Received: 85 bytes
1511037711.978583 TRACE: [LinkService]
[id=261,local=unix:///run/nfd.sock,remote=fd://30] receiveData
1511037711.978640 DEBUG: [Forwarder] onIncomingData face=261
data=/ping/ping/10324781016848213197
1511037711.978713 TRACE: [NameTreeHashtable] found
/ping/ping/10324781016848213197 hash=97694297 bucket=601
1511037711.978783 TRACE: [NameTreeIterator] initialized
entry=/ping/ping/10324781016848213197 ref=/ping/ping/10324781016848213197
state=0
1511037711.978865 TRACE: [NameTreeIterator] advanced end
1511037711.978912 DEBUG: [ContentStore] insert
/ping/ping/10324781016848213197
1511037711.979000 DEBUG: [Forwarder] onIncomingData
matching=/ping/ping/10324781016848213197
1511037711.979084 DEBUG: [Strategy] beforeSatisfyInterest
pitEntry=/ping/ping/10324781016848213197 inFace=261
data=/ping/ping/10324781016848213197
1511037711.979193 DEBUG: [Forwarder] onOutgoingData face=257
data=/ping/ping/10324781016848213197
1511037711.979248 TRACE: [LinkService]
[id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] sendData
1511037711.979334 TRACE: [EthernetTransport]
[id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] doSend
1511037711.979523 TRACE: [EthernetTransport]
[id=257,local=dev://wlan0,remote=ether://[01:00:5e:00:17:aa]] Successfully
sent: 85 bytes
1511037712.079333 DEBUG: [Forwarder] onInterestFinalize
interest=/ping/ping/10324781016848213197 satisfied
1511037712.079457 TRACE: [NameTreeHashtable] erase
/ping/ping/10324781016848213197 hash=97694297 bucket=601
1511037712.314525 TRACE: [DeadNonceList] mark nMarks=48

// timeout event on consumer
1511037645.123436 DEBUG: [Forwarder] onInterestUnsatisfied
interest=/ping/ping/10324781016848213197
1511037645.123563 DEBUG: [Strategy] beforeExpirePendingInterest
pitEntry=/ping/ping/10324781016848213197
1511037645.123683 DEBUG: [Forwarder] onInterestFinalize
interest=/ping/ping/10324781016848213197 unsatisfied
1511037645.123821 TRACE: [NameTreeHashtable] erase
/ping/ping/10324781016848213197 hash=97694297 bucket=601

// data for interest after it wasn't recieved on consumer
1511037720.599789 DEBUG: [Forwarder] onIncomingData face=257
data=/ping/ping/10324781016848213197
1511037720.599938 TRACE: [NameTreeHashtable] not-found
/ping/ping/10324781016848213197 hash=97694297 bucket=601
1511037720.600082 TRACE: [NameTreeHashtable] found /ping/ping hash=0
bucket=0
1511037720.600205 TRACE: [NameTreeHashtable] found /ping hash=3225558032
bucket=16
1511037720.600326 TRACE: [NameTreeHashtable] found / hash=0 bucket=0
1511037720.600476 TRACE: [NameTreeIterator] initialized end
1511037720.600588 DEBUG: [Forwarder] onDataUnsolicited face=257
data=/ping/ping/10324781016848213197 decision=drop
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.lists.cs.ucla.edu/pipermail/nfd-dev/attachments/20180102/f4c8ea49/attachment.html>