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

[Junxiao Shi]

Hi Peter

It appears that NFD2 node is overloaded.
There is a big delay between NFD3 returns first Data and NFD2 receives that
Data.
There is a big delay between NFD1 forwards second Interests and NFD
receives that Interest.

To determine whether a node is overloaded, look at its CPU utilization. If
CPU utilization of any core is over 50%, reduce traffic rate.


It's expected for NFD2 not to return the second Data, because PIT entry has
been satisfied by the first Data.
When the second Data arrives, PIT entry contains no downstream record, and
therefore Data will not be returned to NFD1.


This experiment appears to be using an outdated NFD version (older than Sep
08, 2014).
For future reports, please use git-HEAD.

Yours, Junxiao

On Wed, Jan 21, 2015 at 1:32 PM, Gusev, Peter <peter at remap.ucla.edu> wrote:

>  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
> +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/1c50b222/attachment.html>