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

Sun Feb 1 21:32:19 PST 2015

Hi Peter

There's a clock skew among three machines.
I picked one of the earliest Interests as a sample:

CONSUMER
1422581537.761808 DEBUG: [Forwarder] onOutgoingInterest face=259
interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/key/5/data/%00%00

HUB
1422581504.112268 DEBUG: [Forwarder] onIncomingInterest face=266
interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/key/5/data/%00%00
1422581504.112966 DEBUG: [Forwarder] onOutgoingInterest face=264
interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/key/5/data/%00%00

PRODUCER
1422581537.499525 DEBUG: [Forwarder] onIncomingInterest face=266
interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/key/5/data/%00%00

Assuming 2ms link delay: clock on HUB is ~33651ms behind of CONSUMER; clock
on PRODUCER is ~266ms behind of CONSUMER.

After compensating for the clock skew, the log snippet below says (in terms
of CONSUMER clock, milliseconds):

CONSUMER
55424 send Interest 1
55718 send Interest 2
55950 receive Data 1
55956 receive Data 2

HUB
55425 receive and send Interest 1
55948 receive and send Data 1
55954 receive Interest 2, send Data 2 from ContentStore

PRODUCER
55522 receive Interest 1
55570 send Data 1

Observations:

   - The link between HUB and PRODUCER is congested.
   Evidence: Interest 1 is received 97ms after it's sent. Data 1 is
   received 378ms after it's sent.
   - Interest 2 from CONSUMER to HUB is delayed.
   - HUB log reveals that face 266 (toward CONSUMER) and face 264 (toward
   PRODUCER) are both UDP and have same local IP address.
   The delay of Interest 2 from CONSUMER to HUB might be caused by the
   congestion between HUB and PRODUCER, because part of CONSUMER-HUB logical
   link shares same IP-layer link.

Yours, Junxiao

On Thu, Jan 29, 2015 at 7:56 PM, Gusev, Peter <peter at remap.ucla.edu> wrote:

>  Hi all,
>
>  I’m doing tests and explorations on the reasons, why does NdnCon
> experience rebufferings (i.e. interruptions in video stream which lead to
> algorithm restart).
> I would appreciate any help/suggestions/advices in debugging/analyzing NFD
> logs and NFD itself.
>
>  More specifically, I’d like to hear your comments on the following case.
> With the same configuration as before ([Consumer] <—> [*NFD1*] <==
> *Ethernet**_link*==> [*NFD2*] <==*Ethernet_link*==> [*NFD3*] <—>
> [Producer]) consumer experienced interruption after getting frame 640. So I
> tracked down frame’s 641 interests and data in NFD logs:
>
>  *NFD1 log: **($ cat consumer/nfd.log | grep "**/641/data/%00%00”)*
>
>  1422581555.423600 DEBUG: [Forwarder] onIncomingInterest face=265
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581555.423943 DEBUG: [Forwarder] onOutgoingInterest face=259
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581555.424205 DEBUG: [BestRouteStrategy2]
> /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=
> *1282205730* from=265 newPitEntry-to=259
> *^ 294ms (retransmission, confirmed by consumer log)*
> 1422581555.718095 DEBUG: [Forwarder] onIncomingInterest face=265
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581555.718589 DEBUG: [Forwarder] onOutgoingInterest face=259
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581555.718929 DEBUG: [BestRouteStrategy2]
> /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=589980969
> from=265 retransmit-retry-to=259
> *^ 232ms*
> 1422581555.950466 DEBUG: [Forwarder] onIncomingData face=259
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0
> 1422581555.950763 DEBUG: [Forwarder] onIncomingData
> matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581555.950998 DEBUG: [Strategy] beforeSatisfyPendingInterest
> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> inFace=259
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0
> 1422581555.951438 DEBUG: [Forwarder] onOutgoingData face=265
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0
> *^ 5ms*
> 1422581555.956230 DEBUG: [Forwarder] *onIncomingData* face=259
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0
> 1422581555.956496 DEBUG: [Forwarder] onIncomingData
> matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581555.956724 DEBUG: [Strategy] beforeSatisfyPendingInterest
> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> inFace=259
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0
>
>  *NFD2 log: **($ cat hub/nfd.log | grep "**/641/data/%00%00”)*
>
>  1422581521.773468 DEBUG: [Forwarder] onIncomingInterest face=266
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581521.773947 DEBUG: [Forwarder] onOutgoingInterest face=264
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581521.774352 DEBUG: [BestRouteStrategy2]
> /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=
> *1282205730* from=266 newPitEntry-to=264
> *^ 522ms (??? where is the retransmission interest?)*
> 1422581522.296967 DEBUG: [Forwarder] onIncomingData face=264
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0
> 1422581522.297347 DEBUG: [Forwarder] onIncomingData
> matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581522.297614 DEBUG: [Strategy] beforeSatisfyPendingInterest
> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> inFace=264
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0
> 1422581522.298123 DEBUG: [Forwarder] onOutgoingData face=266
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0
> *^ 5ms (ah, here it is… how?)*
> 1422581522.303090 DEBUG: [Forwarder] onIncomingInterest face=266
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581522.303430 DEBUG: [Forwarder] onOutgoingData face=266
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0
>
>  *NFD3 log: **($ cat producer/nfd.log | grep "**/641/data/%00%00”)*
>
>  1422581555.255647 DEBUG: [Forwarder] onIncomingInterest face=266
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581555.256007 DEBUG: [Forwarder] onOutgoingInterest face=269
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581555.256334 DEBUG: [BestRouteStrategy2]
> /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=
> *1282205730* from=266 newPitEntry-to=269
> *^ 47ms (!!! interest arrival was not late, data generation was not
> delayed)*
> 1422581555.303275 DEBUG: [Forwarder] onIncomingData face=269
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0
> 1422581555.303640 DEBUG: [Forwarder] onIncomingData
> matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> 1422581555.303928 DEBUG: [Strategy] beforeSatisfyPendingInterest
> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00
> inFace=269
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0
> 1422581555.304458 DEBUG: [Forwarder] onOutgoingData face=266
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0
>
>
>  The questions here are:
> 1. How did the retransmission interest arrived on NFD2 ~220ms later than
> was expected and actually after the first interest was already answered?
> 2. If the data was generated and answered by NFD3 in timely manner, why
> did data arrived on NFD2 after 522ms but not after ~50ms?
>
>  Some peculiar place of NFD2’s log:
>  *$ sed -n 38830,38840p hub/nfd.log *
>
>  1422581521.916149 DEBUG: [Forwarder] onIncomingData face=264
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/638/data/%00%0A/14/661/22/0
> 1422581521.916515 DEBUG: [Forwarder] onIncomingData
> matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/638/data/%00%0A
> 1422581521.916799 DEBUG: [Strategy] beforeSatisfyPendingInterest
> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/638/data/%00%0A
> inFace=264
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/638/data/%00%0A/14/661/22/0
> 1422581521.917301 DEBUG: [Forwarder] onOutgoingData face=266
> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/638/data/%00%0A/14/661/22/0
> ^ 360ms
> 1422581522.277620 DEBUG: [Forwarder] onInterestUnsatisfied
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/499/data/%00%06
> 1422581522.278080 DEBUG: [Strategy] beforeExpirePendingInterest
> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/499/data/%00%06
> 1422581522.278524 DEBUG: [Forwarder] onInterestUnsatisfied
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/500/data/%00%06
> 1422581522.278901 DEBUG: [Strategy] beforeExpirePendingInterest
> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/500/data/%00%06
> 1422581522.279352 DEBUG: [Forwarder] onInterestUnsatisfied
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/501/data/%00%05
> 1422581522.279742 DEBUG: [Strategy] beforeExpirePendingInterest
> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/501/data/%00%05
> 1422581522.280119 DEBUG: [Forwarder] onInterestUnsatisfied
> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/501/data/%00%06
>
>
>  I would appreciate any help.
> Looking forward for the insights of NFD developers,
>
>    Thanks,
>
>  PS. full logs are attached
>
>  --
> 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/20150201/b7707295/attachment.html>