Bug #2626
Updated by Davide Pesavento about 9 years ago
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, 1425669071.230902 , nfd performs a `[ContentStore] " [ContentStore] find /localhost/nfd/faces/list R` R” but it doesn't doesn’t register `[ContentStore] " [ContentStore] no-match` 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` /localhost/nfd/faces/list takes a lot longer than any of the other find operations.