From 003745affece75e8de64fe50395008e7a7137c3f Mon Sep 17 00:00:00 2001 From: Dawn Minion Date: Tue, 27 Feb 2024 12:58:03 -0800 Subject: [PATCH] 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. --- internal/pkg/table/destination.go | 22 +++++++++------- pkg/server/fsm.go | 44 ++++++++++++++++++------------- pkg/server/peer.go | 30 ++++++++++++--------- pkg/server/server.go | 12 +++++---- 4 files changed, 63 insertions(+), 45 deletions(-) diff --git a/internal/pkg/table/destination.go b/internal/pkg/table/destination.go index c75332848..843df13e3 100644 --- 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 index 0730daaa6..3aee70b28 100644 --- 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 index 804b78500..91e6decff 100644 --- 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 index 5f9fb6399..a962a1e20 100644 --- 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 } }