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

Dehart, John jdd at wustl.edu
Sat Feb 7 07:50:30 PST 2015


Peter,

Hmm. The first thing I looked at is the start times of each troublesome Interest. Here are the times from
the onIncomingInterest at NFD1:

1423253848.858280

1423253940.375219

1423253970.817990

1423254001.344271

1423254031.836504

1423254062.336132

1423254123.211452

1423254153.709799

1423254184.230811

1423254214.784790

Notice anything? Except for the first one they are nicely spaced at roughly 30 second intervals.
There is one that is a 60 second interval. Could something be happening on one of the systems
every 30 seconds that is causing a disruption? Any chance you could grab system logs for
the three machines? I’m not that familiar with MacOS system logging so I don’t know what to look
for there...

I’ll dig more, hopefully later today.

John



On Feb 6, 2015, at 5:14 PM, Gusev, Peter <peter at remap.ucla.edu<mailto:peter at remap.ucla.edu>> wrote:

Hi guys,

So I’ve run setup today and gathered logs.
I’ve setup NFDs with the following settings
...
 default_level NONE
 Forwarder DEBUG
 UdpFace TRACE
…

And then I run tcpdump on each machine like this:
$ sudo tcpdump -w ~/dump.pcap -i en4 udp port 6363

Here is the summary on “problematic” packets:
https://docs.google.com/document/d/11JAPHI6J4jD6mibMRuWd1EvzP-NY_F2osM2vDF2VaGM/edit?usp=sharing

All the log files and tcpdumps you can find here:
https://www.dropbox.com/s/1d277xbhqs97o66/logs.zip?dl=0

Thanks for all the help!

Thanks,

--
Peter Gusev
Programmer/Analyst @ REMAP, UCLA

peter at remap.ucla.edu<mailto:peter at remap.ucla.edu>
+1 213 5872748
peetonn_ (skype)

On Feb 6, 2015, at 8:03 AM, Gusev, Peter <peter at remap.ucla.edu<mailto:peter at remap.ucla.edu>> wrote:

Ok, thanks Davide!
I’ll try this out

Thanks,

--
Peter Gusev
Programmer/Analyst @ REMAP, UCLA

peter at remap.ucla.edu<mailto: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<mailto: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<mailto: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<mailto: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<mailto:shijunxiao at email.arizona.edu>>
Date: Tue, 3 Feb 2015 22:50:35 -0700
To: "Gusev, Peter" <peter at remap.ucla.edu<mailto:peter at remap.ucla.edu>>
Cc: Jeff Burke <jburke at remap.ucla.edu<mailto:jburke at remap.ucla.edu>>, "nfd-dev at lists.cs.ucla.edu<mailto:nfd-dev at lists.cs.ucla.edu>"
<nfd-dev at lists.cs.ucla.edu<mailto: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<mailto: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<mailto:peter at remap.ucla.edu>
+1 213 5872748
peetonn_ (skype)

_______________________________________________
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


_______________________________________________
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

_______________________________________________
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/20150207/5877ddf6/attachment.html>


More information about the Nfd-dev mailing list