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

[Gusev, Peter]

Ok, thanks Davide!
I’ll try this out

Thanks, 

-- 
Peter Gusev
Programmer/Analyst @ REMAP, UCLA

peter at remap.ucla.edu
+1 213 5872748
peetonn_ (skype)

> On Feb 5, 2015, at 10:22 PM, Davide Pesavento <davide.pesavento at lip6.fr> wrote:
> 
> 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