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

[Gusev, Peter]

Hi all,

I’ve been testing <https://github.com/remap/ndnrtc/tree/issues/2283-retransmissions> N<https://github.com/remap/ndnrtc/tree/issues/2283-retransmissions>DN-RTC with new consumer algorithm and exploring the problem of rebufferings on consumer side (a state, when consumer is not getting data for some amount of time, flushes everything and starts over again). Consumer rebufferings are perceived as audio/video interruptions for 1-1.5sec by the user and decrease overall user experience.

I'll appreciate your insights on the analysis of the logs I retrieved from NFD.

Setup:

[Consumer] <—> [NFD1] <==WiFi_link==> [NFD2] <==Ethernet_link==> [NFD3] <—> [Producer]

Case:
According to my logs, consumer starved for data after 2656 segment has arrived, so I tracked interests and data for 2657 segment. According to my logs, consumer eventually received this data but too late and rebuffering was already inevitable.

NFD1 log:
initial interest: 1421288806.271931 DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.272215 DEBUG: [Forwarder] onOutgoingInterest face=262 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.272469 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=108889115 from=266 newPitEntry-to=262
^ 270ms
retransmission: 1421288806.542289 DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.542697 DEBUG: [Forwarder] onOutgoingInterest face=262 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.543032 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=562292066 from=266 retransmit-retry-to=262
^ 286ms
data arrives: 1421288806.829462 DEBUG: [Forwarder] onIncomingData face=262 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00/1/2749/91/0
1421288806.829818 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.830042 DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00 inFace=262 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00/1/2749/91/0
1421288806.830449 DEBUG: [Forwarder] onOutgoingData face=266 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00/1/2749/91/0

NFD2 log:
initial interest: 1421288806.015075 DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.015845 DEBUG: [Forwarder] onOutgoingInterest face=264 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.016255 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=108889115 from=266 newPitEntry-to=264
^ 545ms
retransmission: 1421288806.561516 DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.562233 DEBUG: [Forwarder] onOutgoingInterest face=264 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.562626 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=562292066 from=266 retransmit-retry-to=264
^ 2ms
data arrives: 1421288806.564828 DEBUG: [Forwarder] onIncomingData face=264 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00/1/2749/91/0
1421288806.565282 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.565594 DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00 inFace=264 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00/1/2749/91/0
1421288806.566213 DEBUG: [Forwarder] onOutgoingData face=266 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00/1/2749/91/0
^ 13ms
data arrives 2:* 1421288806.579547 DEBUG: [Forwarder] onIncomingData face=264 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00/1/2749/91/0
1421288806.579915 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.580162 DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00 inFace=264 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00/1/2749/91/0

*NOTE: no data was forwarded


NFD3 log:
initial interest: 1421288806.249712 DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.250177 DEBUG: [Forwarder] onOutgoingInterest face=269 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.250573 DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=108889115 from=266 newPitEntry-to=269
^271ms
data generated: 1421288806.521982 DEBUG: [Forwarder] onIncomingData face=269 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00/1/2749/91/0
1421288806.522531 DEBUG: [Forwarder] onIncomingData matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.522844 DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00 inFace=269 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00/1/2749/91/0
1421288806.523363 DEBUG: [Forwarder] onOutgoingData face=266 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00/1/2749/91/0
^273ms
retransmission: 1421288806.796022 DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00
1421288806.796418 DEBUG: [Forwarder] onOutgoingData face=266 data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/camera/low/delta/2657/data/%00%00/1/2749/91/0



There are several questions arise:
1. Why do you think the delay b/w initial interest and retransmission for the NFD2 became 545ms (compared to 270ms with NFD1)? Could it be WiFi fault?
2. How come the delay b/w initial interest and data in NFD3 is 271ms and NFD3 forwards this data to NFD2, but NFD2 didn’t get this data and instead got retransmission interest after another 545-271=274ms and later got the same data with 13ms difference? Could it be unreliable logging in NFD?

I attached full NFD logs to this message.

Thank you in advance.
All ideas and thoughts are welcome.

Thanks,

PS. Basically, such things block deployment of NDN-RTC (NdnCon) for the community as it delivers low-quality user experience (i.e. videoconference with interruptions =( ), so I really hope for the help and feedback.


--
Peter Gusev
peter at remap.ucla.edu<mailto:peter at remap.ucla.edu>
+1 213 5872748 (USA)
+7 916 4434826 (Russia)
+37 259 226448 (in case any other number is unavailable)
peetonn_ (skype)

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.lists.cs.ucla.edu/pipermail/nfd-dev/attachments/20150121/c82865b5/attachment.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Archive.zip
Type: application/zip
Size: 1621024 bytes
Desc: Archive.zip
URL: <http://www.lists.cs.ucla.edu/pipermail/nfd-dev/attachments/20150121/c82865b5/attachment.zip>