[Nfd-dev] NDN-RTC: NFD processing logs

Davide Pesavento davide.pesavento at lip6.fr
Thu Feb 5 22:22:27 PST 2015


Peter,

I just checked the code. DatagramFace does not contain a logger
instance, therefore the name of the component you need to enable is
"UdpFace", at the TRACE level. Sorry for the confusion.

To avoid this kind of problems in the future, you can additionally
enable "LoggerFactory" at the DEBUG level. (We should change that to a
warning by the way)

Best,
Davide

On Wed, Feb 4, 2015 at 12:14 AM, Davide Pesavento <davidepesa at gmail.com> wrote:
> Hi Jeff,
>
> Regarding your last question, if you enable the TRACE log level in NFD
> configuration file you should get additional logging when the face receives
> or sends anything over the wire. You should see something like:
>
> TRACE: [UdpFace] [id:42,...] Received X bytes
> or
> TRACE: [UdpFace] [id:42,...] Sent X bytes
>
> If my memory serves me well, those are respectively the first and last
> messages printed by NFD.
>
> Best,
> Davide
>
>
> On Wed, Feb 4, 2015, 7:01 AM Burke, Jeff <jburke at remap.ucla.edu> wrote:
>>
>> Junxiao,
>>
>> The application is intended to work over the current internet with low
>> risk of IP fragmentation, so we are designing the packet sizes for MTUs of
>> 1500 octets.
>>
>> Peter, can you run NTP in a peer-to-peer configuration to lower the clock
>> offset between the vious machines and make it easier to troubleshoot just
>> based on the logging?  I can give you a configuration tomorrow.
>>
>> Junxiao, in addition to tcpdump, is there anything that logs at a lower
>> layer in NFD which we could use to see when interest/data bits first come in
>> over the wire?
>>
>> We will bring the whole setup to the ndn retreat...
>>
>> Jeff
>>
>>
>> From: Junxiao Shi <shijunxiao at email.arizona.edu>
>> Date: Tue, 3 Feb 2015 22:50:35 -0700
>> To: "Gusev, Peter" <peter at remap.ucla.edu>
>> Cc: Jeff Burke <jburke at remap.ucla.edu>, "nfd-dev at lists.cs.ucla.edu"
>> <nfd-dev at lists.cs.ucla.edu>
>>
>> Subject: Re: [Nfd-dev] NDN-RTC: NFD processing logs
>>
>> Hi Peter
>>
>> I forgot to ask earlier: what's the MTU of the NICs?
>> Make sure the MTU is 9000 octets or higher, otherwise IP fragmentation
>> will severely affect performance.
>>
>>
>> Congestion is unlikely to happen with 200Kbps traffic on 1000Mbps link.
>> CPU is also unlikely to be a bottleneck for 60 Interests/s.
>>
>> Use `tcpdump` to see exactly when the packet is transmitted onto the
>> network, in order to determine whether the delay is happening on sender host
>> or receiver host.
>> Running `tcpdump` on the host itself will affect its performance. If an
>> impact is evident, you could setup port mirroring on the switch, and run
>> `tcpdump` on another machine that is connected to the mirrored port.
>>
>> Yours, Junxiao
>>
>> On Tue, Feb 3, 2015 at 12:56 PM, Gusev, Peter <peter at remap.ucla.edu>
>> wrote:
>>>
>>> Hi Junxiao,
>>>
>>> I run tests with all three (consumer, producer and hub) connected to the
>>> same 1Gbit switch. For the app configuration I tested - bitrate is
>>> ~150-200kbit/s, interest rate is about 50-60.
>>>
>>> And discovered these cases:
>>>
>>> Case #1
>>>
>>> NFD1 (consumer):
>>>
>>> 1422920300.410412DEBUG: [Forwarder] onIncomingInterest face=261
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>>
>>> 1422920300.410804 DEBUG: [Forwarder] onOutgoingInterest face=259
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920300.411138 DEBUG: [BestRouteStrategy2]
>>> /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=2128078661
>>> from=261 newPitEntry-to=259
>>> ^ 0 sec, 440 msec // retransmission
>>> 1422920300.851526 DEBUG: [Forwarder] onIncomingInterest face=261
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920300.851843 DEBUG: [Forwarder] onOutgoingInterest face=259
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920300.852127 DEBUG: [BestRouteStrategy2]
>>> /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=2749769734
>>> from=261 retransmit-retry-to=259
>>> ^ 0 sec, 302 msec // data
>>> 1422920301.155108 DEBUG: [Forwarder] onIncomingData face=259
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
>>> 1422920301.155452 DEBUG: [Forwarder] onIncomingData
>>> matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920301.155680 DEBUG: [Strategy] beforeSatisfyPendingInterest
>>> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> inFace=259
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
>>> 1422920301.156152 DEBUG: [Forwarder] onOutgoingData face=261
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
>>>
>>>
>>> NFD2 (hub):
>>> 1422920250.169018DEBUG: [Forwarder] onIncomingInterest face=266
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>>
>>> 1422920250.169560 DEBUG: [Forwarder] onOutgoingInterest face=264
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920250.169959 DEBUG: [BestRouteStrategy2]
>>> /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=2128078661
>>> from=266 newPitEntry-to=264
>>> ^ 0 sec, 736.911 msec // retransmission
>>> 1422920250.906870 DEBUG: [Forwarder] onIncomingInterest face=266
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920250.907384 DEBUG: [Forwarder] onOutgoingInterest face=264
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920250.907801 DEBUG: [BestRouteStrategy2]
>>> /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=2749769734
>>> from=266 retransmit-retry-to=264
>>> ^ 0 sec, 2.541 msec // data
>>> 1422920250.910342 DEBUG: [Forwarder] onIncomingData face=264
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
>>> 1422920250.910812 DEBUG: [Forwarder] onIncomingData
>>> matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920250.911125 DEBUG: [Strategy] beforeSatisfyPendingInterest
>>> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> inFace=264
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
>>> 1422920250.911706 DEBUG: [Forwarder] onOutgoingData face=266
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
>>> 1422920250.922749 DEBUG: [Forwarder] onIncomingData face=264
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
>>> 1422920250.923068 DEBUG: [Forwarder] onIncomingData
>>> matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920250.923315 DEBUG: [Strategy] beforeSatisfyPendingInterest
>>> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> inFace=264
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
>>>
>>> NFD3 (producer):
>>>
>>> 1422920296.818710 DEBUG: [Forwarder] onIncomingInterest face=268
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920296.819102 DEBUG: [Forwarder] onOutgoingInterest face=265
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920296.819408 DEBUG: [BestRouteStrategy2]
>>> /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=2128078661
>>> from=268 newPitEntry-to=265
>>> ^ 0 sec, 551.408 msec // data
>>> 1422920297.370816 DEBUG: [Forwarder] onIncomingData face=265
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
>>> 1422920297.371248 DEBUG: [Forwarder] onIncomingData
>>> matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920297.371547 DEBUG: [Strategy] beforeSatisfyPendingInterest
>>> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> inFace=265
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
>>> 1422920297.372106 DEBUG: [Forwarder] onOutgoingData face=268
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
>>>
>>> ^ 0 sec, 184.298 msec// retransmission
>>>
>>> 1422920297.556404 DEBUG: [Forwarder] onIncomingInterest face=268
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00
>>> 1422920297.557030 DEBUG: [Forwarder] onOutgoingData face=268
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/13851/data/%00%00/3/14365/513/0
>>>
>>> Case #2
>>>
>>> NFD1 (consumer):
>>> 1422919936.433502DEBUG: [Forwarder] onIncomingInterest face=261
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00
>>>
>>> 1422919936.434221 DEBUG: [BestRouteStrategy2]
>>> /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=3853552983
>>> from=261 newPitEntry-to=259
>>> ^ 0 sec, 402.119 msec
>>> 1422919936.836340 DEBUG: [Forwarder] onIncomingData face=259
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00/1/4253/150/0
>>> 1422919936.836649 DEBUG: [Forwarder] onIncomingData
>>> matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00
>>> 1422919936.836871 DEBUG: [Strategy] beforeSatisfyPendingInterest
>>> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00
>>> inFace=259
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00/1/4253/150/0
>>> 1422919936.837279 DEBUG: [Forwarder] onOutgoingData face=261
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00/1/4253/150/0
>>>
>>>
>>>
>>> NFD2 (hub):
>>> 1422919886.178188DEBUG: [Forwarder] onIncomingInterest face=266
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00
>>>
>>> 1422919886.179368 DEBUG: [BestRouteStrategy2]
>>> /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=3791853569
>>> from=266 newPitEntry-to=264
>>> ^ 0 sec, 89.772 msec
>>> 1422919886.269140 DEBUG: [Forwarder] onIncomingData face=264
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00/1/4252/150/0
>>> 1422919886.269671 DEBUG: [Forwarder] onIncomingData
>>> matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00
>>> 1422919886.270079 DEBUG: [Strategy] beforeSatisfyPendingInterest
>>> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00
>>> inFace=264
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00/1/4252/150/0
>>> 1422919886.270718 DEBUG: [Forwarder] onOutgoingData face=266
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4101/data/%00%00/1/4252/150/0
>>>
>>>
>>>
>>> NFD3 (producer):
>>> 1422919932.865989DEBUG: [Forwarder] onIncomingInterest face=268
>>> interest=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00
>>>
>>> 1422919932.866855 DEBUG: [BestRouteStrategy2]
>>> /ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00?ndn.MustBeFresh=1&ndn.InterestLifetime=5000&ndn.Nonce=3853552983
>>> from=268 newPitEntry-to=265
>>> ^ 0 sec, 90.492 msec
>>> 1422919932.957347 DEBUG: [Forwarder] onIncomingData face=265
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00/1/4253/150/0
>>> 1422919932.958010 DEBUG: [Forwarder] onIncomingData
>>> matching=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00
>>> 1422919932.958342 DEBUG: [Strategy] beforeSatisfyPendingInterest
>>> pitEntry=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00
>>> inFace=265
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00/1/4253/150/0
>>> 1422919932.958955 DEBUG: [Forwarder] onOutgoingData face=268
>>> data=/ndn/edu/ucla/remap/ndnrtc/user/remap/streams/top_cam/low/delta/4102/data/%00%00/1/4253/150/0
>>>
>>>
>>>
>>> Can these be cases of congestions on such wideband setup?
>>>
>>> Thanks,
>>>
>>> --
>>> Peter Gusev
>>> Programmer/Analyst @ REMAP, UCLA
>>>
>>> peter at remap.ucla.edu
>>> +1 213 5872748
>>> peetonn_ (skype)
>>
>> _______________________________________________
>> Nfd-dev mailing list
>> Nfd-dev at lists.cs.ucla.edu
>> http://www.lists.cs.ucla.edu/mailman/listinfo/nfd-dev



More information about the Nfd-dev mailing list