From 6a4646509234a73602a0f766a09cf76b66827086 Mon Sep 17 00:00:00 2001 From: Lucas Clemente Date: Sat, 4 Jun 2016 15:13:46 +0200 Subject: [PATCH] reduce calls to Debugf when not debugging to reduce slice allocs ref #129 --- ackhandler/sent_packet_handler.go | 4 ++- frames/log.go | 19 ++++++++++++ frames/log_test.go | 49 +++++++++++++++++++++++++++++++ session.go | 24 +++++---------- utils/log.go | 5 ++++ 5 files changed, 84 insertions(+), 17 deletions(-) create mode 100644 frames/log.go create mode 100644 frames/log_test.go diff --git a/ackhandler/sent_packet_handler.go b/ackhandler/sent_packet_handler.go index 98a5f5d0..19db7155 100644 --- a/ackhandler/sent_packet_handler.go +++ b/ackhandler/sent_packet_handler.go @@ -198,7 +198,9 @@ func (h *sentPacketHandler) ReceivedAck(ackFrame *frames.AckFrame) error { timeDelta := time.Now().Sub(h.packetHistory[h.LargestObserved].sendTime) // TODO: Don't always update RTT h.rttStats.UpdateRTT(timeDelta, ackFrame.DelayTime, time.Now()) - utils.Debugf("\tEstimated RTT: %dms", h.rttStats.SmoothedRTT()/time.Millisecond) + if utils.Debug() { + utils.Debugf("\tEstimated RTT: %dms", h.rttStats.SmoothedRTT()/time.Millisecond) + } var ackedPackets congestion.PacketVector var lostPackets congestion.PacketVector diff --git a/frames/log.go b/frames/log.go new file mode 100644 index 00000000..f4e9074f --- /dev/null +++ b/frames/log.go @@ -0,0 +1,19 @@ +package frames + +import "github.com/lucas-clemente/quic-go/utils" + +// LogFrame logs a frame, either sent or received +func LogFrame(frame Frame, sent bool) { + if !utils.Debug() { + return + } + dir := "<-" + if sent { + dir = "->" + } + if sf, ok := frame.(*StreamFrame); ok { + utils.Debugf("\t%s &frames.StreamFrame{StreamID: %d, FinBit: %t, Offset: 0x%x, Data length: 0x%x, Offset + Data length: 0x%x}", dir, sf.StreamID, sf.FinBit, sf.Offset, sf.DataLen(), sf.Offset+sf.DataLen()) + } else { + utils.Debugf("\t%s %#v", dir, frame) + } +} diff --git a/frames/log_test.go b/frames/log_test.go new file mode 100644 index 00000000..c88168a5 --- /dev/null +++ b/frames/log_test.go @@ -0,0 +1,49 @@ +package frames + +import ( + "bytes" + "os" + + "github.com/lucas-clemente/quic-go/utils" + + . "github.com/onsi/ginkgo" + . "github.com/onsi/gomega" +) + +var _ = Describe("Frame logging", func() { + var ( + buf bytes.Buffer + ) + + BeforeEach(func() { + buf.Reset() + utils.SetLogLevel(utils.LogLevelDebug) + utils.SetLogWriter(&buf) + }) + + AfterSuite(func() { + utils.SetLogLevel(utils.LogLevelNothing) + utils.SetLogWriter(os.Stdout) + }) + + It("doesn't log when debug is disabled", func() { + utils.SetLogLevel(utils.LogLevelInfo) + LogFrame(&RstStreamFrame{}, true) + Expect(buf.Len()).To(BeZero()) + }) + + It("logs sent frames", func() { + LogFrame(&RstStreamFrame{}, true) + Expect(string(buf.Bytes())).To(Equal("\t-> &frames.RstStreamFrame{StreamID:0x0, ByteOffset:0x0, ErrorCode:0x0}\n")) + }) + + It("logs received frames", func() { + LogFrame(&RstStreamFrame{}, false) + Expect(string(buf.Bytes())).To(Equal("\t<- &frames.RstStreamFrame{StreamID:0x0, ByteOffset:0x0, ErrorCode:0x0}\n")) + }) + + It("logs stream frames", func() { + LogFrame(&StreamFrame{}, false) + Expect(string(buf.Bytes())).To(Equal("\t<- &frames.StreamFrame{StreamID: 0, FinBit: false, Offset: 0x0, Data length: 0x0, Offset + Data length: 0x0}\n")) + }) +}) diff --git a/session.go b/session.go index 001e083d..b843558c 100644 --- a/session.go +++ b/session.go @@ -226,7 +226,9 @@ func (s *Session) handlePacketImpl(remoteAddr interface{}, hdr *publicHeader, da hdr.PacketNumber, ) s.lastRcvdPacketNumber = hdr.PacketNumber - utils.Debugf("<- Reading packet 0x%x (%d bytes) for connection %x", hdr.PacketNumber, r.Size(), hdr.ConnectionID) + if utils.Debug() { + utils.Debugf("<- Reading packet 0x%x (%d bytes) for connection %x", hdr.PacketNumber, r.Size(), hdr.ConnectionID) + } // TODO: Only do this after authenticating s.conn.setCurrentRemoteAddr(remoteAddr) @@ -240,32 +242,25 @@ func (s *Session) handlePacketImpl(remoteAddr interface{}, hdr *publicHeader, da for _, ff := range packet.frames { var err error + frames.LogFrame(ff, false) switch frame := ff.(type) { case *frames.StreamFrame: - utils.Debugf("\t<- &frames.StreamFrame{StreamID: %d, FinBit: %t, Offset: 0x%x, Data length: 0x%x, Offset + Data length: 0x%x}", frame.StreamID, frame.FinBit, frame.Offset, frame.DataLen(), frame.Offset+frame.DataLen()) err = s.handleStreamFrame(frame) // TODO: send RstStreamFrame case *frames.AckFrame: err = s.handleAckFrame(frame) case *frames.ConnectionCloseFrame: - utils.Debugf("\t<- %#v", frame) s.closeImpl(qerr.Error(frame.ErrorCode, frame.ReasonPhrase), true) case *frames.GoawayFrame: - utils.Debugf("\t<- %#v", frame) err = errors.New("unimplemented: handling GOAWAY frames") case *frames.StopWaitingFrame: - utils.Debugf("\t<- %#v", frame) err = s.receivedPacketHandler.ReceivedStopWaiting(frame) case *frames.RstStreamFrame: err = s.handleRstStreamFrame(frame) - utils.Debugf("\t<- %#v", frame) case *frames.WindowUpdateFrame: - utils.Debugf("\t<- %#v", frame) err = s.handleWindowUpdateFrame(frame) case *frames.BlockedFrame: - utils.Infof("BLOCKED frame received for connection %x stream %d", s.connectionID, frame.StreamID) case *frames.PingFrame: - utils.Debugf("\t<- %#v", frame) default: return errors.New("Session BUG: unexpected frame type") } @@ -370,7 +365,6 @@ func (s *Session) handleAckFrame(frame *frames.AckFrame) error { if err := s.sentPacketHandler.ReceivedAck(frame); err != nil { return err } - utils.Debugf("\t<- %#v", frame) return nil } @@ -563,12 +557,10 @@ func (s *Session) logPacket(packet *packedPacket) { // We don't need to allocate the slices for calling the format functions return } - utils.Debugf("-> Sending packet 0x%x (%d bytes)", packet.number, len(packet.raw)) - for _, frame := range packet.frames { - if streamFrame, isStreamFrame := frame.(*frames.StreamFrame); isStreamFrame { - utils.Debugf("\t-> &frames.StreamFrame{StreamID: %d, FinBit: %t, Offset: 0x%x, Data length: 0x%x, Offset + Data length: 0x%x}", streamFrame.StreamID, streamFrame.FinBit, streamFrame.Offset, streamFrame.DataLen(), streamFrame.Offset+streamFrame.DataLen()) - } else { - utils.Debugf("\t-> %#v", frame) + if utils.Debug() { + utils.Debugf("-> Sending packet 0x%x (%d bytes)", packet.number, len(packet.raw)) + for _, frame := range packet.frames { + frames.LogFrame(frame, true) } } } diff --git a/utils/log.go b/utils/log.go index c82f6f47..bb0f2551 100644 --- a/utils/log.go +++ b/utils/log.go @@ -27,6 +27,11 @@ var logLevel = LogLevelNothing var mutex sync.Mutex +// SetLogWriter sets the log writer. +func SetLogWriter(w io.Writer) { + out = w +} + // SetLogLevel sets the log level func SetLogLevel(level LogLevel) { logLevel = level