本文永久链接 – https://tonybai.com/2022/10/30/first-exploration-of-slog


Go自诞生以来就在其标准库内置了log包作为Go源码输出日志的标准组件,该包被广泛应用于Go标准库自身以及Go社区项目中。

不过,针对Go标准库log包,Go社区要求改进的声音始终不断,主流声音聚焦在以下几点:

  • log包是为了方便人类可读而设计的,不支持便于机器解析的结构化日志(比如像zap那样输出json格式的日志);
  • 不支持日志级别(log level);
  • log包采用专有日志输出格式,又没有提供可供Go社区共同遵循的Logger接口类型,导致Go社区项目使用的log输出格式五花八门,相互之间又难以兼容。

Go社区曾经尝试过合力改进标准库log包,并撰写了Proposal设计初稿,但最终因各种原因都没有被Go核心团队接受。

2022年8月末,Go团队的Jonathan Amsterdam发起discussion,意在和社区讨论为Go标准库添加结构化的、支持日志级别的日志包相关事宜,并形成一个一致的Proposal。

Jonathan Amsterdam将该结构化日志包命名为slog,计划放在log/slog下。他还在golang.org/x/exp下面给出了slog的初始实现,这几天该Proposal正式进入review阶段。至于何时能正式落地到Go正式版本中还不可知。

在这篇文章中,我们就来简单看一下slog的proposal以及它的初始实现。

1. slog的设计简介

slog的设计之初对社区目前的一些应用广泛的log包进行了详细调研,比如uber zapzerolog等,因此slog的设计也算是“站在前人的肩膀上”,尤其是uber zap。

Jonathan Amsterdam为此次slog的设计设定了如下目标(摘自slog的proposal):

  • 易用性

通过对现有日志包的调查发现,程序员们希望有一套简洁且易于理解的logging API。在此proposal中,我们将采用目前最流行的方式来表达键值对,即交替传入键和值。

  • 高性能高

该log API的设计将尽量减少内存分配和加锁。它提供了一个交替输入键和值的方法,虽略繁琐,但速度更快;

  • 可以与运行时跟踪(tracing)集成

Go团队正在开发一个改进的运行时跟踪(runtime tracing)系统。本软件包的日志将可以被无缝集成到这个跟踪系统中,使开发者能够将他们的程序行为与运行时的行为联系起来。

这里基于slog proposal和golang.org/x/exp/slog的源码,画了一幅slog的结构示意图:

简单解释一下这个图:

slog从逻辑上分为前端(front)和后端(backend)。

slog前端就是slog提供给使用者的API,不过,很遗憾slog依旧像log那样没有抽取出Logger接口,而是定义了一个Logger结构体,并提供了如图中的那些方法,这也意味着我们依旧无法在整个Go社区统一前端API

通过前端方法,slog将日志内容以及相关属性信息封装成一个slog.Record类型实例,然后传递给slog的后端。

如果你使用的是Go社区的第三方log包的前端方法,比如zap,如果要使用slog后端,你同样需要对zap等进行封装,让其输出slog.Record并传递给slog的后端(目前尚没有这方面示例)。

slog将后端抽象为slog.Handler接口,接口如下:

//
// Any of the Handler's methods may be called concurrently with itself
// or with other methods. It is the responsibility of the Handler to
// manage this concurrency.
type Handler interface {
    // Enabled reports whether the handler handles records at the given level.
    // The handler ignores records whose level is lower.
    // Enabled is called early, before any arguments are processed,
    // to save effort if the log event should be discarded.
    Enabled(Level) bool

    // Handle handles the Record.
    // It will only be called if Enabled returns true.
    // Handle methods that produce output should observe the following rules:
    //   - If r.Time is the zero time, ignore the time.
    //   - If an Attr's key is the empty string, ignore the Attr.
    Handle(r Record) error

    // WithAttrs returns a new Handler whose attributes consist of
    // both the receiver's attributes and the arguments.
    // The Handler owns the slice: it may retain, modify or discard it.
    WithAttrs(attrs []Attr) Handler

    // WithGroup returns a new Handler with the given group appended to
    // the receiver's existing groups.
    // The keys of all subsequent attributes, whether added by With or in a
    // Record, should be qualified by the sequence of group names.
    //
    // How this qualification happens is up to the Handler, so long as
    // this Handler's attribute keys differ from those of another Handler
    // with a different sequence of group names.
    //
    // A Handler should treat WithGroup as starting a Group of Attrs that ends
    // at the end of the log event. That is,
    //
    //     logger.WithGroup("s").LogAttrs(slog.Int("a", 1), slog.Int("b", 2))
    //
    // should behave like
    //
    //     logger.LogAttrs(slog.Group("s", slog.Int("a", 1), slog.Int("b", 2)))
    WithGroup(name string) Handler
}

接口类型的存在,让slog的后端扩展性更强,我们除了可以使用slog提供的两个内置Handler实现:TextHandler和JSONHandler之外,还可以基于第三方log包定义或完全自定义后端Handler的实现。

slog内置两个最常用的Handler:TextHandler和JSONHandler。TextHandler顾名思义,像标准库log包那样将日志以一行文本那样输出;而JSONHandler则是以JSON格式输出log内容与各个属性,我们看一下作者给的例子:

// github.com/bigwhite/experiments/tree/master/slog-examples/demo1/main.go
package main

import (
    "net"

    "golang.org/x/exp/slog"
)

func main() {
    slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr)))
    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))
}

这是一个使用内置TextHandler的示例,我们运行一下看看结果:

time=2022-10-23T18:41:35.074+08:00 level=INFO msg=hello name=Al
time=2022-10-23T18:41:35.074+08:00 level=ERROR msg=oops status=500 err="use of closed network connection"
time=2022-10-23T18:41:35.074+08:00 level=ERROR msg=oops status=500 err="use of closed network connection"

我们看到,输出的日志以“key1=value1 key2=value2 … keyN=valueN”形式呈现,time和level两个key是必选,调用Error方法时,err这个key也是必选的。

接下来,我们将TextHandler换成JSONHandler:

slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr)))

改为:

slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr)))

运行修改后的程序,我们得到:

{"time":"2022-10-23T18:45:26.2131+08:00","level":"INFO","msg":"hello","name":"Al"}
{"time":"2022-10-23T18:45:26.213287+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T18:45:26.21331+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}

我们看到,每条日志以一条json记录的形式呈现,这样的结构化日志非常适合机器解析。

如果我们去掉上面SetDefault那一行代码,再来运行一下程序:

2022/10/23 18:47:51 INFO hello name=Al
2022/10/23 18:47:51 ERROR oops status=500 err="use of closed network connection"
2022/10/23 18:47:51 ERROR oops status=500 err="use of closed network connection"

我们得到了不同于TextHandler和JSONHandler的日志样式,不过这个日志样式非常眼熟!这不和log包的输出样式相同么!没错,如果没有显式将新创建的Logger设置为默认Logger,slog会使用defaultHandler,而defaultHandler的output函数就是log.Output:

// slog项目

// logger.go
var defaultLogger atomic.Value

func init() {
    defaultLogger.Store(Logger{
        handler: newDefaultHandler(log.Output), // 这里直接使用了log.Output
    })
} 

// handler.go

type defaultHandler struct {
    ch *commonHandler
    // log.Output, except for testing
    output func(calldepth int, message string) error
}

func newDefaultHandler(output func(int, string) error) *defaultHandler {
    return &defaultHandler{
        ch:     &commonHandler{json: false},
        output: output,
    }
}

slog的前端是“固定格式”的,因此没什么可定制的。但后端这块倒是有不少玩法,接下来我们重点看一下后端。

2. Handler选项(HandlerOptions)

slog提供了HandlerOptions结构:

// handler.go

// HandlerOptions are options for a TextHandler or JSONHandler.
// A zero HandlerOptions consists entirely of default values.
type HandlerOptions struct {
    // Add a "source" attribute to the output whose value is of the form
    // "file:line".
    // This is false by default, because there is a cost to extracting this
    // information.
    AddSource bool

    // Ignore records with levels below Level.Level().
    // The default is InfoLevel.
    Level Leveler

    // If set, ReplaceAttr is called on each attribute of the message,
    // and the returned value is used instead of the original. If the returned
    // key is empty, the attribute is omitted from the output.
    //
    // The built-in attributes with keys "time", "level", "source", and "msg"
    // are passed to this function first, except that time and level are omitted
    // if zero, and source is omitted if AddSourceLine is false.
    //
    // ReplaceAttr can be used to change the default keys of the built-in
    // attributes, convert types (for example, to replace a `time.Time` with the
    // integer seconds since the Unix epoch), sanitize personal information, or
    // remove attributes from the output.
    ReplaceAttr func(a Attr) Attr
}

通过该结构,我们可以为输出的日志添加source信息,即输出日志的文件名与行号,下面就是一个例子:

// github.com/bigwhite/experiments/tree/master/slog-examples/demo2/main.go
package main

import (
    "net"
    "os"

    "golang.org/x/exp/slog"
)

func main() {
    opts := slog.HandlerOptions{
        AddSource: true,
    }

    slog.SetDefault(slog.New(opts.NewJSONHandler(os.Stderr)))
    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))
}

运行上述程序,我们将得到:

{"time":"2022-10-23T21:46:25.718112+08:00","level":"INFO","source":"/Users/tonybai/go/src/github.com/bigwhite/experiments/slog-examples/demo2/main.go:16","msg":"hello","name":"Al"}
{"time":"2022-10-23T21:46:25.718324+08:00","level":"ERROR","source":"/Users/tonybai/go/src/github.com/bigwhite/experiments/slog-examples/demo2/main.go:17","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T21:46:25.718352+08:00","level":"ERROR","source":"/Users/tonybai/go/src/github.com/bigwhite/experiments/slog-examples/demo2/main.go:18","msg":"oops","status":500,"err":"use of closed network connection"}

我们也可以通过HandlerOptions实现日志级别的动态设置,比如下面例子:

// github.com/bigwhite/experiments/tree/master/slog-examples/demo3/main.go
func main() {
    var lvl = &slog.AtomicLevel{}
    lvl.Set(slog.DebugLevel)
    opts := slog.HandlerOptions{
        Level: lvl,
    }
    slog.SetDefault(slog.New(opts.NewJSONHandler(os.Stderr)))

    slog.Info("before resetting log level:")

    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))

    slog.Info("after resetting log level to error level:")
    lvl.Set(slog.ErrorLevel)
    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))

}

slog.HandlerOptions的字段Level是一个接口类型变量,其类型为slog.Leveler:

type Leveler interface {
    Level() Level
}

实现了Level方法的类型都可以赋值给HandlerOptions的Level字段,slog提供了支持并发访问的AtomicLevel供我们直接使用,上面的demo3使用的就是AtomicLevel,初始时设置的是DebugLevel,于是第一次调用Info、Error等API输出的日志都会得到输出,之后重置日志级别为ErrorLevel,这样Info API输出的日志将不会被呈现出来,下面是demo3程序的运行结果:

{"time":"2022-10-23T21:58:48.467666+08:00","level":"INFO","msg":"before resetting log level:"}
{"time":"2022-10-23T21:58:48.467818+08:00","level":"INFO","msg":"hello","name":"Al"}
{"time":"2022-10-23T21:58:48.467825+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T21:58:48.467842+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T21:58:48.467846+08:00","level":"INFO","msg":"after resetting log level to error level:"}
{"time":"2022-10-23T21:58:48.46785+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T21:58:48.467854+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}

HandlerOptions的第三个字段ReplaceAttr有什么功用,就留给大家自己探索一下。

除了利用HandleOptions做一些定制之外,我们也可以完全自定义Handler接口的实现,下面我们就用一个示例来说明一下。

3. 自定义Handler接口的实现

我们来定义一个新Handler:ChanHandler,该Handler实现将日志写入channel的行为(用来模拟日志写入kafka),我们来建立该ChanHandler:

// github.com/bigwhite/experiments/tree/master/slog-examples/demo4/main.go
type ChanHandler struct {
    slog.Handler
    ch  chan []byte
    buf *bytes.Buffer
}

func (h *ChanHandler) Enabled(level slog.Level) bool {
    return h.Handler.Enabled(level)
}

func (h *ChanHandler) Handle(r slog.Record) error {
    err := h.Handler.Handle(r)
    if err != nil {
        return err
    }
    var nb = make([]byte, h.buf.Len())
    copy(nb, h.buf.Bytes())
    h.ch <- nb
    h.buf.Reset()
    return nil
}

func (h *ChanHandler) WithAttrs(as []slog.Attr) slog.Handler {
    return &ChanHandler{
        buf:     h.buf,
        ch:      h.ch,
        Handler: h.Handler.WithAttrs(as),
    }
}

func (h *ChanHandler) WithGroup(name string) slog.Handler {
    return &ChanHandler{
        buf:     h.buf,
        ch:      h.ch,
        Handler: h.Handler.WithGroup(name),
    }
}

func NewChanHandler(ch chan []byte) *ChanHandler {
    var b = make([]byte, 256)
    h := &ChanHandler{
        buf: bytes.NewBuffer(b),
        ch:  ch,
    }

    h.Handler = slog.NewJSONHandler(h.buf)

    return h
}

我们看到ChanHandler内嵌了slog.JSONHandler,对slog.Handler接口的实现多半由内嵌的JSONHandler去完成,唯一不同的是Handle方法,这里要把JSONHandler处理完的日志copy出来并发送到channel中。下面是该demo的main函数:

// github.com/bigwhite/experiments/tree/master/slog-examples/demo4/main.go

func main() {
    var ch = make(chan []byte, 100)
    attrs := []slog.Attr{
        {Key: "field1", Value: slog.StringValue("value1")},
        {Key: "field2", Value: slog.StringValue("value2")},
    }
    slog.SetDefault(slog.New(NewChanHandler(ch).WithAttrs(attrs)))
    go func() { // 模拟channel的消费者,用来消费日志
        for {
            b := <-ch
            fmt.Println(string(b))
        }
    }()

    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))

    time.Sleep(3 * time.Second)
}

运行上述程序,我们将得到下面输出结果:

{"time":"2022-10-23T23:09:01.358702+08:00","level":"INFO","msg":"hello","field1":"value1","field2":"value2","name":"Al"}

{"time":"2022-10-23T23:09:01.358836+08:00","level":"ERROR","msg":"oops","field1":"value1","field2":"value2","status":500,"err":"use of closed network connection"}

{"time":"2022-10-23T23:09:01.358856+08:00","level":"ERROR","msg":"oops","field1":"value1","field2":"value2","status":500,"err":"use of closed network connection"}

4. slog的性能

我们再来看看slog的性能,我们直接使用了slog源码中自带的与zap的性能对比数据,使用benchstat工具查看对比结果如下:

$ benchstat zapbenchmarks/zap.bench slog.bench
name                              old time/op    new time/op    delta
Attrs/async_discard/5_args-8         348ns ± 2%      88ns ± 2%   -74.77%  (p=0.008 n=5+5)
Attrs/async_discard/10_args-8        570ns ± 2%     280ns ± 2%   -50.94%  (p=0.008 n=5+5)
Attrs/async_discard/40_args-8       1.84µs ± 2%    0.91µs ± 3%   -50.37%  (p=0.008 n=5+5)
Attrs/fastText_discard/5_args-8      476ns ± 2%     200ns ±45%   -57.92%  (p=0.008 n=5+5)
Attrs/fastText_discard/10_args-8     822ns ± 7%     524ns ± 2%   -36.27%  (p=0.008 n=5+5)
Attrs/fastText_discard/40_args-8    2.70µs ± 3%    2.01µs ± 3%   -25.76%  (p=0.008 n=5+5)

name                              old alloc/op   new alloc/op   delta
Attrs/async_discard/5_args-8          320B ± 0%        0B       -100.00%  (p=0.008 n=5+5)
Attrs/async_discard/10_args-8         640B ± 0%      208B ± 0%   -67.50%  (p=0.008 n=5+5)
Attrs/async_discard/40_args-8       2.69kB ± 0%    1.41kB ± 0%   -47.64%  (p=0.008 n=5+5)
Attrs/fastText_discard/5_args-8       320B ± 0%        0B       -100.00%  (p=0.008 n=5+5)
Attrs/fastText_discard/10_args-8      641B ± 0%      208B ± 0%   -67.55%  (p=0.008 n=5+5)
Attrs/fastText_discard/40_args-8    2.70kB ± 0%    1.41kB ± 0%   -47.63%  (p=0.029 n=4+4)

name                              old allocs/op  new allocs/op  delta
Attrs/async_discard/5_args-8          1.00 ± 0%      0.00       -100.00%  (p=0.008 n=5+5)
Attrs/async_discard/10_args-8         1.00 ± 0%      1.00 ± 0%      ~     (all equal)
Attrs/async_discard/40_args-8         1.00 ± 0%      1.00 ± 0%      ~     (all equal)
Attrs/fastText_discard/5_args-8       1.00 ± 0%      0.00       -100.00%  (p=0.008 n=5+5)
Attrs/fastText_discard/10_args-8      1.00 ± 0%      1.00 ± 0%      ~     (all equal)
Attrs/fastText_discard/40_args-8      1.00 ± 0%      1.00 ± 0%      ~     (all equal)

我们看到,slog的性能相对于本就以高性能著称的zap还要好上不少,内存分配也减少很多。

5. 小结

通过对slog的初步探索,感觉slog整体上借鉴了zap等第三方log包的设计,都采用前后端分离的策略,但似乎又比zap好理解一些。

前面示例中提到了使用起来很方便的前端API,谈到了slog的高性能,slog设计目标中与runtime tracing集成在proposal中提及不多,更多谈到的是其与context.Context的集成(通过slog.WithContext和slog.FromContext等),也许这就是与runtime tracing集成的基础吧。

Jonathan Amsterdam在proposal也提到过,每个第三方log包都有其特点,不指望slog能替换掉所有第三方log包,只是希望slog能与第三方log包充分交互,实现每个程序有一个共同的 “后端”。 一个有许多依赖关系的应用程序可能会发现,它已经连接了许多日志包。如果所有的包都支持slog提出的Handler接口,那么应用程序就可以创建一个单一的Handler并为每个日志库安装一次,以便在其所有的依赖中获得一致的日志。

个人观点:等slog加入标准库后,新项目推荐使用slog。

本文涉及的示例代码可以在这里下载。

6. 参考资料

  • Proposal: Structured Logging review – https://go-review.googlesource.com/c/proposal/+/444415/3/design/56345-structured-logging.md
  • discussion: structured, leveled logging – https://github.com/golang/go/discussions/54763
  • proposal: log/slog: structured, leveled logging – https://github.com/golang/go/issues/56345
  • slog实验性实现 – https://github.com/golang/exp/tree/master/slog
  • logr – https://github.com/go-logr/logr
  • Go Logging Design Proposal – Ross Light – https://docs.google.com/document/d/1nFRxQ5SJVPpIBWTFHV-q5lBYiwGrfCMkESFGNzsrvBU/edit
  • Standardization around logging and related concerns – https://groups.google.com/g/golang-dev/c/F3l9Iz1JX4g/m/t0J0loRaDQAJ

“Gopher部落”知识星球旨在打造一个精品Go学习和进阶社群!高品质首发Go技术文章,“三天”首发阅读权,每年两期Go语言发展现状分析,每天提前1小时阅读到新鲜的Gopher日报,网课、技术专栏、图书内容前瞻,六小时内必答保证等满足你关于Go语言生态的所有需求!2022年,Gopher部落全面改版,将持续分享Go语言与Go应用领域的知识、技巧与实践,并增加诸多互动形式。欢迎大家加入!

img{512x368}
img{512x368}

img{512x368}
img{512x368}

我爱发短信:企业级短信平台定制开发专家 https://51smspush.com/。smspush : 可部署在企业内部的定制化短信平台,三网覆盖,不惧大并发接入,可定制扩展; 短信内容你来定,不再受约束, 接口丰富,支持长短信,签名可选。2020年4月8日,中国三大电信运营商联合发布《5G消息白皮书》,51短信平台也会全新升级到“51商用消息平台”,全面支持5G RCS消息。

著名云主机服务厂商DigitalOcean发布最新的主机计划,入门级Droplet配置升级为:1 core CPU、1G内存、25G高速SSD,价格5$/月。有使用DigitalOcean需求的朋友,可以打开这个链接地址:https://m.do.co/c/bff6eed92687 开启你的DO主机之路。

Gopher Daily(Gopher每日新闻)归档仓库 – https://github.com/bigwhite/gopherdaily

我的联系方式:

  • 微博:https://weibo.com/bigwhite20xx
  • 博客:tonybai.com
  • github: https://github.com/bigwhite

商务合作方式:撰稿、出书、培训、在线课程、合伙创业、咨询、广告合作。

© 2022, bigwhite. 版权所有.

Related posts:

  1. Go coding in go way
  2. Go语言之禅
  3. Uber Go语言编码规范
  4. GoCN社区Go读书会第二期:《Go语言精进之路》
  5. Gopher部落:2022年要做的事儿