[Nfd-dev] Interest lifetime for NFD command interests

Alex Afanasyev alexander.afanasyev at ucla.edu
Mon Apr 28 19:01:15 PDT 2014 

From what I can see, the most time was spent on verifying of the command interest and signing the response.

---
Alex

> On Apr 28, 2014, at 6:45 PM, "Thompson, Jeff" <jefft0 at remap.ucla.edu> wrote:
> 
> Below is the DEBUG trace of prefix registration on the Pi. I changed the timestamps to elapsed time from receiving the request (and trucated the interests). Of course with the terminal I/O, it now takes 2.7 seconds, but hopefully it is representative.
> 
> - Jeff T
> 
> 0.000   DEBUG: [TcpChannel] [0.0.0.0:6363] << Connection from 127.0.0.1:45549
> 0.001   INFO: [FaceTable] Added face id=5 remote=tcp4://127.0.0.1:45549 local=tcp4://127.0.0.1:6363
> 0.324   DEBUG: [Forwarder] onIncomingData face=1 data=/localhost/nfd/faces/events/%04
> 0.335   DEBUG: [Forwarder] onIncomingData matching=/localhost/nfd/faces/events
> 0.340   DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/localhost/nfd/faces/events inFace=1 data=/localhost/nfd/faces/events/%04
> 0.350   DEBUG: [Forwarder] onOutgoingData face=4 data=/localhost/nfd/faces/events/%04
> 0.355   DEBUG: [FaceMonitor] onNotification: Interest sent: /localhost/nfd/faces/events/%05?ndn.InterestLifetime=60000 milliseconds&ndn.Nonce=2975392766
> 0.363   DEBUG: [Forwarder] onIncomingInterest face=5 interest=/localhost/nfd/rib/register/h%0C%07%0A%08%08testecho
> 0.451   DEBUG: [Forwarder] onOutgoingInterest face=4 interest=/localhost/nfd/rib/register/h%0C%07%0A%08%08testecho
> 0.544   DEBUG: [Forwarder] onIncomingInterest face=4 interest=/localhost/nfd/faces/events/%05
> 0.555   DEBUG: [Forwarder] onOutgoingInterest face=1 interest=/localhost/nfd/faces/events/%05
> 0.568   DEBUG: [InternalFace] 1398735087.459180 DEBUG: [RibManager] Parameters parsed OK
> 0.570   DEBUG: [RibManager] command result: processing verb: register: /localhost/nfd/faces/events/%05
> 0.581   DEBUG: [InternalFace] found Interest filter for /localhost/nfd/faces (previous match)
> 0.597   DEBUG: [FaceManager] command result: processing verb: events
> 0.908   DEBUG: [Forwarder] onIncomingInterest face=4 interest=/localhost/nfd/fib/add-nexthop/h%12%07%0A%08%08testechoi%01%05j%01%00/%00%00%01E%AB%1B%A7r
> 1.004   DEBUG: [Forwarder] onOutgoingInterest face=1 interest=/localhost/nfd/fib/add-nexthop/h%12%07%0A%08%08testechoi%01%05j%01%00/%00%00%01E%AB%1B%A7r
> 1.095   DEBUG: [InternalFace] received Interest: /localhost/nfd/fib/add-nexthop/h%12%07%0A%08%08testecho
> 1.944   DEBUG: [Forwarder] onOutgoingData face=4 data=/localhost/nfd/fib/add-nexthop/h%12%07%0A%08%08testechoi%01%05j%01%00/%00%00%01E%AB%1B%A7r
> 2.356   DEBUG: [Forwarder] onIncomingData face=4 data=/localhost/nfd/rib/register/h%0C%07%0A%08%08testecho/%01E%AB%1B%A2%93
> 2.443   DEBUG: [Forwarder] onIncomingData matching=/localhost/nfd/rib/register/h%0C%07%0A%08%08testecho/%01E%AB%1B%A2%93/%BF%15%EE%EE%FC%CDw%C5
> 2.528   DEBUG: [Strategy] beforeSatisfyPendingInterest pitEntry=/localhost/nfd/rib/register/h%0C%07%0A%08%08testecho/%01E%AB%1B%A2%93/%BF%15%EE%EE%FC%CDw%C5
> 2.691   DEBUG: [Forwarder] onOutgoingData face=5 data=/localhost/nfd/rib/register/h%0C%07%0A%08%08testecho/%01E%AB%1B%A2%93
> 
> From: Alex Afansyev <alexander.afanasyev at ucla.edu>
> Date: Monday, April 28, 2014 6:18 PM
> To: Jeff Thompson <jefft0 at remap.ucla.edu>
> Cc: Jeff Burke <jburke at remap.ucla.edu>, nfd-dev <nfd-dev at lists.cs.ucla.edu>
> Subject: Re: [Nfd-dev] Interest lifetime for NFD command interests
> 
> it's in the config file.  You can either change log level globally (the most verbose is TRACE) or do it per-module
> 
> ---
> Alex
> 
>> On Apr 28, 2014, at 6:16 PM, Thompson, Jeff <jefft0 at remap.ucla.edu> wrote:
>> 
>> Does anyone know what is the command to increase the debug log level in NFD, so I can get a trace?  (nfd --help doesn't seem to say.) 
>> 
>> - Jeff T
>> 
>> From: <Burke>, Jeff Burke <jburke at remap.ucla.edu>
>> Date: Monday, April 28, 2014 6:07 PM
>> To: Jeff Thompson <jefft0 at remap.ucla.edu>, Alex Afansyev <alexander.afanasyev at ucla.edu>
>> Cc: nfd-dev <nfd-dev at lists.cs.ucla.edu>
>> Subject: Re: [Nfd-dev] Interest lifetime for NFD command interests
>> 
>> 
>> Most of the redmine issue referenced by Alex deals with timeouts in the case of an unavailable remote node, failed dns lookup, etc., but in a successful registration—such as the one taking 1200ms on the PI— what are the dominant time components?  
>> 
>> Jeff
>> 
>> From: "Thompson, Jeff" <jefft0 at remap.ucla.edu>
>> Date: Tue, 29 Apr 2014 00:58:44 +0000
>> To: Alex Afanasyev <alexander.afanasyev at ucla.edu>
>> Cc: nfd-dev <nfd-dev at lists.cs.ucla.edu>
>> Subject: Re: [Nfd-dev] Interest lifetime for NFD command interests
>> 
>> Hi Alex,
>> 
>> Fair enough.  But I just tested on the Raspberry Pi, and it takes NFD 1200 seconds to answer a prefix registration.  For use on the Pi, we increased the command interest lifetime to 2000 milliseconds.
>> 
>> - Jeff T
>> 
>> From: Alex Afansyev <alexander.afanasyev at ucla.edu>
>> Date: Friday, April 18, 2014 2:10 PM
>> To: Jeff Thompson <jefft0 at remap.ucla.edu>
>> Cc: nfd-dev <nfd-dev at lists.cs.ucla.edu>
>> Subject: Re: [Nfd-dev] Interest lifetime for NFD command interests
>> 
>> Hi Jeff,
>> 
>> I agree completely with this for prefix registration commands.  I would say, there is no much value/reason to make the lifetime longer than, say, a second.  Could be shorter, but on some extremely busy systems (like our Jenkins slave), even a simple registration may take some time.
>> 
>> For face creation, lifetime should be longer that 4 seconds since it can take some time to create some tunnels (e.g., TCP).  We even have a redmine issue for that (http://redmine.named-data.net/issues/1455)
>> 
>> ---
>> Alex
>> 
>>> On Apr 18, 2014, at 11:51 AM, Thompson, Jeff <jefft0 at remap.ucla.edu> wrote:
>>> 
>>> For a command interest to NFD/NRD, is there a recommended InterestLifetime (used as a timeout)?  Since it goes to the local host, can it safely be shorter than 4000 milliseconds?
>>> 
>>> Thank you,
>>> - Jeff T
>> _______________________________________________ Nfd-dev mailing list Nfd-dev at lists.cs.ucla.edu http://www.lists.cs.ucla.edu/mailman/listinfo/nfd-dev
> 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.lists.cs.ucla.edu/pipermail/nfd-dev/attachments/20140428/7572cf11/attachment.html>

More information about the Nfd-dev mailing list