<div dir="ltr"><div>Hi Peter</div><div><br></div><div>There's a clock skew among three machines.</div><div>I picked one of the earliest Interests as a sample:</div><blockquote style="margin:0 0 0 40px;border:none;padding:0px"><div><font face="monospace, monospace">CONSUMER</font></div><div><div><span style="font-family:monospace,monospace">1422581537.761808 DEBUG: [Forwarder] onOutgoingInterest face=259 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/key/5/data/%00%00</span><br></div></div><div><font face="monospace, monospace"><br></font></div><div><font face="monospace, monospace">HUB</font></div><div><div><font face="monospace, monospace">1422581504.112268 DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/key/5/data/%00%00</font></div></div><div><div><font face="monospace, monospace">1422581504.112966 DEBUG: [Forwarder] onOutgoingInterest face=264 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/key/5/data/%00%00</font></div></div><div><font face="monospace, monospace"><br></font></div><div><font face="monospace, monospace">PRODUCER</font></div><div><div><font face="monospace, monospace">1422581537.499525 DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/key/5/data/%00%00</font></div></div></blockquote><div><br></div><div>Assuming 2ms link delay: clock on HUB is ~33651ms behind of CONSUMER; clock on PRODUCER is ~266ms behind of CONSUMER.</div><div><br></div><div><br></div><div>After compensating for the clock skew, the log snippet below says (in terms of CONSUMER clock, milliseconds):</div><blockquote style="margin:0 0 0 40px;border:none;padding:0px"><div>CONSUMER</div><div>55424 send Interest 1</div><div>55718 send Interest 2</div><div>55950 receive Data 1</div><div>55956 receive Data 2</div><div><br></div><div>HUB</div><div>55425 receive and send Interest 1</div><div>55948 receive and send Data 1</div><div>55954 receive Interest 2, send Data 2 from ContentStore</div><div><br></div><div>PRODUCER</div><div>55522 receive Interest 1</div><div>55570 send Data 1</div></blockquote><div><br></div><div>Observations:</div><div><ul><li>The link between HUB and PRODUCER is congested.<br>Evidence: Interest 1 is received 97ms after it's sent. Data 1 is received 378ms after it's sent.</li><li>Interest 2 from CONSUMER to HUB is delayed.</li><li>HUB log reveals that face 266 (toward CONSUMER) and face 264 (toward PRODUCER) are both UDP and have same local IP address.<br>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.</li></ul></div><div><br></div>Yours, Junxiao<br><div class="gmail_extra"><br><div class="gmail_quote">On Thu, Jan 29, 2015 at 7:56 PM, Gusev, Peter <span dir="ltr"><<a href="mailto:peter@remap.ucla.edu" target="_blank">peter@remap.ucla.edu</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">



<div>
<div style="word-wrap:break-word">
<div>Hi all,</div>
<div><br>
</div>
<div>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).</div>
<div>I would appreciate any help/suggestions/advices in debugging/analyzing NFD logs and NFD itself.</div>
<div><br>
</div>
<div>More specifically, I’d like to hear your comments on the following case.</div>
<div>With the same configuration as before ([Consumer] <—> [<b>NFD1</b>] <==<i>Ethernet</i><i>_link</i>==> [<b>NFD2</b>] <==<i>Ethernet_link</i>==> [<b>NFD3</b>] <—> [Producer]) consumer experienced
 interruption after getting frame 640. So I tracked down frame’s 641 interests and data in NFD logs:</div>
<div><br>
</div>
<div><b>NFD1 log: </b><i>($ cat consumer/nfd.log | grep "</i><i>/641/data/%00%00”)</i></div>
<div><br>
</div>
<div>1422581555.423600 DEBUG: [Forwarder] onIncomingInterest face=265 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>1422581555.423943 DEBUG: [Forwarder] onOutgoingInterest face=259 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>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=<b>1282205730</b> from=265 newPitEntry-to=259</div>
<div><b>^ 294ms (retransmission, confirmed by consumer log)</b></div>
<div>1422581555.718095 DEBUG: [Forwarder] onIncomingInterest face=265 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>1422581555.718589 DEBUG: [Forwarder] onOutgoingInterest face=259 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>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</div>
<div><b>^ 232ms</b></div>
<div>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</div>
<div>1422581555.950763 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>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</div>
<div>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</div>
<div><b>^ 5ms</b></div>
<div>1422581555.956230 DEBUG: [Forwarder] <b>onIncomingData</b> face=259 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00/5/664/22/0</div>
<div>1422581555.956496 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>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</div>
<div><br>
</div>
<div><b>NFD2 log: </b><i>($ cat hub/nfd.log | grep "</i><i>/641/data/%00%00”)</i></div>
<div><br>
</div>
<div>1422581521.773468 DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>1422581521.773947 DEBUG: [Forwarder] onOutgoingInterest face=264 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>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=<b>1282205730</b> from=266 newPitEntry-to=264</div>
<div><b>^ 522ms (??? where is the retransmission interest?)</b></div>
<div>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</div>
<div>1422581522.297347 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>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</div>
<div>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</div>
<div><b>^ 5ms (ah, here it is… how?)</b></div>
<div>1422581522.303090 DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>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</div>
<div><br>
</div>
<div><b>NFD3 log: </b><i>($ cat producer/nfd.log | grep "</i><i>/641/data/%00%00”)</i></div>
<div><br>
</div>
<div>1422581555.255647 DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>1422581555.256007 DEBUG: [Forwarder] onOutgoingInterest face=269 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>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=<b>1282205730</b> from=266 newPitEntry-to=269</div>
<div><b>^ 47ms (!!! interest arrival was not late, data generation was not delayed)</b></div>
<div>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</div>
<div>1422581555.303640 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/641/data/%00%00</div>
<div>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</div>
<div>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</div>
<div> </div>
<div><br>
</div>
<div>The questions here are:</div>
<div>1. How did the retransmission interest arrived on NFD2 ~220ms later than was expected and actually after the first interest was already answered?</div>
<div>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?</div>
<div><br>
</div>
<div>Some peculiar place of NFD2’s log:</div>
<div>
<div style="margin:0px;font-size:11px;font-family:Menlo"><b>$ sed -n 38830,38840p hub/nfd.log </b></div>
</div>
<div style="margin:0px;font-size:11px;font-family:Menlo"><b><br>
</b></div>
<div>
<div>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</div>
<div>1422581521.916515 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/638/data/%00%0A</div>
<div>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</div>
<div>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</div>
<div>^ 360ms</div>
<div>1422581522.277620 DEBUG: [Forwarder] onInterestUnsatisfied interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/499/data/%00%06</div>
<div>1422581522.278080 DEBUG: [Strategy] beforeExpirePendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/499/data/%00%06</div>
<div>1422581522.278524 DEBUG: [Forwarder] onInterestUnsatisfied interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/500/data/%00%06</div>
<div>1422581522.278901 DEBUG: [Strategy] beforeExpirePendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/500/data/%00%06</div>
<div>1422581522.279352 DEBUG: [Forwarder] onInterestUnsatisfied interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/501/data/%00%05</div>
<div>1422581522.279742 DEBUG: [Strategy] beforeExpirePendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/501/data/%00%05</div>
<div>1422581522.280119 DEBUG: [Forwarder] onInterestUnsatisfied interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/501/data/%00%06</div>
</div>
<div><br>
</div>
<div><br>
</div>
<div>I would appreciate any help.</div>
<div>Looking forward for the insights of NFD developers,</div>
<br>
<div>
<div style="color:rgb(0,0,0);letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
<div style="color:rgb(0,0,0);letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
<div style="color:rgb(0,0,0);letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
<div style="color:rgb(0,0,0);font-family:Helvetica;font-style:normal;font-variant:normal;font-weight:normal;letter-spacing:normal;line-height:normal;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
Thanks, </div>
<div style="color:rgb(0,0,0);font-family:Helvetica;font-style:normal;font-variant:normal;font-weight:normal;letter-spacing:normal;line-height:normal;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
<br>
</div>
<div style="color:rgb(0,0,0);font-family:Helvetica;font-style:normal;font-variant:normal;font-weight:normal;letter-spacing:normal;line-height:normal;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
PS. full logs are attached</div>
<div style="color:rgb(0,0,0);font-family:Helvetica;font-style:normal;font-variant:normal;font-weight:normal;letter-spacing:normal;line-height:normal;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
</div>
</div>
</div>
</div>
</div>
</div>
<div style="word-wrap:break-word">
<div>
<div style="color:rgb(0,0,0);letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
<div style="color:rgb(0,0,0);letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
<div style="color:rgb(0,0,0);letter-spacing:normal;text-align:start;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
<div style="color:rgb(0,0,0);font-family:Helvetica;font-style:normal;font-variant:normal;font-weight:normal;letter-spacing:normal;line-height:normal;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
</div>
<div style="color:rgb(0,0,0);font-family:Helvetica;font-style:normal;font-variant:normal;font-weight:normal;letter-spacing:normal;line-height:normal;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
<br>
</div>
<div style="color:rgb(0,0,0);font-family:Helvetica;font-style:normal;font-variant:normal;font-weight:normal;letter-spacing:normal;line-height:normal;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
-- <br>
Peter Gusev</div>
<div style="color:rgb(0,0,0);font-family:Helvetica;font-style:normal;font-variant:normal;font-weight:normal;letter-spacing:normal;line-height:normal;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
Programmer/Analyst @ REMAP, UCLA</div>
<div style="color:rgb(0,0,0);font-family:Helvetica;font-style:normal;font-variant:normal;font-weight:normal;letter-spacing:normal;line-height:normal;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px;word-wrap:break-word">
<br>
<a href="mailto:peter@remap.ucla.edu" target="_blank">peter@remap.ucla.edu</a><br>
<a href="tel:%2B1%20213%205872748" value="+12135872748" target="_blank">+1 213 5872748</a><br>
peetonn_ (skype)</div>
</div>
</div>
</div>
</div>
</div></div></blockquote></div><br></div></div>