From 5ffe7cd1533fe3412687d55e6a7cec628db26555 Mon Sep 17 00:00:00 2001 From: Steven Allen Date: Mon, 20 Apr 2020 14:53:40 -0700 Subject: [PATCH] chore: optimize debug logging a bit These are all critical paths so we should try to do as little work as possible. --- dht.go | 10 +++++-- dht_net.go | 76 +++++++++++++++++++++++++++++------------------------- go.mod | 1 + go.sum | 3 --- 4 files changed, 50 insertions(+), 40 deletions(-) diff --git a/dht.go b/dht.go index 7bfb027b9..45ed04a83 100644 --- a/dht.go +++ b/dht.go @@ -15,6 +15,7 @@ import ( "github.com/libp2p/go-libp2p-core/peerstore" "github.com/libp2p/go-libp2p-core/protocol" "github.com/libp2p/go-libp2p-core/routing" + "go.uber.org/zap" "go.opencensus.io/tag" @@ -34,7 +35,10 @@ import ( "github.com/multiformats/go-multihash" ) -var logger = logging.Logger("dht") +var ( + logger = logging.Logger("dht") + baseLogger = logger.Desugar() +) // BaseConnMgrScore is the base of the score set on the connection manager "kbucket" tag. // It is added with the common prefix length between two peer IDs. @@ -464,7 +468,9 @@ func (dht *IpfsDHT) putLocal(key string, rec *recpb.Record) error { // If we connect to a peer we already have in the RT but do not exchange a query (rare) // Do Nothing. func (dht *IpfsDHT) peerFound(ctx context.Context, p peer.ID, queryPeer bool) { - logger.Debugw("peer found", "peer", p) + if c := baseLogger.Check(zap.DebugLevel, "peer found"); c != nil { + c.Write(zap.String("peer", p.String())) + } b, err := dht.validRTPeer(p) if err != nil { logger.Errorw("failed to validate if peer is a DHT peer", "peer", p, "error", err) diff --git a/dht_net.go b/dht_net.go index 9bb1aed6b..912d287c1 100644 --- a/dht_net.go +++ b/dht_net.go @@ -20,6 +20,7 @@ import ( "github.com/libp2p/go-msgio" "go.opencensus.io/stats" "go.opencensus.io/tag" + "go.uber.org/zap" ) var dhtReadMessageTimeout = 10 * time.Second @@ -97,8 +98,9 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool { } // This string test is necessary because there isn't a single stream reset error // instance in use. - if err.Error() != "stream reset" { - logger.Debugf("error reading message: %#v", err) + if c := baseLogger.Check(zap.DebugLevel, "error reading message"); c != nil && err.Error() != "stream reset" { + c.Write(zap.String("from", mPeer.String()), + zap.Error(err)) } if msgLen > 0 { _ = stats.RecordWithTags(ctx, @@ -113,7 +115,10 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool { err = req.Unmarshal(msgbytes) r.ReleaseMsg(msgbytes) if err != nil { - logger.Debugf("error unmarshaling message: %#v", err) + if c := baseLogger.Check(zap.DebugLevel, "error unmarshaling message"); c != nil { + c.Write(zap.String("from", mPeer.String()), + zap.Error(err)) + } _ = stats.RecordWithTags(ctx, []tag.Mutator{tag.Upsert(metrics.KeyMessageType, "UNKNOWN")}, metrics.ReceivedMessages.M(1), @@ -138,37 +143,39 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool { handler := dht.handlerForMsgType(req.GetType()) if handler == nil { stats.Record(ctx, metrics.ReceivedMessageErrors.M(1)) - logger.Warnw("can't handle received message", "from", mPeer, "type", req.GetType()) + if c := baseLogger.Check(zap.DebugLevel, "can't handle received message"); c != nil { + c.Write(zap.String("from", mPeer.String()), + zap.Int32("type", int32(req.GetType()))) + } return false } // a peer has queried us, let's add it to RT dht.peerFound(dht.ctx, mPeer, true) - logger.Debugw("handling message", - "type", req.GetType(), - "key", req.GetKey(), - "from", mPeer, - ) + if c := baseLogger.Check(zap.DebugLevel, "handling message"); c != nil { + c.Write(zap.String("from", mPeer.String()), + zap.Int32("type", int32(req.GetType())), + zap.Binary("key", req.GetKey())) + } resp, err := handler(ctx, mPeer, &req) if err != nil { stats.Record(ctx, metrics.ReceivedMessageErrors.M(1)) - logger.Debugw( - "error handling message", - "type", req.GetType(), - "key", req.GetKey(), - "from", mPeer, - "error", err) + if c := baseLogger.Check(zap.DebugLevel, "error handling message"); c != nil { + c.Write(zap.String("from", mPeer.String()), + zap.Int32("type", int32(req.GetType())), + zap.Binary("key", req.GetKey()), + zap.Error(err)) + } return false } - logger.Debugw( - "handled message", - "type", req.GetType(), - "key", req.GetKey(), - "from", mPeer, - "time", time.Since(startTime), - ) + if c := baseLogger.Check(zap.DebugLevel, "handled message"); c != nil { + c.Write(zap.String("from", mPeer.String()), + zap.Int32("type", int32(req.GetType())), + zap.Binary("key", req.GetKey()), + zap.Duration("time", time.Since(startTime))) + } if resp == nil { continue @@ -178,24 +185,23 @@ func (dht *IpfsDHT) handleNewMessage(s network.Stream) bool { err = writeMsg(s, resp) if err != nil { stats.Record(ctx, metrics.ReceivedMessageErrors.M(1)) - logger.Debugw( - "error writing response", - "type", req.GetType(), - "key", req.GetKey(), - "from", mPeer, - "error", err) + if c := baseLogger.Check(zap.DebugLevel, "error writing response"); c != nil { + c.Write(zap.String("from", mPeer.String()), + zap.Int32("type", int32(req.GetType())), + zap.Binary("key", req.GetKey()), + zap.Error(err)) + } return false } elapsedTime := time.Since(startTime) - logger.Debugw( - "responded to message", - "type", req.GetType(), - "key", req.GetKey(), - "from", mPeer, - "time", elapsedTime, - ) + if c := baseLogger.Check(zap.DebugLevel, "responded to message"); c != nil { + c.Write(zap.String("from", mPeer.String()), + zap.Int32("type", int32(req.GetType())), + zap.Binary("key", req.GetKey()), + zap.Duration("time", elapsedTime)) + } latencyMillis := float64(elapsedTime) / float64(time.Millisecond) stats.Record(ctx, metrics.InboundRequestLatency.M(latencyMillis)) diff --git a/go.mod b/go.mod index f007163ab..6a6385252 100644 --- a/go.mod +++ b/go.mod @@ -34,4 +34,5 @@ require ( github.com/stretchr/testify v1.5.1 github.com/whyrusleeping/go-keyspace v0.0.0-20160322163242-5b898ac5add1 go.opencensus.io v0.22.3 + go.uber.org/zap v1.10.0 ) diff --git a/go.sum b/go.sum index 04e044360..0941fb042 100644 --- a/go.sum +++ b/go.sum @@ -83,7 +83,6 @@ github.com/gxed/hashland/murmur3 v0.0.1 h1:SheiaIt0sda5K+8FLz952/1iWS9zrnKsEJaOJ github.com/gxed/hashland/murmur3 v0.0.1/go.mod h1:KjXop02n4/ckmZSnY2+HKcLud/tcmvhST0bie/0lS48= github.com/hashicorp/errwrap v1.0.0 h1:hLrqtEDnRye3+sgx6z4qVLNuviH3MR5aQ0ykNJa/UYA= github.com/hashicorp/errwrap v1.0.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4= -github.com/hashicorp/go-multierror v1.0.0/go.mod h1:dHtQlpGsu+cZNNAkkCN/P3hoUDHhCYQXV3UM06sGGrk= github.com/hashicorp/go-multierror v1.1.0 h1:B9UzwGQJehnUY1yNrnwREHc3fGbC2xefo8g4TbElacI= github.com/hashicorp/go-multierror v1.1.0/go.mod h1:spPvp8C1qA32ftKqdAHm4hHTbPw+vmowP0z+KUhOZdA= github.com/hashicorp/golang-lru v0.5.0/go.mod h1:/m3WP610KZHVQ1SGc6re/UDhFvYD7pJ4Ao+sR/qLZy8= @@ -279,8 +278,6 @@ github.com/libp2p/go-libp2p-pnet v0.2.0 h1:J6htxttBipJujEjz1y0a5+eYoiPcFHhSYHH6n github.com/libp2p/go-libp2p-pnet v0.2.0/go.mod h1:Qqvq6JH/oMZGwqs3N1Fqhv8NVhrdYcO0BW4wssv21LA= github.com/libp2p/go-libp2p-record v0.1.2 h1:M50VKzWnmUrk/M5/Dz99qO9Xh4vs8ijsK+7HkJvRP+0= github.com/libp2p/go-libp2p-record v0.1.2/go.mod h1:pal0eNcT5nqZaTV7UGhqeGqxFgGdsU/9W//C8dqjQDk= -github.com/libp2p/go-libp2p-routing-helpers v0.2.0 h1:+QKTsx2Bg0q3oueQ9CopTwKN5NsnF+qEC+sbkSVXnsU= -github.com/libp2p/go-libp2p-routing-helpers v0.2.0/go.mod h1:Db+7LRSPImkV9fOKsNWVW5IXyy9XDse92lUtO3O+jlo= github.com/libp2p/go-libp2p-routing-helpers v0.2.1 h1:tV5fxxkl1cEEFXIv9yl5OGbLjEwngtq1qf5G/beLRvQ= github.com/libp2p/go-libp2p-routing-helpers v0.2.1/go.mod h1:rTLUHlGDZbXHANJAWP2xW7ruPNJLj41/GnCBiR+qgjU= github.com/libp2p/go-libp2p-secio v0.1.0/go.mod h1:tMJo2w7h3+wN4pgU2LSYeiKPrfqBgkOsdiKK77hE7c8=