go-zero日志打印

go-zero 日志打印，错误使用导致内存陡增，服务运行缓慢，最直接的表现就是日志打印非常慢。

背景：

据客户反应，存证服务上线初始阶段，链上事件消费正常，在运行了一段时间后，事件消费缓慢，无法追上航贸链最新高度。最直接的表现就是日志打印非常慢，每条日志打印间隔都在 100ms ～ 300ms，更有甚者能达到 300ms 以上。

一、定位问题

在我们的开发环境能够复现上述现象，在事件订阅前两个小时，日志打印很快，之后日志打印越来越慢。后开启 pprof 分析 CPU 和内存使用情况。

• CPU 时间都消耗在了 logx.output 和 runtime.scanobject 上。
• 内存消耗在了 logx.WithFileds 上。

图示：dtdh CPU 采样

图示：dtdh 内存采样展示

从上述图上可以很清楚的看到 dtdh 服务运行缓慢的直接原因：频繁的对象创建和 GC 扫描，以及大内存拷贝综合导致我们的存证服务越来越慢。 后定位到出错行代码，发现源头是我们在一个全局对象 dtdhEventHandler，疯狂的往其 logger 对象添加 fileds。

func (h *DtdhEventHandler) handleEvent(e *common.ContractEventInfo) {
    logx.Infof("[event] [%s] DtdhEventHandler event: %s", e.GetTxId(), util.ToJSON(e))
    eventID := logic.GetEventID(e.GetTxId(), e.GetTopic(), e.GetEventIndex())
    logFields := map[string]interface{}{
       "txid":        e.GetTxId(),
       "blockHeight": e.BlockHeight,
       "event":       e.Topic,
       "contract":    h.contractName(),
       "eventID":     eventID,
    }
    h.logger = h.logger.WithFields(util.ConvertToLogxFields(logFields)...) // 错误使用了 go-zero 的 WithFields

	....

}

发现 go-zero 在 v1.6.5 版本中，WithFields 函数没有 new 新的 fields ，而是在原先内存上进行 append，不过这在 v1.8.x 版本已经修复。

二、问题解决

结合我们的业务对打印方式进行调整，针对这种全局对象 dtdhEventHandler ，不再使用其自带 logger 对象打印日志。有两种方式：

• 第一种：打印日志时，重新构造一个 logger 对象，使用这个新 logger 打印日志。

  logger := logx.WithContext(context.Background()).WithFields(util.ConvertToLogxFields(logFields)...)
  logger.Infof("DtdhEventHandler event handle success")
  ...

• 第二种：使用 logx.Infof() 进行打印，可以封装一个函数，在每次打印时将 fields 放入 logx.Infof() 里。

  logx.Infof("DtdhEventHandler event handle, fields: %v", util.ConvertToLogxFields(logFields))
  ...

三、最佳打印

上述两种打印都不是很友好，特别是第二种，在每次打印时需要将 fileds 动态的传入。所以我们采用第一种方式，那么我们需要什么时候，构造 logger？上下文获取 logger 方不方便？

• 在每个对象调用时，添加 fields 字段，构造新的 logger 实例，避免并发问题。
• 使用context.Context作为日志上下文的载体： 利用 context 携带 logger ，下游函数取出 logger 进行打印即可。

所以我们需要封装日志操作，提供一致的 API。

使用 go-zero

xlog.go 文件

package xlog

import (
    "context"

    "github.com/zeromicro/go-zero/core/logx"
)

type contextKey string

const (
    loggerKey contextKey = "logger"
)

// GetLogger extract logger from context and with fields or// create a new logger from logx with fields.
func GetLogger(ctx context.Context, fields ...logx.LogField) logx.Logger {
    logger, ok := ctx.Value(loggerKey).(logx.Logger)
    if !ok {
       return logx.WithContext(ctx).WithFields(fields...)
    }
    return logger.WithFields(fields...)
}

// WithContext set logger to context.func WithContext(ctx context.Context, logger logx.Logger) context.Context {
    return context.WithValue(ctx, loggerKey, logger)
}

xlog_test.go 文件

func TestGetLogger(t *testing.T) {
    logFields := map[string]interface{}{
       "txid":        "e.GetTxId()",
       "blockHeight": "e.BlockHeight",
       "event":       "e.Topic",
       "contract":    "h.contractName",
       "eventID":     "eventID",
    }
    logger := GetLogger(context.Background(), util.ConvertToLogxFields(logFields)...)
    logger.Infof("test")
    ctx := WithContext(context.Background(), logger)
    callBack(ctx)
    logger.Infof("end")
}

func callBack(ctx context.Context) {
    logger := GetLogger(ctx)
    logger.Info("callBack")
}

使用规范：

不推荐写法：

h.logger = h.logger.WithFields(...)
h.looger.Infof("")

这种在 h 是一个全局变量时，存在两个问题。

1. 内存持续增长问题。
2. 并发时，会导致打印出来的 fields 不准确。

推荐写法：

需要携带 fields 情况： 推荐用 xlog 里的写法：

1. 用到日志打印的地方，先通过 xlog.GetLogger(ctx) 获取 logger。
2. 需要上下文传递时，通过 xlog.WithContext(ctx) 进行传递。

不需要携带 fields ： 推荐使用 logx.Infof() 这种方式进行打印。

针对 http 请求：

可以通过中间件自动注入基础上下文信息。

四、使用 go slog 进行打印。

如果 go.mod 中版本在 1.21.1 以上，推荐使用 slog 进行日志打印。slog  作为官方标准，正逐步成为 Go 生态的日志事实标准，选择  slog  可减少技术债，更适合长期维护的项目。

multiFileHandler.go

package multiFileHandler

import (
    "context"
    "log/slog"
    "os"
    "path/filepath"
    "sync"
    "gopkg.in/natefinch/lumberjack.v2"
)

type contextKey string

const (
    loggerKey contextKey = "logger"
)

type MultiFileHandler struct {
    basePath string
    handlers map[slog.Level]slog.Handler

    mux sync.RWMutex
}

func NewMultiFileHandler(basePath string) *MultiFileHandler {
    os.MkdirAll(basePath, 0755)
    multiFileHandler := &MultiFileHandler{
       basePath: basePath,
       handlers: make(map[slog.Level]slog.Handler),
    }

    for level := slog.LevelDebug; level <= slog.LevelError; level += 4 {
       multiFileHandler.getHandler(level)
    }

    return multiFileHandler
}

func (h *MultiFileHandler) getHandler(level slog.Level) slog.Handler {
    h.mux.RLock()
    handler, ok := h.handlers[level]
    h.mux.RUnlock()
    if ok {
       return handler
    }
    h.mux.Lock()
    defer h.mux.Unlock()
    if handler, ok = h.handlers[level]; ok {
       return handler
    }
    // 确定文件名
    var levelName string
    switch {
    case level <= slog.LevelDebug:
       levelName = "debug"
    case level <= slog.LevelInfo:
       levelName = "info"
    case level <= slog.LevelWarn:
       levelName = "warn"
    default:
       levelName = "error"
    }

    // 创建新文件
    filePath := filepath.Join(h.basePath, levelName+".log")
    _, err := os.OpenFile(filePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644)
    if err != nil {
       slog.Error("创建日志文件失败", "level", levelName, "error", err)
       return nil
    }
    fileWriter := &lumberjack.Logger{
       Filename:   filePath,
       MaxSize:    10, // megabytes
       MaxBackups: 3,
       MaxAge:     28, // days
       Compress:   true,
    }

    // 创建新的JSON handler
    handler = slog.NewJSONHandler(fileWriter, &slog.HandlerOptions{
       Level: level,
    })

    h.handlers[level] = handler
    return handler
}

func (h *MultiFileHandler) Enabled(ctx context.Context, level slog.Level) bool {
    return true
}

func (h *MultiFileHandler) Handle(ctx context.Context, r slog.Record) error {
    handler := h.getHandler(r.Level)
    if handler == nil {
       return nil
    }
    return handler.Handle(ctx, r)
}

func (h *MultiFileHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
    for level, handler := range h.handlers {
       h.handlers[level] = handler.WithAttrs(attrs)
    }
    return &MultiFileHandler{
       basePath: h.basePath,
       handlers: h.handlers,
    }
}

func (h *MultiFileHandler) WithGroup(name string) slog.Handler {
    for _, handler := range h.handlers {
       handler = handler.WithGroup(name)
    }
    return &MultiFileHandler{
       basePath: h.basePath,
       handlers: h.handlers,
    }
}

// GetLogger extract logger from context and with attrs or// create a new logger from logx with attrs.
func GetLogger(ctx context.Context, attrs ...slog.Attr) *slog.Logger {
    logger, ok := ctx.Value(loggerKey).(*slog.Logger)
    if !ok {
       return slog.New(NewMultiFileHandler("./logs").WithAttrs(attrs))
    }
    return logger
}

// WithContext set logger to context.func WithContext(ctx context.Context, logger *slog.Logger) context.Context {
    return context.WithValue(ctx, loggerKey, logger)
}

multiFileHandler_test.go

func TestNewMultiFileHandler(t *testing.T) {
    handler := NewMultiFileHandler("./logs")
    slog.SetDefault(slog.New(handler))

    slog.Info("this is info log")
    slog.Debug("this is debug log")
    slog.Warn("this is warn log")
    slog.Error("this is error log")

    slog.NewJSONHandler(os.Stdout, nil)
}

func TestGetLogger(t *testing.T) {
    logFields := map[string]interface{}{
       "txid":        "e.GetTxId()",
       "blockHeight": "e.BlockHeight",
       "event":       "e.Topic",
       "contract":    "h.contractName",
       "eventID":     "eventID",
    }
    logger := GetLogger(context.Background(), util.ConvertToSlogAttrs(logFields)...)
    logger.Info("test")
    ctx := WithContext(context.Background(), logger)
    callBack(ctx)
    logger.Info("end")
}

func callBack(ctx context.Context) {
    logger := GetLogger(ctx)
    logger.Info("callBack")
}

使用方式类似 logx，slog 提供了很多可能性，可以基于官方的 slog 开发我们自己的 logger 日志打印。