[Nfd-dev] ndnping RTT investigation

Mon Mar 9 08:54:26 PDT 2015

Junxiao: Do you have some idea of what's causing the long delay in the find…R lookup?
-------

John: I'm just wondering, if the CS being full is related to the long search delay of find…R lookup, then wouldn't this happen all the time after the CS is full rather than periodically like what you observed?

Lan

On Mar 6, 2015, at 2:46 PM, "Dehart, John" <jdd at wustl.edu> wrote:

> 
> All:
> 
> We have been noticing odd spikes in ndnping RTTs and have been trying to track down the root cause of it.
> 
> I believe I have narrowed it down to an interaction between the ndnping Interests and the Interests we send out to collect data
> from nfd for the ndnmap.arl.wustl.edu bandwidth display.
> 
> I have some very specific data now on something strange that is happening with nfd.
> 
> I include a portion of the combined log files from nfd and an ndndump I was running on the WU Testbed node
> at the time of such a spike. The ndnping in question has a reference number of: 1744606568
> I have modified the log messages to insert “nfd” and “ndndump” to help keep straight which messages
> are from which log. Please note that this is all from the WU Testbed node so the times should be 
> directly comparable.
> 
> At time 1425669071.230902 , nfd performs a " [ContentStore] find /localhost/nfd/faces/list R”
> but it doesn’t register  " [ContentStore]   no-match” until 1425669071.253650, which is 
> 22.748 ms later. There were NO nfd log messages in between.
> During that time, ndndump registers the arrival of 7 new Interests.
> 
> From this it would appear that the search of the CS took over 22.748 ms.
> At this point, the CS is full.  I am analyzing a fuller log of the ContentStore messages
> and what I am finding is that the “find … R” lookups that come back no-match are 
> taking longer as the CS fills up. 
> The “find … L” lookups also are increasing in time but they seem to max out at around 2 or 3 ms.
> 
> What is going on with the “find … R” lookups?
> 
> John
> 
> 
> 1425669071.226706 ndndump From: 128.252.153.28, To: 128.252.153.194, Tunnel Type: UDP, INTEREST: /ndn/edu/wustl/ndnmap/stats/128.196.203.36/72.36.112.82/141.225.11.173/193.147.51.186?ndn.MustBeFresh=1&ndn.InterestLifetime=700&ndn.Nonce=3582782466
> 1425669071.226759 nfd DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/wustl/ndnmap/stats/128.196.203.36/72.36.112.82/141.225.11.173/193.147.51.186
> 1425669071.227090 nfd DEBUG: [ContentStore] find /ndn/edu/wustl/ndnmap/stats/128.196.203.36/72.36.112.82/141.225.11.173/193.147.51.186 L
> 1425669071.229658 nfd DEBUG: [ContentStore]   no-match
> 1425669071.229736 nfd DEBUG: [AccessStrategy] /ndn/edu/wustl/ndnmap/stats/128.196.203.36/72.36.112.82/141.225.11.173/193.147.51.186?ndn.MustBeFresh=1&ndn.InterestLifetime=700&ndn.Nonce=3582782466 interestFrom 266 new-interest mi=/ndn/edu/wustl/ndnmap/stats/128.196.203.36/72.36.112.82/141.225.11.173
> 1425669071.230136 nfd DEBUG: [AccessStrategy] /ndn/edu/wustl/ndnmap/stats/128.196.203.36/72.36.112.82/141.225.11.173/193.147.51.186?ndn.MustBeFresh=1&ndn.InterestLifetime=700&ndn.Nonce=3582782466 interestTo 269 last-nexthop rto=111227
> 1425669071.230395 nfd DEBUG: [Forwarder] onOutgoingInterest face=269 interest=/ndn/edu/wustl/ndnmap/stats/128.196.203.36/72.36.112.82/141.225.11.173/193.147.51.186
> 1425669071.230794 nfd DEBUG: [Forwarder] onIncomingInterest face=269 interest=/localhost/nfd/faces/list
> 1425669071.230902 nfd DEBUG: [ContentStore] find /localhost/nfd/faces/list R
> 1425669071.231738 ndndump From: 128.252.153.28, To: 128.252.153.194, Tunnel Type: UDP, INTEREST: /ndn/edu/ucla/ndnmap/stats/192.172.226.248/128.97.98.7/129.82.138.48/162.105.146.26/128.195.4.36?ndn.MustBeFresh=1&ndn.InterestLifetime=700&ndn.Nonce=2821820197
> 1425669071.236867 ndndump From: 128.252.153.28, To: 128.252.153.194, Tunnel Type: UDP, INTEREST: /ndn/edu/arizona/ndnmap/stats/192.172.226.248/129.82.138.48/141.225.11.173/133.9.73.66/128.187.81.12?ndn.MustBeFresh=1&ndn.InterestLifetime=700&ndn.Nonce=2335882350
> 1425669071.241170 ndndump From: 172.16.21.176, To: 128.252.153.194, Tunnel Type: UDP, INTEREST: /ndn/edu/wustl/ping/1744606568?ndn.MustBeFresh=1&ndn.Nonce=1744606568
> 1425669071.241297 ndndump From: 128.252.153.28, To: 128.252.153.194, Tunnel Type: UDP, INTEREST: /ndn/org/caida/ndnmap/stats/128.195.4.36/202.120.188.176?ndn.MustBeFresh=1&ndn.InterestLifetime=700&ndn.Nonce=2532105913
> 1425669071.244815 ndndump From: 128.252.153.28, To: 128.252.153.194, Tunnel Type: UDP, INTEREST: /ndn/ch/unibas/ndnmap/stats/193.147.51.186/162.105.146.26/137.194.54.81?ndn.MustBeFresh=1&ndn.InterestLifetime=700&ndn.Nonce=3200941563
> 1425669071.249054 ndndump From: 128.252.153.28, To: 128.252.153.194, Tunnel Type: UDP, INTEREST: /ndn/cn/edu/pku/ndnmap/stats/202.120.188.176/114.247.165.44?ndn.MustBeFresh=1&ndn.InterestLifetime=700&ndn.Nonce=338471191
> 1425669071.253186 ndndump From: 128.252.153.28, To: 128.252.153.194, Tunnel Type: UDP, INTEREST: /ndn/edu/neu/ndnmap/stats/162.105.146.26?ndn.MustBeFresh=1&ndn.InterestLifetime=700&ndn.Nonce=763898399
> 1425669071.253650 nfd DEBUG: [ContentStore]   no-match
> 1425669071.253702 nfd DEBUG: [Forwarder] onOutgoingInterest face=1 interest=/localhost/nfd/faces/list
> 1425669071.253788 nfd DEBUG: [BestRouteStrategy2] /localhost/nfd/faces/list?ndn.ChildSelector=1&ndn.MustBeFresh=1&ndn.Nonce=2666790337 from=269 newPitEntry-to=1
> 1425669071.253909 nfd DEBUG: [InternalFace] received Interest: /localhost/nfd/faces/list
> 1425669071.253986 nfd DEBUG: [InternalFace] found Interest filter for /localhost/nfd/faces (previous match)
> 1425669071.254052 nfd DEBUG: [FaceManager] command result: processing verb: list
> 1425669071.257714 nfd DEBUG: [Forwarder] onIncomingData face=1 data=/localhost/nfd/faces/list/%FD%00%00%01K%F0%7F%A1%96/%00%00
> 1425669071.257882 nfd DEBUG: [ContentStore] insert /localhost/nfd/faces/list/%FD%00%00%01K%F0%7F%A1%96/%00%00
> 1425669071.258040 ndndump From: 128.252.153.28, To: 128.252.153.194, Tunnel Type: UDP, INTEREST: /ndn/it/unipd/ndnmap/stats/72.36.112.82/192.43.193.111/193.147.51.186/161.105.195.18?ndn.MustBeFresh=1&ndn.InterestLifetime=700&ndn.Nonce=738760142
> 1425669071.258043 nfd DEBUG: [Forwarder] onIncomingData matching=/localhost/nfd/faces/list
> 1425669071.258123 nfd DEBUG: [Strategy] beforeSatisfyInterest pitEntry=/localhost/nfd/faces/list inFace=1 data=/localhost/nfd/faces/list/%FD%00%00%01K%F0%7F%A1%96/%00%00
> 1425669071.258333 nfd DEBUG: [Forwarder] onOutgoingData face=269 data=/localhost/nfd/faces/list/%FD%00%00%01K%F0%7F%A1%96/%00%00
> 1425669071.258514 nfd DEBUG: [Forwarder] onIncomingInterest face=266 interest=/ndn/edu/ucla/ndnmap/stats/192.172.226.248/128.97.98.7/129.82.138.48/162.105.146.26/128.195.4.36
> 1425669071.258815 nfd DEBUG: [ContentStore] find /ndn/edu/ucla/ndnmap/stats/192.172.226.248/128.97.98.7/129.82.138.48/162.105.146.26/128.195.4.36 L
> 1425669071.261579 nfd DEBUG: [ContentStore]   no-match
> 1425669071.261652 nfd DEBUG: [Forwarder] onOutgoingInterest face=260 interest=/ndn/edu/ucla/ndnmap/stats/192.172.226.248/128.97.98.7/129.82.138.48/162.105.146.26/128.195.4.36
> 1425669071.261920 ndndump From: 128.252.153.194, To: 72.36.112.82, Tunnel Type: UDP, INTEREST: /ndn/edu/ucla/ndnmap/stats/192.172.226.248/128.97.98.7/129.82.138.48/162.105.146.26/128.195.4.36?ndn.MustBeFresh=1&ndn.InterestLifetime=700&ndn.Nonce=2821820197
> 1425669071.261945 nfd DEBUG: [BestRouteStrategy2] /ndn/edu/ucla/ndnmap/stats/192.172.226.248/128.97.98.7/129.82.138.48/162.105.146.26/128.195.4.36?ndn.MustBeFresh=1&ndn.InterestLifetime=700&ndn.Nonce=2821820197 from=266 newPitEntry-to=260
> 1425669071.262232 nfd DEBUG: [Forwarder] onIncomingInterest face=303 interest=/ndn/edu/wustl/ping/1744606568
> _______________________________________________
> Nfd-dev mailing list
> Nfd-dev at lists.cs.ucla.edu
> http://www.lists.cs.ucla.edu/mailman/listinfo/nfd-dev