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

Tue Feb 3 21:50:35 PST 2015

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> 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.410412 DEBUG: [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
> <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.169018 DEBUG: [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
> <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
> <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.433502 DEBUG: [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 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.178188 DEBUG: [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.865989 DEBUG: [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 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
> +1 213 5872748
> peetonn_ (skype)
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.lists.cs.ucla.edu/pipermail/nfd-dev/attachments/20150203/e6b11aa4/attachment.html>