Skip to content

Commit

Permalink
fw: refactor strategy logging and improve ASF probe logging
Browse files Browse the repository at this point in the history 
Bring strategy logging in line with format from 6bf94c0.
This should also marginally improve performance when log level is raised.

Refs: #5262, #5267
Co-authored-by: Davide Pesavento <[email protected]>
Change-Id: I6493b6476f3d0c6ae5562b66abfa46f6c6f4903d
  • Loading branch information
@awlane @Pesa
awlane and Pesa committed Jul 28, 2023
1 parent 6bf94c0 commit 653eb07
Show file tree
Hide file tree
Showing 9 changed files with 96 additions and 100 deletions.
41 changes: 20 additions & 21 deletions daemon/fw/access-strategy.cpp
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
/* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */
/*
* Copyright (c) 2014-2022, Regents of the University of California,
* Copyright (c) 2014-2023, Regents of the University of California,
* Arizona Board of Regents,
* Colorado State University,
* University Pierre & Marie Curie, Sorbonne University,
Expand Down Expand Up @@ -65,7 +65,7 @@ AccessStrategy::afterReceiveInterest(const Interest& interest, const FaceEndpoin
case RetxSuppressionResult::FORWARD:
return afterReceiveRetxInterest(interest, ingress, pitEntry);
case RetxSuppressionResult::SUPPRESS:
NFD_LOG_DEBUG(interest << " interestFrom " << ingress << " retx-suppress");
NFD_LOG_INTEREST_FROM(interest, ingress, "suppressed");
return;
}
}
Expand All @@ -79,7 +79,7 @@ AccessStrategy::afterReceiveNewInterest(const Interest& interest, const FaceEndp

// has measurements for Interest Name?
if (mi != nullptr) {
NFD_LOG_DEBUG(interest << " interestFrom " << ingress << " new-interest mi=" << miName);
NFD_LOG_INTEREST_FROM(interest, ingress, "new mi=" << miName);

// send to last working nexthop
bool isSentToLastNexthop = this->sendToLastNexthop(interest, ingress, pitEntry, *mi, fibEntry);
Expand All @@ -88,7 +88,7 @@ AccessStrategy::afterReceiveNewInterest(const Interest& interest, const FaceEndp
}
}
else {
NFD_LOG_DEBUG(interest << " interestFrom " << ingress << " new-interest no-mi");
NFD_LOG_INTEREST_FROM(interest, ingress, "new no-mi");
}

// no measurements, or last working nexthop unavailable
Expand All @@ -105,8 +105,8 @@ void
AccessStrategy::afterReceiveRetxInterest(const Interest& interest, const FaceEndpoint& ingress,
const shared_ptr<pit::Entry>& pitEntry)
{
NFD_LOG_INTEREST_FROM(interest, ingress, "retx");
const auto& fibEntry = this->lookupFib(*pitEntry);
NFD_LOG_DEBUG(interest << " interestFrom " << ingress << " retx-forward");
this->multicast(interest, ingress.face, pitEntry, fibEntry);
}

Expand All @@ -116,29 +116,29 @@ AccessStrategy::sendToLastNexthop(const Interest& interest, const FaceEndpoint&
const fib::Entry& fibEntry)
{
if (mi.lastNexthop == face::INVALID_FACEID) {
NFD_LOG_DEBUG(pitEntry->getInterest() << " no-last-nexthop");
NFD_LOG_INTEREST_FROM(interest, ingress, "no-last-nexthop");
return false;
}

if (mi.lastNexthop == ingress.face.getId()) {
NFD_LOG_DEBUG(pitEntry->getInterest() << " last-nexthop-is-downstream");
NFD_LOG_INTEREST_FROM(interest, ingress, "last-nexthop-is-downstream");
return false;
}

Face* outFace = this->getFace(mi.lastNexthop);
if (outFace == nullptr || !fibEntry.hasNextHop(*outFace)) {
NFD_LOG_DEBUG(pitEntry->getInterest() << " last-nexthop-gone");
NFD_LOG_INTEREST_FROM(interest, ingress, "last-nexthop-gone");
return false;
}

if (wouldViolateScope(ingress.face, interest, *outFace)) {
NFD_LOG_DEBUG(pitEntry->getInterest() << " last-nexthop-violates-scope");
NFD_LOG_INTEREST_FROM(interest, ingress, "last-nexthop-violates-scope");
return false;
}

auto rto = mi.rtt.getEstimatedRto();
NFD_LOG_DEBUG(pitEntry->getInterest() << " interestTo " << mi.lastNexthop
<< " last-nexthop rto=" << time::duration_cast<time::microseconds>(rto).count());
NFD_LOG_INTEREST_FROM(interest, ingress, "to=" << mi.lastNexthop << " last-nexthop rto="
<< time::duration_cast<time::microseconds>(rto).count() << "us");

if (!this->sendInterest(interest, *outFace, pitEntry)) {
return false;
Expand All @@ -164,8 +164,8 @@ AccessStrategy::afterRtoTimeout(const weak_ptr<pit::Entry>& pitWeak,

Face* inFace = this->getFace(inFaceId);
if (inFace == nullptr) {
NFD_LOG_DEBUG(pitEntry->getInterest() << " timeoutFrom " << firstOutFaceId
<< " inFace-gone " << inFaceId);
NFD_LOG_DEBUG(pitEntry->getName() << " timeout from=" << firstOutFaceId
<< " in-face-gone=" << inFaceId);
return;
}

Expand All @@ -178,8 +178,7 @@ AccessStrategy::afterRtoTimeout(const weak_ptr<pit::Entry>& pitWeak,
const Interest& interest = inRecord->getInterest();
const fib::Entry& fibEntry = this->lookupFib(*pitEntry);

NFD_LOG_DEBUG(pitEntry->getInterest() << " timeoutFrom " << firstOutFaceId
<< " multicast-except " << firstOutFaceId);
NFD_LOG_DEBUG(pitEntry->getName() << " timeout from=" << firstOutFaceId << " multicast");
this->multicast(interest, *inFace, pitEntry, fibEntry, firstOutFaceId);
}

Expand All @@ -195,7 +194,8 @@ AccessStrategy::multicast(const Interest& interest, const Face& inFace,
wouldViolateScope(inFace, interest, outFace)) {
continue;
}
NFD_LOG_DEBUG(pitEntry->getInterest() << " interestTo " << outFace.getId() << " multicast");
NFD_LOG_DEBUG(interest.getName() << " nonce=" << interest.getNonce()
<< " multicast to=" << outFace.getId());
if (this->sendInterest(interest, outFace, pitEntry)) {
++nSent;
}
Expand All @@ -213,19 +213,18 @@ AccessStrategy::beforeSatisfyInterest(const Data& data, const FaceEndpoint& ingr
}

if (!pitEntry->hasInRecords()) { // already satisfied by another upstream
NFD_LOG_DEBUG(pitEntry->getInterest() << " dataFrom " << ingress << " not-fastest");
NFD_LOG_DATA_FROM(data, ingress, "not-fastest");
return;
}

auto outRecord = pitEntry->getOutRecord(ingress.face);
if (outRecord == pitEntry->out_end()) { // no out-record
NFD_LOG_DEBUG(pitEntry->getInterest() << " dataFrom " << ingress << " no-out-record");
if (outRecord == pitEntry->out_end()) {
NFD_LOG_DATA_FROM(data, ingress, "no-out-record");
return;
}

auto rtt = time::steady_clock::now() - outRecord->getLastRenewed();
NFD_LOG_DEBUG(pitEntry->getInterest() << " dataFrom " << ingress
<< " rtt=" << time::duration_cast<time::microseconds>(rtt).count());
NFD_LOG_DATA_FROM(data, ingress, "rtt=" << time::duration_cast<time::microseconds>(rtt).count() << "us");
this->updateMeasurements(ingress.face, data, rtt);
}

Expand Down
33 changes: 15 additions & 18 deletions daemon/fw/asf-strategy.cpp
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
/* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */
/*
* Copyright (c) 2014-2022, Regents of the University of California,
* Copyright (c) 2014-2023, Regents of the University of California,
* Arizona Board of Regents,
* Colorado State University,
* University Pierre & Marie Curie, Sorbonne University,
Expand All @@ -25,7 +25,6 @@

#include "asf-strategy.hpp"
#include "algorithm.hpp"
#include "common/global.hpp"
#include "common/logger.hpp"

namespace nfd::fw::asf {
Expand Down Expand Up @@ -75,11 +74,11 @@ AsfStrategy::afterReceiveInterest(const Interest& interest, const FaceEndpoint&
if (!hasPendingOutRecords(*pitEntry)) {
auto* faceToUse = getBestFaceForForwarding(interest, ingress.face, fibEntry, pitEntry);
if (faceToUse == nullptr) {
NFD_LOG_DEBUG(interest << " new-interest from=" << ingress << " no-nexthop");
NFD_LOG_INTEREST_FROM(interest, ingress, "new no-nexthop");
sendNoRouteNack(ingress.face, pitEntry);
}
else {
NFD_LOG_DEBUG(interest << " new-interest from=" << ingress << " forward-to=" << faceToUse->getId());
NFD_LOG_INTEREST_FROM(interest, ingress, "new forward-to=" << faceToUse->getId());
forwardInterest(interest, *faceToUse, fibEntry, pitEntry);
sendProbe(interest, ingress, *faceToUse, fibEntry, pitEntry);
}
Expand All @@ -91,13 +90,12 @@ AsfStrategy::afterReceiveInterest(const Interest& interest, const FaceEndpoint&
auto suppressResult = m_retxSuppression->decidePerUpstream(*pitEntry, *faceToUse);
if (suppressResult == RetxSuppressionResult::SUPPRESS) {
// Cannot be sent on this face, interest was received within the suppression window
NFD_LOG_DEBUG(interest << " retx-interest from=" << ingress
<< " forward-to=" << faceToUse->getId() << " suppressed");
NFD_LOG_INTEREST_FROM(interest, ingress, "retx forward-to=" << faceToUse->getId() << " suppressed");
}
else {
// The retx arrived after the suppression period: forward it but don't probe, because
// probing was done earlier for this interest when it was newly received
NFD_LOG_DEBUG(interest << " retx-interest from=" << ingress << " forward-to=" << faceToUse->getId());
NFD_LOG_INTEREST_FROM(interest, ingress, "retx forward-to=" << faceToUse->getId());
auto* outRecord = forwardInterest(interest, *faceToUse, fibEntry, pitEntry);
if (outRecord && suppressResult == RetxSuppressionResult::FORWARD) {
m_retxSuppression->incrementIntervalForOutRecord(*outRecord);
Expand All @@ -111,17 +109,16 @@ AsfStrategy::afterReceiveInterest(const Interest& interest, const FaceEndpoint&
const auto& nexthops = fibEntry.getNextHops();
auto it = findEligibleNextHopWithEarliestOutRecord(ingress.face, interest, nexthops, pitEntry);
if (it == nexthops.end()) {
NFD_LOG_DEBUG(interest << " retx-interest from=" << ingress << " no eligible nexthop");
NFD_LOG_INTEREST_FROM(interest, ingress, "retx no-nexthop");
return;
}
auto& outFace = it->getFace();
auto suppressResult = m_retxSuppression->decidePerUpstream(*pitEntry, outFace);
if (suppressResult == RetxSuppressionResult::SUPPRESS) {
NFD_LOG_DEBUG(interest << " retx-interest from=" << ingress
<< " retry-to=" << outFace.getId() << " suppressed");
NFD_LOG_INTEREST_FROM(interest, ingress, "retx retry-to=" << outFace.getId() << " suppressed");
}
else {
NFD_LOG_DEBUG(interest << " retx-interest from=" << ingress << " retry-to=" << outFace.getId());
NFD_LOG_INTEREST_FROM(interest, ingress, "retx retry-to=" << outFace.getId());
// sendInterest() is used here instead of forwardInterest() because the measurements info
// were already attached to this face in the previous forwarding
auto* outRecord = sendInterest(interest, outFace, pitEntry);
Expand All @@ -137,25 +134,24 @@ AsfStrategy::beforeSatisfyInterest(const Data& data, const FaceEndpoint& ingress
{
NamespaceInfo* namespaceInfo = m_measurements.getNamespaceInfo(pitEntry->getName());
if (namespaceInfo == nullptr) {
NFD_LOG_DEBUG(pitEntry->getName() << " data from=" << ingress << " no-measurements");
NFD_LOG_DATA_FROM(data, ingress, "no-measurements");
return;
}

// Record the RTT between the Interest out to Data in
FaceInfo* faceInfo = namespaceInfo->getFaceInfo(ingress.face.getId());
if (faceInfo == nullptr) {
NFD_LOG_DEBUG(pitEntry->getName() << " data from=" << ingress << " no-face-info");
NFD_LOG_DATA_FROM(data, ingress, "no-face-info");
return;
}

auto outRecord = pitEntry->getOutRecord(ingress.face);
if (outRecord == pitEntry->out_end()) {
NFD_LOG_DEBUG(pitEntry->getName() << " data from=" << ingress << " no-out-record");
NFD_LOG_DATA_FROM(data, ingress, "no-out-record");
}
else {
faceInfo->recordRtt(time::steady_clock::now() - outRecord->getLastRenewed());
NFD_LOG_DEBUG(pitEntry->getName() << " data from=" << ingress
<< " rtt=" << faceInfo->getLastRtt() << " srtt=" << faceInfo->getSrtt());
NFD_LOG_DATA_FROM(data, ingress, "rtt=" << faceInfo->getLastRtt() << " srtt=" << faceInfo->getSrtt());
}

// Extend lifetime for measurements associated with Face
Expand All @@ -169,7 +165,7 @@ void
AsfStrategy::afterReceiveNack(const lp::Nack& nack, const FaceEndpoint& ingress,
const shared_ptr<pit::Entry>& pitEntry)
{
NFD_LOG_DEBUG(nack.getInterest() << " nack from=" << ingress << " reason=" << nack.getReason());
NFD_LOG_NACK_FROM(nack, ingress, "");
onTimeoutOrNack(pitEntry->getName(), ingress.face.getId(), true);
}

Expand Down Expand Up @@ -213,7 +209,8 @@ AsfStrategy::sendProbe(const Interest& interest, const FaceEndpoint& ingress, co

Interest probeInterest(interest);
probeInterest.refreshNonce();
NFD_LOG_TRACE("Sending probe " << probeInterest << " to=" << faceToProbe->getId());
NFD_LOG_DEBUG("Sending probe " << probeInterest.getName() << " nonce=" << probeInterest.getNonce()
<< " to=" << faceToProbe->getId() << " trigger-nonce=" << interest.getNonce());
forwardInterest(probeInterest, *faceToProbe, fibEntry, pitEntry);

m_probing.afterForwardingProbe(fibEntry, interest.getName());
Expand Down
17 changes: 8 additions & 9 deletions daemon/fw/best-route-strategy.cpp
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
/* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */
/*
* Copyright (c) 2014-2022, Regents of the University of California,
* Copyright (c) 2014-2023, Regents of the University of California,
* Arizona Board of Regents,
* Colorado State University,
* University Pierre & Marie Curie, Sorbonne University,
Expand Down Expand Up @@ -61,9 +61,9 @@ void
BestRouteStrategy::afterReceiveInterest(const Interest& interest, const FaceEndpoint& ingress,
const shared_ptr<pit::Entry>& pitEntry)
{
RetxSuppressionResult suppression = m_retxSuppression->decidePerPitEntry(*pitEntry);
auto suppression = m_retxSuppression->decidePerPitEntry(*pitEntry);
if (suppression == RetxSuppressionResult::SUPPRESS) {
NFD_LOG_DEBUG(interest << " from=" << ingress << " suppressed");
NFD_LOG_INTEREST_FROM(interest, ingress, "suppressed");
return;
}

Expand All @@ -78,8 +78,7 @@ BestRouteStrategy::afterReceiveInterest(const Interest& interest, const FaceEndp
});

if (it == nexthops.end()) {
NFD_LOG_DEBUG(interest << " from=" << ingress << " noNextHop");

NFD_LOG_INTEREST_FROM(interest, ingress, "new no-nexthop");
lp::NackHeader nackHeader;
nackHeader.setReason(lp::NackReason::NO_ROUTE);
this->sendNack(nackHeader, ingress.face, pitEntry);
Expand All @@ -88,7 +87,7 @@ BestRouteStrategy::afterReceiveInterest(const Interest& interest, const FaceEndp
}

Face& outFace = it->getFace();
NFD_LOG_DEBUG(interest << " from=" << ingress << " newPitEntry-to=" << outFace.getId());
NFD_LOG_INTEREST_FROM(interest, ingress, "new to=" << outFace.getId());
this->sendInterest(interest, outFace, pitEntry);
return;
}
Expand All @@ -102,19 +101,19 @@ BestRouteStrategy::afterReceiveInterest(const Interest& interest, const FaceEndp
if (it != nexthops.end()) {
Face& outFace = it->getFace();
this->sendInterest(interest, outFace, pitEntry);
NFD_LOG_DEBUG(interest << " from=" << ingress << " retransmit-unused-to=" << outFace.getId());
NFD_LOG_INTEREST_FROM(interest, ingress, "retx unused-to=" << outFace.getId());
return;
}

// find an eligible upstream that is used earliest
it = findEligibleNextHopWithEarliestOutRecord(ingress.face, interest, nexthops, pitEntry);
if (it == nexthops.end()) {
NFD_LOG_DEBUG(interest << " from=" << ingress << " retransmitNoNextHop");
NFD_LOG_INTEREST_FROM(interest, ingress, "retx no-nexthop");
}
else {
Face& outFace = it->getFace();
this->sendInterest(interest, outFace, pitEntry);
NFD_LOG_DEBUG(interest << " from=" << ingress << " retransmit-retry-to=" << outFace.getId());
NFD_LOG_INTEREST_FROM(interest, ingress, "retx retry-to=" << outFace.getId());
}
}

Expand Down
16 changes: 7 additions & 9 deletions daemon/fw/multicast-strategy.cpp
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
/* -*- Mode:C++; c-file-style:"gnu"; indent-tabs-mode:nil; -*- */
/*
* Copyright (c) 2014-2022, Regents of the University of California,
* Copyright (c) 2014-2023, Regents of the University of California,
* Arizona Board of Regents,
* Colorado State University,
* University Pierre & Marie Curie, Sorbonne University,
Expand Down Expand Up @@ -67,18 +67,17 @@ MulticastStrategy::afterReceiveInterest(const Interest& interest, const FaceEndp
for (const auto& nexthop : nexthops) {
Face& outFace = nexthop.getFace();

RetxSuppressionResult suppressResult = m_retxSuppression->decidePerUpstream(*pitEntry, outFace);

auto suppressResult = m_retxSuppression->decidePerUpstream(*pitEntry, outFace);
if (suppressResult == RetxSuppressionResult::SUPPRESS) {
NFD_LOG_DEBUG(interest << " from=" << ingress << " to=" << outFace.getId() << " suppressed");
NFD_LOG_INTEREST_FROM(interest, ingress, "to=" << outFace.getId() << " suppressed");
continue;
}

if (!isNextHopEligible(ingress.face, interest, nexthop, pitEntry)) {
continue;
}

NFD_LOG_DEBUG(interest << " from=" << ingress << " pitEntry-to=" << outFace.getId());
NFD_LOG_INTEREST_FROM(interest, ingress, "to=" << outFace.getId());
auto* sentOutRecord = this->sendInterest(interest, outFace, pitEntry);
if (sentOutRecord && suppressResult == RetxSuppressionResult::FORWARD) {
m_retxSuppression->incrementIntervalForOutRecord(*sentOutRecord);
Expand All @@ -93,16 +92,15 @@ MulticastStrategy::afterNewNextHop(const fib::NextHop& nextHop,
// no need to check for suppression, as it is a new next hop

auto nextHopFaceId = nextHop.getFace().getId();
auto& interest = pitEntry->getInterest();
const auto& interest = pitEntry->getInterest();

// try to find an incoming face record that doesn't violate scope restrictions
for (const auto& r : pitEntry->getInRecords()) {
auto& inFace = r.getFace();
if (isNextHopEligible(inFace, interest, nextHop, pitEntry)) {

NFD_LOG_DEBUG(interest << " from=" << inFace.getId() << " pitEntry-to=" << nextHopFaceId);
if (isNextHopEligible(inFace, interest, nextHop, pitEntry)) {
NFD_LOG_INTEREST_FROM(interest, inFace.getId(), "new-nexthop to=" << nextHopFaceId);
this->sendInterest(interest, nextHop.getFace(), pitEntry);

break; // just one eligible incoming face record is enough
}
}
Expand Down
Loading

0 comments on commit 653eb07

Please sign in to comment.