[Nfd-dev] NDN-RTC: NFD processing logs

Tue Feb 3 22:01:46 PST 2015

Junxiao,

The application is intended to work over the current internet with low risk of IP fragmentation, so we are designing the packet sizes for MTUs of 1500 octets.

Peter, can you run NTP in a peer-to-peer configuration to lower the clock offset between the vious machines and make it easier to troubleshoot just based on the logging?  I can give you a configuration tomorrow.

Junxiao, in addition to tcpdump, is there anything that logs at a lower layer in NFD which we could use to see when interest/data bits first come in over the wire?

We will bring the whole setup to the ndn retreat...

Jeff

From: Junxiao Shi <shijunxiao at email.arizona.edu<mailto:shijunxiao at email.arizona.edu>>
Date: Tue, 3 Feb 2015 22:50:35 -0700
To: "Gusev, Peter" <peter at remap.ucla.edu<mailto:peter at remap.ucla.edu>>
Cc: Jeff Burke <jburke at remap.ucla.edu<mailto:jburke at remap.ucla.edu>>, "nfd-dev at lists.cs.ucla.edu<mailto:nfd-dev at lists.cs.ucla.edu>" <nfd-dev at lists.cs.ucla.edu<mailto:nfd-dev at lists.cs.ucla.edu>>
Subject: Re: [Nfd-dev] NDN-RTC: NFD processing logs

Hi Peter

I forgot to ask earlier: what's the MTU of the NICs?
Make sure the MTU is 9000 octets or higher, otherwise IP fragmentation will severely affect performance.

Congestion is unlikely to happen with 200Kbps traffic on 1000Mbps link.
CPU is also unlikely to be a bottleneck for 60 Interests/s.

Use `tcpdump` to see exactly when the packet is transmitted onto the network, in order to determine whether the delay is happening on sender host or receiver host.
Running `tcpdump` on the host itself will affect its performance. If an impact is evident, you could setup port mirroring on the switch, and run `tcpdump` on another machine that is connected to the mirrored port.

Yours, Junxiao

On Tue, Feb 3, 2015 at 12:56 PM, Gusev, Peter <peter at remap.ucla.edu<mailto:peter at remap.ucla.edu>> wrote:
Hi Junxiao,

I run tests with all three (consumer, producer and hub) connected to the same 1Gbit switch. For the app configuration I tested - bitrate is ~150-200kbit/s, interest rate is about 50-60.

And discovered these cases:

Case #1

NFD1 (consumer):
1422920300.410412DEBUG: [Forwarder] onIncomingInterest face=261 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920300.410804 DEBUG: [Forwarder] onOutgoingInterest face=259 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920300.411138 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=2128078661<tel:2128078661> from=261 newPitEntry-to=259
^ 0 sec, 440 msec // retransmission
1422920300.851526 DEBUG: [Forwarder] onIncomingInterest face=261 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920300.851843 DEBUG: [Forwarder] onOutgoingInterest face=259 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920300.852127 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=2749769734 from=261 retransmit-retry-to=259
^ 0 sec, 302 msec // data
1422920301.155108 DEBUG: [Forwarder] onIncomingData face=259 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
1422920301.155452 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920301.155680 DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00 inFace=259 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
1422920301.156152 DEBUG: [Forwarder] onOutgoingData face=261 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0

NFD2 (hub):
1422920250.169018DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920250.169560 DEBUG: [Forwarder] onOutgoingInterest face=264 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920250.169959 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=2128078661<tel:2128078661> from=266 newPitEntry-to=264
^ 0 sec, 736.911 msec // retransmission
1422920250.906870 DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920250.907384 DEBUG: [Forwarder] onOutgoingInterest face=264 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920250.907801 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=2749769734 from=266 retransmit-retry-to=264
^ 0 sec, 2.541 msec // data
1422920250.910342 DEBUG: [Forwarder] onIncomingData face=264 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
1422920250.910812 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920250.911125 DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00 inFace=264 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
1422920250.911706 DEBUG: [Forwarder] onOutgoingData face=266 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
1422920250.922749 DEBUG: [Forwarder] onIncomingData face=264 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
1422920250.923068 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920250.923315 DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00 inFace=264 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0

NFD3 (producer):
1422920296.818710 DEBUG: [Forwarder] onIncomingInterest face=268 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920296.819102 DEBUG: [Forwarder] onOutgoingInterest face=265 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920296.819408 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=2128078661<tel:2128078661> from=268 newPitEntry-to=265
^ 0 sec, 551.408 msec // data
1422920297.370816 DEBUG: [Forwarder] onIncomingData face=265 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
1422920297.371248 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920297.371547 DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00 inFace=265 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
1422920297.372106 DEBUG: [Forwarder] onOutgoingData face=268 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
^ 0 sec, 184.298 msec// retransmission
1422920297.556404 DEBUG: [Forwarder] onIncomingInterest face=268 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
1422920297.557030 DEBUG: [Forwarder] onOutgoingData face=268 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0

Case #2

NFD1 (consumer):
1422919936.433502DEBUG: [Forwarder] onIncomingInterest face=261 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00
1422919936.434221 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=3853552983<tel:3853552983> from=261 newPitEntry-to=259
^ 0 sec, 402.119 msec
1422919936.836340 DEBUG: [Forwarder] onIncomingData face=259 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00/1/4253/150/0
1422919936.836649 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00
1422919936.836871 DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00 inFace=259 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00/1/4253/150/0
1422919936.837279 DEBUG: [Forwarder] onOutgoingData face=261 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00/1/4253/150/0

NFD2 (hub):
1422919886.178188DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00
1422919886.179368 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=3791853569 from=266 newPitEntry-to=264
^ 0 sec, 89.772 msec
1422919886.269140 DEBUG: [Forwarder] onIncomingData face=264 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00/1/4252/150/0
1422919886.269671 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00
1422919886.270079 DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00 inFace=264 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00/1/4252/150/0
1422919886.270718 DEBUG: [Forwarder] onOutgoingData face=266 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00/1/4252/150/0

NFD3 (producer):
1422919932.865989DEBUG: [Forwarder] onIncomingInterest face=268 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00
1422919932.866855 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=3853552983<tel:3853552983> from=268 newPitEntry-to=265
^ 0 sec, 90.492 msec
1422919932.957347 DEBUG: [Forwarder] onIncomingData face=265 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00/1/4253/150/0
1422919932.958010 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00
1422919932.958342 DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00 inFace=265 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00/1/4253/150/0
1422919932.958955 DEBUG: [Forwarder] onOutgoingData face=268 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00/1/4253/150/0

Can these be cases of congestions on such wideband setup?

Thanks,

--
Peter Gusev
Programmer/Analyst @ REMAP, UCLA

peter at remap.ucla.edu<mailto:peter at remap.ucla.edu>
+1 213 5872748<tel:%2B1%20213%205872748>
peetonn_ (skype)

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.lists.cs.ucla.edu/pipermail/nfd-dev/attachments/20150204/bc68f2d2/attachment.html>