NFD

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 22.748 ms.

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

Here are some other examples of CS 'find' operations:

1425669061.723974 DEBUG: [ContentStore] find /localhost/nfd/faces/events R
1425669061.725418 DEBUG: [ContentStore]   no-match

1425669105.051430 DEBUG: [ContentStore] find /localhost/nfd/faces/list R
1425669105.074600 DEBUG: [ContentStore]   no-match

1425669001.213923 DEBUG: [ContentStore] find /localhost/nfd/status R
1425669001.214097 DEBUG: [ContentStore]   no-match

1425669001.222970 DEBUG: [ContentStore] find /localhost/nfd/faces/channels R
1425669001.223182 DEBUG: [ContentStore]   no-match

1425669001.639833 DEBUG: [ContentStore] find /localhost/nfd/faces/query/%96%1Cr%1Audp4%3A%2F%2F128.252.153.28%3A6363 R
1425669001.640152 DEBUG: [ContentStore]   no-match

1425669105.099019 DEBUG: [ContentStore] find /ndn/it/unipd/ndnmap/stats/72.36.112.82/192.43.193.111/193.147.51.186/161.105.195.18 L
1425669105.101716 DEBUG: [ContentStore]   no-match

1425669105.242469 DEBUG: [ContentStore] find /ndn/edu/wustl/ping/1744606602 L
1425669105.242597 DEBUG: [ContentStore]   no-match

Analyzing these times, I get this:

   Time Diff       find log msg      no-match log mst               name
0.174045562744   1425669001.213923   1425669001.214097   find   /localhost/nfd/status   R   no-match
0.211954116821   1425669001.222970   1425669001.223182   find   /localhost/nfd/faces/channels   R   no-match
0.319004058838   1425669001.639833   1425669001.640152   find   /localhost/nfd/faces/query/%96%1Cr%1Audp4%3A%2F%2F128.252.153.28%3A6363   R   no-match
1.44410133362    1425669061.723974   1425669061.725418   find   /localhost/nfd/faces/events   R   no-match
23.1699943542    1425669105.051430   1425669105.074600   find   /localhost/nfd/faces/list   R   no-match
2.6969909668     1425669105.099019   1425669105.101716   find   /ndn/it/unipd/ndnmap/stats/72.36.112.82/192.43.193.111/193.147.51.186/161.105.195.18   L   no-match
0.128030776978   1425669105.242469   1425669105.242597   find   /ndn/edu/wustl/ping/1744606602   L   no-match

So, it appears that the find for /localhost/nfd/faces/list takes a lot longer than
any of the other find operations.