logs: Guard frequently called logs behind if check

Moves a number of heavily called debug lines behind if checks to avoid needless allocations of Fields objects and stringification of fields. For cases where the server is not set to "debug" log level, these fields were allocated on the heap and then immediately discarded - as well a number of these were stringifying state / NLRIs regardless of log level. In servers with significant amounts of routes and BGP peers, this lead to a large amount of wasted allocations - in our case looking at Go's memory profiler, 25% of all allocations were from these lines alone.
osrg · Mar 2, 2024 · 003745a · 003745a
1 parent 87e5b81
commit 003745a
Show file tree

Hide file tree

Showing 4 changed files with 63 additions and 45 deletions.
diff --git a/internal/pkg/table/destination.go b/internal/pkg/table/destination.go
@@ -273,10 +273,12 @@ func (dest *Destination) Calculate(logger log.Logger, newPath *Path) *Update {
 // we can receive withdraws for such paths and withdrawals may not be
 // stopped by the same policies.
 func (dest *Destination) explicitWithdraw(logger log.Logger, withdraw *Path) *Path {
-	logger.Debug("Removing withdrawals",
-		log.Fields{
-			"Topic": "Table",
-			"Key":   dest.GetNlri().String()})
+	if logger.GetLevel() >= log.DebugLevel {
+		logger.Debug("Removing withdrawals",
+			log.Fields{
+				"Topic": "Table",
+				"Key":   dest.GetNlri().String()})
+	}
 
 	// If we have some withdrawals and no know-paths, it means it is safe to
 	// delete these withdraws.
@@ -328,11 +330,13 @@ func (dest *Destination) implicitWithdraw(logger log.Logger, newPath *Path) {
 		// paths and when doing RouteRefresh (not EnhancedRouteRefresh)
 		// we get same paths again.
 		if newPath.GetSource().Equal(path.GetSource()) && newPath.GetNlri().PathIdentifier() == path.GetNlri().PathIdentifier() {
-			logger.Debug("Implicit withdrawal of old path, since we have learned new path from the same peer",
-				log.Fields{
-					"Topic": "Table",
-					"Key":   dest.GetNlri().String(),
-					"Path":  path})
+			if logger.GetLevel() >= log.DebugLevel {
+				logger.Debug("Implicit withdrawal of old path, since we have learned new path from the same peer",
+					log.Fields{
+						"Topic": "Table",
+						"Key":   dest.GetNlri().String(),
+						"Path":  path})
+			}
 
 			found = i
 			newPath.GetNlri().SetPathLocalIdentifier(path.GetNlri().PathLocalIdentifier())

diff --git a/pkg/server/fsm.go b/pkg/server/fsm.go
@@ -537,10 +537,12 @@ func (h *fsmHandler) connectLoop(ctx context.Context, wg *sync.WaitGroup) {
 			timer.Stop()
 			return
 		case <-timer.C:
-			fsm.logger.Debug("try to connect",
-				log.Fields{
-					"Topic": "Peer",
-					"Key":   addr})
+			if fsm.logger.GetLevel() >= log.DebugLevel {
+				fsm.logger.Debug("try to connect",
+					log.Fields{
+						"Topic": "Peer",
+						"Key":   addr})
+			}
 		}
 
 		laddr, err := net.ResolveTCPAddr("tcp", net.JoinHostPort(localAddress, strconv.Itoa(localPort)))
@@ -583,11 +585,13 @@ func (h *fsmHandler) connectLoop(ctx context.Context, wg *sync.WaitGroup) {
 							"Key":   addr})
 				}
 			} else {
-				fsm.logger.Debug("failed to connect",
-					log.Fields{
-						"Topic": "Peer",
-						"Key":   addr,
-						"Error": err})
+				if fsm.logger.GetLevel() >= log.DebugLevel {
+					fsm.logger.Debug("failed to connect",
+						log.Fields{
+							"Topic": "Peer",
+							"Key":   addr,
+							"Error": err})
+				}
 			}
 		}
 		tick = retry
@@ -1726,16 +1730,18 @@ func (h *fsmHandler) sendMessageloop(ctx context.Context, wg *sync.WaitGroup) er
 			return fmt.Errorf("closed")
 		case bgp.BGP_MSG_UPDATE:
 			update := m.Body.(*bgp.BGPUpdate)
-			fsm.lock.RLock()
-			fsm.logger.Debug("sent update",
-				log.Fields{
-					"Topic":       "Peer",
-					"Key":         fsm.pConf.State.NeighborAddress,
-					"State":       fsm.state.String(),
-					"nlri":        update.NLRI,
-					"withdrawals": update.WithdrawnRoutes,
-					"attributes":  update.PathAttributes})
-			fsm.lock.RUnlock()
+			if fsm.logger.GetLevel() >= log.DebugLevel {
+				fsm.lock.RLock()
+				fsm.logger.Debug("sent update",
+					log.Fields{
+						"Topic":       "Peer",
+						"Key":         fsm.pConf.State.NeighborAddress,
+						"State":       fsm.state.String(),
+						"nlri":        update.NLRI,
+						"withdrawals": update.WithdrawnRoutes,
+						"attributes":  update.PathAttributes})
+				fsm.lock.RUnlock()
+			}
 		default:
 			fsm.lock.RLock()
 			fsm.logger.Debug("sent",

diff --git a/pkg/server/peer.go b/pkg/server/peer.go
@@ -403,11 +403,13 @@ func (peer *peer) filterPathFromSourcePeer(path, old *table.Path) *table.Path {
 			return old.Clone(true)
 		}
 	}
-	peer.fsm.logger.Debug("From me, ignore",
-		log.Fields{
-			"Topic": "Peer",
-			"Key":   peer.ID(),
-			"Data":  path})
+	if peer.fsm.logger.GetLevel() >= log.DebugLevel {
+		peer.fsm.logger.Debug("From me, ignore",
+			log.Fields{
+				"Topic": "Peer",
+				"Key":   peer.ID(),
+				"Data":  path})
+	}
 	return nil
 }
 
@@ -477,13 +479,17 @@ func (peer *peer) updatePrefixLimitConfig(c []oc.AfiSafi) error {
 func (peer *peer) handleUpdate(e *fsmMsg) ([]*table.Path, []bgp.RouteFamily, *bgp.BGPMessage) {
 	m := e.MsgData.(*bgp.BGPMessage)
 	update := m.Body.(*bgp.BGPUpdate)
-	peer.fsm.logger.Debug("received update",
-		log.Fields{
-			"Topic":       "Peer",
-			"Key":         peer.fsm.pConf.State.NeighborAddress,
-			"nlri":        update.NLRI,
-			"withdrawals": update.WithdrawnRoutes,
-			"attributes":  update.PathAttributes})
+
+	if peer.fsm.logger.GetLevel() >= log.DebugLevel {
+		peer.fsm.logger.Debug("received update",
+			log.Fields{
+				"Topic":       "Peer",
+				"Key":         peer.fsm.pConf.State.NeighborAddress,
+				"nlri":        update.NLRI,
+				"withdrawals": update.WithdrawnRoutes,
+				"attributes":  update.PathAttributes})
+	}
+
 	peer.fsm.lock.Lock()
 	peer.fsm.pConf.Timers.State.UpdateRecvTime = time.Now().Unix()
 	peer.fsm.lock.Unlock()

diff --git a/pkg/server/server.go b/pkg/server/server.go
@@ -632,11 +632,13 @@ func filterpath(peer *peer, path, old *table.Path) *table.Path {
 					return old.Clone(true)
 				}
 			}
-			peer.fsm.logger.Debug("From same AS, ignore",
-				log.Fields{
-					"Topic": "Peer",
-					"Key":   peer.ID(),
-					"Path":  path})
+			if peer.fsm.logger.GetLevel() >= log.DebugLevel {
+				peer.fsm.logger.Debug("From same AS, ignore",
+					log.Fields{
+						"Topic": "Peer",
+						"Key":   peer.ID(),
+						"Path":  path})
+			}
 			return nil
 		}
 	}