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

Tue Feb 3 11:56:29 PST 2015

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 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 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 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<mailto:peter at remap.ucla.edu>
+1 213 5872748
peetonn_ (skype)

On Feb 2, 2015, at 7:04 PM, Burke, Jeff <jburke at remap.ucla.edu<mailto:jburke at remap.ucla.edu>> wrote:

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<mailto:shijunxiao at email.arizona.edu>]
Received: Monday, 02 Feb 2015, 11:33AM
To: Gusev, Peter [peter at remap.ucla.edu<mailto:peter at remap.ucla.edu>]
CC: {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

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/0e162428/attachment.html>