[Nfd-dev] Help needed with ASF measurement

[Ashlesh Gawande (agawande)]

I haven't found anything suspicious. There doesn't seem to be a code path that generates an out record without updating last renewed field.


Even if there was a bug in the forwarding pipeline and it is not updated somewhere, I think we should not get a negative value:


1477331706.109322 ERROR: [AsfMeasurements] Recording RTT for inFace: 311

1477331706.109335 ERROR: [AsfMeasurements] steady clock now: 2148492683226381 nanoseconds since boot outRecordLastRenewed: 7018100696742452000 nanoseconds since boot

1477331706.109351 ERROR: [AsfMeasurements] steadyRtt: -7015952204059211821 nanoseconds
1477331706.109368 ERROR: [AsfMeasurements] Wrong measurement

This means time::steady_clock::now() is smaller time::steady_clock::TimePoint::min().


(Machine is Ubuntu 14.04, gcc 4.9.3.

32 NFDs are running on this machine at the same time. Such wrong measurements happen randomly).


Ashlesh

________________________________
From: Lan Wang (lanwang)
Sent: Monday, October 24, 2016 1:21:49 PM
To: Junxiao Shi
Cc: Ashlesh Gawande (agawande); <nfd-dev at lists.cs.ucla.edu>
Subject: Re: Help needed with ASF measurement

Junxiao,

Thank you very much for the quick feedback.

Ashlesh: have you found anything suspicious?

Lan

On Oct 24, 2016, at 11:00 AM, Junxiao Shi <shijunxiao at email.arizona.edu<mailto:shijunxiao at email.arizona.edu>> wrote:


Hi Ashlesh

This is probably a forwarding pipelines bug, but I won't have time to diagnose this until at least Thursday.

Things to look at:

1. Find every code line that updates last renewed field.
2. Find which forwarding pipelines calls the function that updates last renewed field.
3. Determine if there's a code path that generates an out record without updating last renewed field.

Yours, Junxiao

On Oct 24, 2016 08:52, "Ashlesh Gawande (agawande)" <agawande at memphis.edu<mailto:agawande at memphis.edu>> wrote:

Hi Junxiao


I am testing ASF in Mini-NDN.


The following line calculates the steady RTT by subtracting outRecord->getLastRenewed()

from time::steady_clock::now()

https://github.com/named-data/NFD/blob/master/daemon/fw/asf-measurements.cpp#L117

(which is called from beforeSatisfyInterest https://github.com/named-data/NFD/blob/master/daemon/fw/asf-strategy.cpp#L115)


Sometimes the value of this steadyRTT is huge (ex: 200000 seconds) or negative.

This makes ASF change faces to a higher RTT face.


So what could be the reason that this happening? I see much better and expected results if I ignore these high/negative values.


(I see that https://github.com/named-data/NFD/blob/master/daemon/table/pit-face-record.cpp#L34

initializes getLastRenewed to time::steady_clock::TimePoint::min(). So maybe for some reason getLastRenewed does not get updated?)


Thanks

Ashlesh


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.lists.cs.ucla.edu/pipermail/nfd-dev/attachments/20161024/44a6e87a/attachment.html>