dev: log redis cost

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 (
+require github.com/tylerb/gls v0.0.0-20150407001822-e606233f194d // indirect
-	github.com/tylerb/gls v0.0.0-20150407001822-e606233f194d // indirect
-	github.com/tylerb/is v2.1.4+incompatible // indirect
-)

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.4.2 h1:BR6WA79nUfvYhHww/Nbzu/iM9RdCfx3G3hg1XusjIIM=
-qoobing.com/gomod/log v1.2.8/go.mod h1:/ZTN/ukAbSqRb4eMlF9LpfkVgM21xwprbd5y3tcQxpM=
+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=

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
+	var cost float64
-	fmt.Fprintf(&buf, "%s%s(", c.prefix, method)
+	var bufCmd bytes.Buffer
-	if method != "Receive" {
+	var bufReply bytes.Buffer
-		buf.WriteString(commandName)
+	if !start.IsZero() {
-		for _, arg := range args {
+		cost = float64(time.Since(start).Microseconds()) / 1000.0
-			buf.WriteString(", ")
-			c.printValue(&buf, arg)
-		}
-	}
-	buf.WriteString(") -> (")
-	if err != nil {
-		fmt.Fprintf(&buf, "error: %v)", err)
 	} else {
-		if method != "Send" {
+		cost = 0.0
-			c.printValue(&buf, reply)
-		}
-		buf.WriteString(")")
 	}
-	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
 }

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,

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,