From 333a99ef069344dd5649101541b09e93fbc3e0b9 Mon Sep 17 00:00:00 2001 From: bryan Date: Mon, 16 Jun 2025 13:47:21 +0800 Subject: [PATCH] dev: log redis cost --- go.mod | 7 +--- go.sum | 4 +- logging/logging.go | 92 +++++++++++++++++++++++++++++--------------- redis/redis.go | 11 ++++++ sentinel/sentinel.go | 10 +++++ 5 files changed, 87 insertions(+), 37 deletions(-) diff --git a/go.mod b/go.mod index 630d130..e6c52ca 100644 --- a/go.mod +++ b/go.mod @@ -4,11 +4,8 @@ go 1.18 require ( github.com/gomodule/redigo v1.9.2 - qoobing.com/gomod/log v1.2.8 + qoobing.com/gomod/log v1.4.2 qoobing.com/gomod/str v1.0.5 ) -require ( - github.com/tylerb/gls v0.0.0-20150407001822-e606233f194d // indirect - github.com/tylerb/is v2.1.4+incompatible // indirect -) +require github.com/tylerb/gls v0.0.0-20150407001822-e606233f194d // indirect diff --git a/go.sum b/go.sum index 18a4b4a..0fdb08d 100644 --- a/go.sum +++ b/go.sum @@ -8,8 +8,8 @@ github.com/tylerb/gls v0.0.0-20150407001822-e606233f194d/go.mod h1:0MwyId/pXK5wk github.com/tylerb/is v2.1.4+incompatible h1:BMf2zP0kY2Ykzx2W1fDrjwKj1x1B4E0mELkpjaNy1tM= github.com/tylerb/is v2.1.4+incompatible/go.mod h1:3Bw2NWEEe8Kx7/etYqgm9ug53iNDgabnloch75jjOSc= gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= -qoobing.com/gomod/log v1.2.8 h1:J1L87VhDMHvCgPZH2H/6QuwTLiMorJL97xVx7FJyi2g= -qoobing.com/gomod/log v1.2.8/go.mod h1:/ZTN/ukAbSqRb4eMlF9LpfkVgM21xwprbd5y3tcQxpM= +qoobing.com/gomod/log v1.4.2 h1:BR6WA79nUfvYhHww/Nbzu/iM9RdCfx3G3hg1XusjIIM= +qoobing.com/gomod/log v1.4.2/go.mod h1:rNXuq0d/EWog4+8hIEVGvkusLD/pzafYBQo6w+Evv6A= qoobing.com/gomod/str v1.0.1/go.mod h1:gbhN2dba/P5gFRGVJvEI57KEJLlMHHAd6Kuuxn4GlMY= qoobing.com/gomod/str v1.0.5 h1:AXEB8k/yhepLK5jVez+WL4sWVuCFb8pWAgmo3nvt96A= qoobing.com/gomod/str v1.0.5/go.mod h1:gbhN2dba/P5gFRGVJvEI57KEJLlMHHAd6Kuuxn4GlMY= diff --git a/logging/logging.go b/logging/logging.go index 0e1ea25..0b04956 100644 --- a/logging/logging.go +++ b/logging/logging.go @@ -34,6 +34,11 @@ type Logger interface { type loggingConn struct { redis.Conn + startSend []struct { + start time.Time + commandName string + args []interface{} + } logger Logger prefix string logskip func(cmdName string) bool @@ -41,21 +46,22 @@ type loggingConn struct { // NewLoggingConn returns a logging wrapper around a connection. func NewLoggingConn(conn redis.Conn, logger Logger, prefix string) redis.Conn { - return &loggingConn{conn, logger, prefix, nil} + return &loggingConn{conn, nil, logger, prefix, nil} } // NewLoggingConnFilter returns a logging wrapper around a connection and a filter function. func NewLoggingConnFilter(conn redis.Conn, logger Logger, prefix string, skip func(cmdName string) bool) redis.Conn { - return &loggingConn{conn, logger, prefix, skip} + return &loggingConn{conn, nil, logger, prefix, skip} } func (c *loggingConn) Close() error { + c.startSend = nil err := c.Conn.Close() - c.logger.Debugf("%sClose() -> (%v)", c.prefix, err) + //c.logger.Debugf("%sClose() -> (%v)", c.prefix, err) return err } -func (c *loggingConn) printValue(buf *bytes.Buffer, v interface{}) { +func (c *loggingConn) formatPrint(buf *bytes.Buffer, v interface{}) { const chop = 128 switch v := v.(type) { case []byte: @@ -82,7 +88,7 @@ func (c *loggingConn) printValue(buf *bytes.Buffer, v interface{}) { } for _, vv := range v { buf.WriteString(sep) - c.printValue(buf, vv) + c.formatPrint(buf, vv) sep = ", " } buf.WriteString(fin) @@ -92,69 +98,95 @@ func (c *loggingConn) printValue(buf *bytes.Buffer, v interface{}) { } } -func (c *loggingConn) print(method, commandName string, args []interface{}, reply interface{}, err error) { +func (c *loggingConn) trace(method string, start time.Time, commandName string, args []interface{}, reply interface{}, err error) { + if commandName == "" { + return + } if c.logskip != nil && c.logskip(commandName) { return } - var buf bytes.Buffer - fmt.Fprintf(&buf, "%s%s(", c.prefix, method) - if method != "Receive" { - buf.WriteString(commandName) - for _, arg := range args { - buf.WriteString(", ") - c.printValue(&buf, arg) - } - } - buf.WriteString(") -> (") - if err != nil { - fmt.Fprintf(&buf, "error: %v)", err) + var cost float64 + var bufCmd bytes.Buffer + var bufReply bytes.Buffer + if !start.IsZero() { + cost = float64(time.Since(start).Microseconds()) / 1000.0 } else { - if method != "Send" { - c.printValue(&buf, reply) - } - buf.WriteString(")") + cost = 0.0 } - c.logger.Debugf("%s", buf.String()) + bufCmd.WriteString(commandName) + for _, arg := range args { + bufCmd.WriteString(", ") + c.formatPrint(&bufCmd, arg) + } + if err != nil { + fmt.Fprintf(&bufReply, "\x1b[31merror: %v\x1b[0m", err) + } else { + c.formatPrint(&bufReply, reply) + } + c.logger.Debugf("\x1b[33m[%.3fms]\x1b[0m %s%s(%s) -> (%s)", cost, c.prefix, method, bufCmd.String(), bufReply.String()) } func (c *loggingConn) Do(commandName string, args ...interface{}) (interface{}, error) { + start := time.Now() reply, err := c.Conn.Do(commandName, args...) - c.print("Do", commandName, args, reply, err) + c.trace("Do", start, commandName, args, reply, err) return reply, err } func (c *loggingConn) DoContext(ctx context.Context, commandName string, args ...interface{}) (interface{}, error) { + start := time.Now() reply, err := redis.DoContext(c.Conn, ctx, commandName, args...) - c.print("DoContext", commandName, args, reply, err) + c.trace("DoContext", start, commandName, args, reply, err) return reply, err } func (c *loggingConn) DoWithTimeout(timeout time.Duration, commandName string, args ...interface{}) (interface{}, error) { + start := time.Now() reply, err := redis.DoWithTimeout(c.Conn, timeout, commandName, args...) - c.print("DoWithTimeout", commandName, args, reply, err) + c.trace("DoWithTimeout", start, commandName, args, reply, err) return reply, err } +func (c *loggingConn) pushSendArgs(commandName string, args []interface{}) { + c.startSend = append(c.startSend, struct { + start time.Time + commandName string + args []interface{} + }{time.Now(), commandName, args}) +} + +func (c *loggingConn) popSendArgs() (time.Time, string, []interface{}) { + if len(c.startSend) > 0 { + send := c.startSend[0] + c.startSend = c.startSend[1:] + return send.start, send.commandName, send.args + } + return time.Time{}, "", nil +} + func (c *loggingConn) Send(commandName string, args ...interface{}) error { + c.pushSendArgs(commandName, args) err := c.Conn.Send(commandName, args...) - c.print("Send", commandName, args, nil, err) return err } func (c *loggingConn) Receive() (interface{}, error) { reply, err := c.Conn.Receive() - c.print("Receive", "", nil, reply, err) + start, commandName, args := c.popSendArgs() + c.trace("Receive", start, commandName, args, reply, err) return reply, err } func (c *loggingConn) ReceiveContext(ctx context.Context) (interface{}, error) { reply, err := redis.ReceiveContext(c.Conn, ctx) - c.print("ReceiveContext", "", nil, reply, err) + start, commandName, args := c.popSendArgs() + c.trace("ReceiveContext", start, commandName, args, reply, err) return reply, err } func (c *loggingConn) ReceiveWithTimeout(timeout time.Duration) (interface{}, error) { reply, err := redis.ReceiveWithTimeout(c.Conn, timeout) - c.print("ReceiveWithTimeout", "", nil, reply, err) + start, commandName, args := c.popSendArgs() + c.trace("ReceiveWithTimeout", start, commandName, args, reply, err) return reply, err } diff --git a/redis/redis.go b/redis/redis.go index 986b5ee..fd96489 100644 --- a/redis/redis.go +++ b/redis/redis.go @@ -2,6 +2,7 @@ package redis import ( "fmt" + "strings" "time" "qoobing.com/gomod/log" @@ -54,6 +55,16 @@ func NewPool(cfg Config) *redis.Pool { logPrefix = "redis " logLogger = log.New("redis") ) + logLogger.SetCalldepth(3) + logLogger.SetSkipfunc(func(filename string) bool { + if strings.Contains(filename, "/github.com/gomodule/redigo") { + return true + } + if strings.Contains(filename, "/qoobing.com/gomod/") { + return true + } + return false + }) return &redis.Pool{ MaxIdle: *cfg.MaxIdle, MaxActive: *cfg.MaxActive, diff --git a/sentinel/sentinel.go b/sentinel/sentinel.go index 410d75c..a44451c 100644 --- a/sentinel/sentinel.go +++ b/sentinel/sentinel.go @@ -126,6 +126,16 @@ func NewPool(cfg Config) *redis.Pool { logPrefix = "redis " logLogger = log.New("redis") ) + logLogger.SetCalldepth(3) + logLogger.SetSkipfunc(func(filename string) bool { + if strings.Contains(filename, "/github.com/gomodule/redigo") { + return true + } + if strings.Contains(filename, "/qoobing.com/gomod/") { + return true + } + return false + }) return &redis.Pool{ MaxIdle: *cfg.MaxIdle, MaxActive: *cfg.MaxActive,