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 (
-	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

go.sum

@@ -0,0 +1,15 @@
+github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
+github.com/gomodule/redigo v1.9.2 h1:HrutZBLhSIU8abiSfW8pj8mPhOyMYjZT/wcA4/L9L9s=
+github.com/gomodule/redigo v1.9.2/go.mod h1:KsU3hiK/Ay8U42qpaJk+kuNa3C+spxapWpM+ywhcgtw=
+github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
+github.com/stretchr/testify v1.8.4 h1:CcVxjf3Q8PM0mHUKJCdn+eZZtm5yQwehR5yeSVQQcUk=
+github.com/tylerb/gls v0.0.0-20150407001822-e606233f194d h1:yYYPFFlbqxF5mrj5sEfETtM/Ssz2LTy0/VKlDdXYctc=
+github.com/tylerb/gls v0.0.0-20150407001822-e606233f194d/go.mod h1:0MwyId/pXK5wkYYEXe7NnVknX+aNBuF73fLV3U0reU8=
+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.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=

logging/logging.go

@@ -18,49 +18,50 @@ import (
 	"bytes"
 	"context"
 	"fmt"
-	"log"
 	"time"
 
 	"github.com/gomodule/redigo/redis"
 )
 
 var (
-	_            redis.ConnWithTimeout = (*loggingConn)(nil)
-	logCallDepth                       = 3
+	_ redis.ConnWithTimeout = (*loggingConn)(nil)
 )
 
-// NewLoggingConn returns a logging wrapper around a connection.
-func NewLoggingConn(conn redis.Conn, logger *log.Logger, prefix string) redis.Conn {
-	if prefix != "" {
-		prefix = prefix + "."
-	}
-	return &loggingConn{conn, logger, prefix, nil}
-}
-
-// NewLoggingConnFilter returns a logging wrapper around a connection and a filter function.
-func NewLoggingConnFilter(conn redis.Conn, logger *log.Logger, prefix string, skip func(cmdName string) bool) redis.Conn {
-	if prefix != "" {
-		prefix = prefix + "."
-	}
-	return &loggingConn{conn, logger, prefix, skip}
+type Logger interface {
+	Debugf(format string, v ...interface{})
+	Errorf(format string, v ...interface{})
 }
 
 type loggingConn struct {
 	redis.Conn
-	logger *log.Logger
-	prefix string
-	skip   func(cmdName string) bool
+	startSend []struct {
+		start       time.Time
+		commandName string
+		args        []interface{}
+	}
+	logger  Logger
+	prefix  string
+	logskip func(cmdName string) bool
+}
+
+// NewLoggingConn returns a logging wrapper around a connection.
+func NewLoggingConn(conn redis.Conn, logger Logger, prefix string) redis.Conn {
+	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, nil, logger, prefix, skip}
 }
 
 func (c *loggingConn) Close() error {
+	c.startSend = nil
 	err := c.Conn.Close()
-	var buf bytes.Buffer
-	fmt.Fprintf(&buf, "%sClose() -> (%v)", c.prefix, err)
-	c.logger.Output(logCallDepth, buf.String()) // nolint: errcheck
+	//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:
@@ -87,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)
@@ -97,66 +98,95 @@ func (c *loggingConn) printValue(buf *bytes.Buffer, v interface{}) {
 	}
 }
 
-func (c *loggingConn) print(method, commandName string, args []interface{}, reply interface{}, err error) {
-	if c.skip != nil && c.skip(commandName) {
+func (c *loggingConn) trace(method string, start time.Time, commandName string, args []interface{}, reply interface{}, err error) {
+	if 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)
-		}
+	if c.logskip != nil && c.logskip(commandName) {
+		return
 	}
-	buf.WriteString(") -> (")
-	if method != "Send" {
-		c.printValue(&buf, reply)
-		buf.WriteString(", ")
+	var cost float64
+	var bufCmd bytes.Buffer
+	var bufReply bytes.Buffer
+	if !start.IsZero() {
+		cost = float64(time.Since(start).Microseconds()) / 1000.0
+	} else {
+		cost = 0.0
 	}
-	fmt.Fprintf(&buf, "%v)", err)
-	c.logger.Output(logCallDepth+1, buf.String()) // nolint: errcheck
+	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.go

@@ -1,11 +1,39 @@
 package redis
 
 import (
+	redigo "github.com/gomodule/redigo/redis"
 	"qoobing.com/gomod/redis/redis"
 	"qoobing.com/gomod/redis/sentinel"
 )
 
-type Config = sentinel.Config
+type (
+	Conn   = redigo.Conn
+	Pool   = redigo.Pool
+	Config = sentinel.Config
+)
 
-var NewPool = redis.NewPool
-var NewSentinelPool = sentinel.NewPool
+var (
+	NewRedisPool     = redis.NewPool
+	NewSentinelPool  = sentinel.NewPool
+	Int              = redigo.Int
+	Int64            = redigo.Int64
+	Uint64           = redigo.Uint64
+	Float64          = redigo.Float64
+	String           = redigo.String
+	Strings          = redigo.Strings
+	Bool             = redigo.Bool
+	Ints             = redigo.Ints
+	Float64s         = redigo.Float64s
+	Values           = redigo.Values
+	ErrNil           = redigo.ErrNil
+	ErrPoolExhausted = redigo.ErrPoolExhausted
+)
+
+func NewPool(cfg Config) *redigo.Pool {
+	if cfg.Master != "" {
+		return NewRedisPool(cfg)
+	} else if cfg.MasterName != "" {
+		return NewSentinelPool(cfg)
+	}
+	panic("invalid config: Master & MasterName are both empty")
+}

redis/redis.go

@@ -2,10 +2,11 @@ package redis
 
 import (
 	"fmt"
-	"log"
-	"os"
+	"strings"
 	"time"
 
+	"qoobing.com/gomod/log"
+
 	"github.com/gomodule/redigo/redis"
 	"qoobing.com/gomod/redis/logging"
 	"qoobing.com/gomod/redis/sentinel"
@@ -51,12 +52,19 @@ func NewPool(cfg Config) *redis.Pool {
 	}
 
 	var (
-		logPrefix    = "redis"
-		logStdPrefix = "DBUG "
-		logStdWriter = os.Stdout
-		logStdFlags  = log.Ldate | log.Lmicroseconds | log.Lshortfile
-		logStdLogger = log.New(logStdWriter, logStdPrefix, logStdFlags)
+		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,
@@ -65,6 +73,7 @@ func NewPool(cfg Config) *redis.Pool {
 		Dial: func() (redis.Conn, error) {
 			c, err := redis.Dial("tcp", masterAddr)
 			if err != nil {
+				logLogger.Errorf("connect [%s] error: %s", masterAddr, err)
 				return nil, err
 			}
 
@@ -76,21 +85,15 @@ func NewPool(cfg Config) *redis.Pool {
 			}
 
 			if err != nil {
+				logLogger.Errorf("auth [%s] error: %s", masterAddr, err)
 				return nil, fmt.Errorf("redis master AUTH failed: <%s>", err.Error())
 			} else if okstr != "OK" {
+				logLogger.Errorf("auth [%s] not return ok but '%s'", masterAddr, okstr)
 				return nil, fmt.Errorf("redis master AUTH failed: <%s>", okstr)
 			}
 
-			//// if !TestRole(c, "master") {
-			//// 	c.Close()
-			//// 	err = fmt.Errorf(
-			//// 		"master(%s) got by name '%s' is not redis master",
-			//// 		masterAddr, masterName)
-			//// 	return nil, err
-			//// }
-
 			if cfg.Debug {
-				c = logging.NewLoggingConn(c, logStdLogger, logPrefix)
+				c = logging.NewLoggingConn(c, logLogger, logPrefix)
 			}
 			return c, nil
 		},

sentinel/sentinel.go

@@ -3,14 +3,13 @@ package sentinel
 import (
 	"errors"
 	"fmt"
-	"log"
 	"net"
-	"os"
 	"strings"
 	"sync"
 	"time"
 
 	"github.com/gomodule/redigo/redis"
+	"qoobing.com/gomod/log"
 	"qoobing.com/gomod/redis/logging"
 )
 
@@ -29,6 +28,15 @@ type Config struct {
 	IdleTimeout      *int   `toml:"idle_timeout"`      //空闲超时时间
 }
 
+func (cfg Config) GetSecDsn() (dsn string) {
+	if cfg.Master != "" {
+		dsn += fmt.Sprintf("mode=redis address=%s", cfg.Master)
+	} else if cfg.MasterName != "" {
+		dsn += fmt.Sprintf("mode=sentinel address=%s mastername=%s", cfg.Sentinels, cfg.MasterName)
+	}
+	return dsn
+}
+
 type Sentinel struct {
 	// Addrs is a slice with known Sentinel addresses.
 	Addrs []string
@@ -114,14 +122,20 @@ func NewPool(cfg Config) *redis.Pool {
 	} else if *cfg.MaxActive < 0 {
 		*cfg.MaxActive = 100
 	}
-
 	var (
-		logPrefix    = "redis"
-		logStdPrefix = "DBUG "
-		logStdWriter = os.Stdout
-		logStdFlags  = log.Ldate | log.Lmicroseconds | log.Lshortfile
-		logStdLogger = log.New(logStdWriter, logStdPrefix, logStdFlags)
+		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,
@@ -130,11 +144,13 @@ func NewPool(cfg Config) *redis.Pool {
 		Dial: func() (redis.Conn, error) {
 			masterAddr, err := sntnl.MasterAddr()
 			if err != nil {
+				logLogger.Errorf("get master from sentinel error: %s", err)
 				return nil, err
 			}
 
 			c, err := redis.Dial("tcp", masterAddr)
 			if err != nil {
+				logLogger.Errorf("connect [%s] error: %s", masterAddr, err)
 				return nil, err
 			}
 
@@ -146,8 +162,10 @@ func NewPool(cfg Config) *redis.Pool {
 			}
 
 			if err != nil {
+				logLogger.Errorf("auth [%s] error: %s", masterAddr, err)
 				return nil, fmt.Errorf("redis master AUTH failed: <%s>", err.Error())
 			} else if okstr != "OK" {
+				logLogger.Errorf("auth [%s] not return ok but '%s'", masterAddr, okstr)
 				return nil, fmt.Errorf("redis master AUTH failed: <%s>", okstr)
 			}
 
@@ -156,11 +174,12 @@ func NewPool(cfg Config) *redis.Pool {
 				err = fmt.Errorf(
 					"master(%s) got by name '%s' is not redis master",
 					masterAddr, masterName)
+				logLogger.Errorf("%s", err.Error())
 				return nil, err
 			}
 
 			if cfg.Debug {
-				c = logging.NewLoggingConn(c, logStdLogger, logPrefix)
+				c = logging.NewLoggingConn(c, logLogger, logPrefix)
 			}
 			return c, nil
 		},