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

Burke, Jeff jburke at remap.UCLA.EDU
Mon Feb 2 19:04:25 PST 2015


Junxiao,
Thanks for considering this.
These are gigabit nics doing nothing else of significance, with ndnrtc traffic in the hundreds of kilobits/sec. I don't see how local congestion in the hundreds of ms (of all packets) would result?
Jeff

-----Original Message-----
From: Junxiao Shi [shijunxiao at email.arizona.edu]
Received: Monday, 02 Feb 2015, 11:33AM
To: Gusev, Peter [peter at remap.ucla.edu]
CC: {nfd-dev at lists.cs.ucla.edu} [nfd-dev at lists.cs.ucla.edu]
Subject: Re: [Nfd-dev] NDN-RTC: NFD processing logs

Hi Peter

This statement means:
Both CONSUMER-HUB and HUB-PRODUCER links are using the same physical NIC of HUB router.
Thus, a congestion on HUB-PRODUCER can cause an underlying congestion on this physical NIC, and therefore cause a delay on CONSUMER-HUB link.

To eliminate this factor, use two physical NICs on the HUB, so that CONSUMER-HUB and HUB-PRODUCER links won't affect each other.

Yours, Junxiao

On Mon, Feb 2, 2015 at 12:24 PM, Gusev, Peter <peter at remap.ucla.edu<mailto:peter at remap.ucla.edu>> wrote:
Hi Junxiao,

Thanks for your  analysis!
You’re right, there’s a clock skew (even though all three machines are NTP-synchronized to the time1.ucla.edu<http://time1.ucla.edu>).


  *   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.

I didn’t quite get this statement - do you mean that consumer and producer run on the same machine? In the scenario I run, there were three machines (consumer 128.97.152.44, hub 131.179.141.51 and producer 131.179.141.33) connected using 1Gbit switches (LAN). Do you think this could be a congestion problem still?
I’ll run new tests now eliminating one network segment by connecting consumer to the 131.179.141.xx subnet.

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)

On Feb 1, 2015, at 9:32 PM, Junxiao Shi <shijunxiao at email.arizona.edu<mailto:shijunxiao at email.arizona.edu>> wrote:

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<mailto: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<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/20150203/19bbb979/attachment.html>


More information about the Nfd-dev mailing list