[Nfd-dev] Interest lifetime for NFD command interests

Mon Apr 28 18:45:54 PDT 2014

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<mailto:alexander.afanasyev at ucla.edu>>
Date: Monday, April 28, 2014 6:18 PM
To: Jeff Thompson <jefft0 at remap.ucla.edu<mailto:jefft0 at remap.ucla.edu>>
Cc: Jeff Burke <jburke at remap.ucla.edu<mailto:jburke at remap.ucla.edu>>, nfd-dev <nfd-dev at lists.cs.ucla.edu<mailto: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<mailto: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<mailto:jburke at remap.ucla.edu>>
Date: Monday, April 28, 2014 6:07 PM
To: Jeff Thompson <jefft0 at remap.ucla.edu<mailto:jefft0 at remap.ucla.edu>>, Alex Afansyev <alexander.afanasyev at ucla.edu<mailto:alexander.afanasyev at ucla.edu>>
Cc: nfd-dev <nfd-dev at lists.cs.ucla.edu<mailto: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<mailto:jefft0 at remap.ucla.edu>>
Date: Tue, 29 Apr 2014 00:58:44 +0000
To: Alex Afanasyev <alexander.afanasyev at ucla.edu<mailto:alexander.afanasyev at ucla.edu>>
Cc: nfd-dev <nfd-dev at lists.cs.ucla.edu<mailto: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<mailto:alexander.afanasyev at ucla.edu>>
Date: Friday, April 18, 2014 2:10 PM
To: Jeff Thompson <jefft0 at remap.ucla.edu<mailto:jefft0 at remap.ucla.edu>>
Cc: nfd-dev <nfd-dev at lists.cs.ucla.edu<mailto: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<mailto: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<mailto: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/20140429/937281de/attachment.html>