[Nfd-dev] NDN-RTC: NFD processing logs
Junxiao Shi
shijunxiao at email.arizona.edu
Mon Feb 2 11:32:15 PST 2015
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> 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).
>
>
> - 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
> +1 213 5872748
> peetonn_ (skype)
>
> On Feb 1, 2015, at 9:32 PM, Junxiao Shi <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>
> 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/20150202/0e4272bd/attachment.html>
More information about the Nfd-dev
mailing list