0%

Zap 是由 Uber 开发的专为 Go 应用程序设计的结构化日志记录包。根据它们在 GitHub 上的 README 文档,它提供了 “极快” 的结构化、分级日志记录,且分配资源最小。 这一说法得到了它们的基准测试结果的支持,这些结果表明 Zap 在性能上几乎优于 Go 的其他大部分可比较的结构化日志记录库,除了 Zerolog

开始使用 Zap

在开始使用Zap之前,您需要通过以下命令将其安装到您的项目中:

1
go get -u go.uber.org/zap

一旦你安装了 Zap,你可以像这样在你的程序中开始使用它:

1
2
3
4
5
6
7
8
9
10
11
12
13
package main

import (
"go.uber.org/zap"
)

func main() {
logger := zap.Must(zap.NewProduction())

defer logger.Sync()

logger.Info("Hello from Zap logger!")
}

输出:

1
{"level":"info","ts":1706518203.525694,"caller":"gopprof/main.go:12","msg":"Hello from Zap logger!"}

与 Go 的大多数其他日志记录包不同,Zap 不提供预先配置的全局日志记录器供直接使用。因此,在开始记录日志之前,您必须创建一个 zap.Logger 实例。 NewProduction() 方法返回一个 Logger,配置为以 JSON 格式记录到标准错误,并将其最低日志级别设置为 INFO

生成的输出相对简单,没有什么意外,除了其默认的时间戳格式(ts),它以自 1970年1月1日 UTC 起经过的纳秒数呈现,而不是典型的 ISO-8601 格式。

您还可以利用 NewDevelopment 来创建更适用于开发环境的日志记录,以 DEBUG 级别记录并使用更符合人类习惯的格式:

1
logger := zap.Must(zap.NewDevelopment())

输出:

1
2023-05-14T20:42:39.137+0100    INFO    zap/main.go:12  Hello from Zap logger!

您可以轻松地通过环境变量在开发和生产 Logger 之间进行切换:

1
2
3
4
logger := zap.Must(zap.NewProduction())
if os.Getenv("APP_ENV") == "development" {
logger = zap.Must(zap.NewDevelopment())
}

设置全局 logger

如果您想在不先创建实例的情况下编写日志,可以在 init() 函数中使用 ReplaceGlobals() 方法:

1
2
3
4
5
6
7
8
9
10
11
12
13
package main

import (
"go.uber.org/zap"
)

func init() {
zap.ReplaceGlobals(zap.Must(zap.NewProduction()))
}

func main() {
zap.L().Info("Hello from Zap!")
}

这种方法将通过 zap.L() 访问的全局记录器替换为一个功能 Logger 实例,这样你就可以直接通过将 zap 包导入到你的文件中来使用它。

Zap 基本 API

Zap 提供了两个主要的日志 API。第一个是低级别的 Logger 类型,它提供了一种结构化的记录消息的方式。 它专为在性能敏感的环境中使用而设计,其中每个分配都很重要,它只支持强类型的上下文字段:

1
2
3
4
5
6
7
8
9
10
11
func main() {
logger := zap.Must(zap.NewProduction())

defer logger.Sync()

logger.Info("User logged in",
zap.String("username", "johndoe"),
zap.Int("userid", 123456),
zap.String("provider", "google"),
)
}

输出:

1
{"level":"info","ts":1706518317.8943732,"caller":"gopprof/main.go:12","msg":"User logged in","username":"johndoe","userid":123456,"provider":"google"}

该类型为每个支持的日志级别(Info()Warn()Error()等)公开了一个方法,并且每个方法都接受一个消息和零个或多个字段,这些字段是强类型的键/值对,如上例所示。

第二个高级 API 是 SugaredLogger 类型,它代表了一种更随意的日志记录方法。它的 API 比 Logger 类型更简洁,但性能略有损失。在底层,它依赖于 Logger 类型进行实际的日志记录操作。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
func main() {
logger := zap.Must(zap.NewProduction())

defer logger.Sync()

sugar := logger.Sugar()

sugar.Info("Hello from Zap logger!")
sugar.Infoln(
"Hello from Zap logger!",
)
sugar.Infof(
"Hello from Zap logger! The time is %s",
time.Now().Format("03:04 AM"),
)

sugar.Infow("User logged in",
"username", "johndoe",
"userid", 123456,
zap.String("provider", "google"),
)
}

输出:

1
2
3
4
{"level":"info","ts":1684147807.960761,"caller":"zap/main.go:17","msg":"Hello from Zap logger!"}
{"level":"info","ts":1684147807.960845,"caller":"zap/main.go:18","msg":"Hello from Zap logger!"}
{"level":"info","ts":1684147807.960909,"caller":"zap/main.go:21","msg":"Hello from Zap logger! The time is 11:50 AM"}
{"level":"info","ts":1684148355.2692218,"caller":"zap/main.go:25","msg":"User logged in","username":"johndoe","userid":123456,"provider":"google"}

一个 Logger 可以通过调用它的 Sugar() 方法转换为 SugaredLogger 类型。相反,Desugar() 方法将 SugaredLogger 转换为 Logger ,您可以根据需要执行这些转换,因为性能开销可以忽略不计。

1
2
3
4
5
6
7
8
sugar := zap.Must(zap.NewProduction()).Sugar()

defer sugar.Sync()
sugar.Infow("Hello from SugaredLogger!")

logger := sugar.Desugar()

logger.Info("Hello from Logger!")

这个特性意味着你不必在你的代码库中选择其中一个。例如,你可以在通常情况下默认使用 SugaredLogger 以获得灵活性,然后在性能敏感代码的边界处转换为 Logger 类型。

SugaredLogger 类型为每个支持的级别提供了四种方法:

  1. 第一个(Info()Error(),等等)与 Logger 上的 level 方法同名,但它接受一个或多个 any 类型的参数。在内部,它们使用 fmt.Sprint() 方法将参数连接到输出的 msg 属性中。

  2. ln 结尾的方法(如 Infoln()Errorln())与第一个方法相同,只是使用 fmt.Sprintln() 来构建和记录消息。

  3. f 结尾的方法使用 fmt.Sprintf() 方法来构建和记录一个模板化的消息。

  4. 最后,以 w 结尾的方法允许您向日志记录中添加强类型和弱类型的键值对混合。日志消息是第一个参数;随后的参数应该按照上面的示例以键值对的形式提供。

使用松散类型的键/值对时需要注意的一点是,键始终预期为字符串,而值可以是任何类型。如果使用非字符串键,程序将在开发中出现恐慌:

1
sugar.Infow("User logged in", 1234, "userID")
1
2
3
4
5
6
7
8
2023-05-15T12:06:12.996+0100    ERROR   zap@v1.24.0/sugar.go:210        Ignored key-value pairs with non-string keys.   {"invalid": [{"position": 0, "key": 1234, "value": "userID"}]}
go.uber.org/zap.(*SugaredLogger).Infow
/home/ayo/go/pkg/mod/go.uber.org/zap@v1.24.0/sugar.go:210
main.main
/home/ayo/dev/demo/zap/main.go:14
runtime.main
/usr/local/go/src/runtime/proc.go:250
2023-05-15T12:06:12.996+0100 INFO zap/main.go:14 User logged in

在生产环境中,会记录一个单独的错误,并跳过键/值对:

1
2
{"level":"error","ts":1684148883.086758,"caller":"zap@v1.24.0/sugar.go:210","msg":"Ignored key-value pairs with non-string keys.","invalid":[{"position":0,"key":1234,"value":"userID"}],"stacktrace":"go.uber.org/zap.(*SugaredLogger).Infow\n\t/home/ayo/go/pkg/mod/go.uber.org/zap@v1.24.0/sugar.go:210\nmain.main\n\t/home/ayo/dev/demo/zap/main.go:14\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
{"level":"info","ts":1684148883.0867138,"caller":"zap/main.go:14","msg":"User logged in"}

传递一个孤立的键(没有对应的值)的行为类似:在开发中会引发恐慌,在生产中会产生错误。由于这些松散类型的键/值对存在所有这些警告,我们建议始终使用强类型的上下文字段,无论您是否使用 LoggerSugaredLogger

Zap 中的日志级别

Zap 提供以下日志级别,按严重程度递增。每个级别都与相应的整数关联:

  • DEBUG (-1): 用于记录调试消息的有用信息。
  • INFO (0): 用于描述正常应用程序操作的消息。
  • WARN (1): 用于记录指示发生了可能需要注意的异常情况的消息,以防升级为更严重的问题。
  • ERROR (2): 用于记录程序中的意外错误条件。
  • DPANIC (3): 用于记录开发中的严重错误条件。它在开发中的行为类似于 PANIC ,在生产中的行为类似于 ERROR
  • PANIC (4): 在记录错误条件后调用 panic()
  • FATAL (5): 在记录错误条件后调用 os.Exit(1)

这些级别在 zapcore 包中定义,该包定义并实现了 Zap 构建的底层接口。

值得注意的是,没有 TRACE 级别,也没有办法向记录器添加自定义级别,这可能会成为一些人的瓶颈。 如前所述,生产记录器的默认日志级别是 INFO 。如果您希望修改此设置,必须创建一个自定义记录器,我们将在接下来的部分详细介绍。

创建自定义记录器(logger)

到目前为止,我们已经展示了如何通过 Zap 提供的生产和开发预设来使用默认配置。现在让我们来看看如何使用自定义配置选项创建一个实例。

使用Zap创建自定义 Logger 有两种主要方法。第一种方法是使用其 Config 类型来构建自定义记录器,如下所示:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
package main

import (
"os"

"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)

func createLogger() *zap.Logger {
encoderCfg := zap.NewProductionEncoderConfig()
encoderCfg.TimeKey = "timestamp"
encoderCfg.EncodeTime = zapcore.ISO8601TimeEncoder

config := zap.Config{
Level: zap.NewAtomicLevelAt(zap.InfoLevel),
Development: false,
DisableCaller: false,
DisableStacktrace: false,
Sampling: nil,
Encoding: "json",
EncoderConfig: encoderCfg,
OutputPaths: []string{
"stderr",
},
ErrorOutputPaths: []string{
"stderr",
},
InitialFields: map[string]interface{}{
"pid": os.Getpid(),
},
}

return zap.Must(config.Build())
}

func main() {
logger := createLogger()

defer logger.Sync()

logger.Info("Hello from Zap!")
}

输出:

1
{"level":"info","timestamp":"2023-05-15T12:40:16.647+0100","caller":"zap/main.go:42","msg":"Hello from Zap!","pid":2329946}

上面的 createLogger() 函数返回一个新的 zap.Logger,它的功能类似于 NewProduction() Logger,但有一些不同之处。 我们将 Zap 的生产配置作为我们自定义日志记录器的基础,通过调用 NewProductionEncoderConfig() 并稍微修改它,将 ts 字段更改为 timestamp ,并将时间格式更改为 ISO-8601zapcore 包公开了 Zap 构建在其上的接口,以便您可以自定义和扩展其功能。

Config 对象包含创建新 Logger 时所需的许多常见配置选项。每个字段代表的详细描述都在项目文档中,因此我们在这里不会重复列举它们,除了一些特殊情况:

  • OutputPaths 指定一个或多个日志输出的目标(详见 Open 以获取更多详情)。
  • ErrorOutputPaths 类似于 OutputPaths ,但仅用于 Zap 内部错误,而不是由您的应用程序生成或记录的错误(例如由不匹配的松散类型键/值对引起的错误)。
  • InitialFields 指定了应该包含在从 Config 对象创建的每个记录器产生的每个日志条目中的全局上下文字段。我们这里只包括程序的进程 ID,但您可以添加其他有用的全局元数据,比如运行程序的 Go 版本、git 提交哈希或应用程序版本、环境或部署信息等。

一旦您设置了首选配置设置,必须调用 Build() 方法来生成 Logger。请查看 Configzapcore.EncoderConfig 的文档,了解所有可用选项。

创建自定义记录器的第二种更高级的方法涉及使用 zap.New() 方法。它接受一个 zapcore.Core 接口和零个或多个选项来配置 Logger 。以下是一个示例,同时将彩色输出记录到控制台,并以 JSON 格式记录到文件中:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
func createLogger() *zap.Logger {
stdout := zapcore.AddSync(os.Stdout)

file := zapcore.AddSync(&lumberjack.Logger{
Filename: "logs/app.log",
MaxSize: 10, // megabytes
MaxBackups: 3,
MaxAge: 7, // days
})

level := zap.NewAtomicLevelAt(zap.InfoLevel)

productionCfg := zap.NewProductionEncoderConfig()
productionCfg.TimeKey = "timestamp"
productionCfg.EncodeTime = zapcore.ISO8601TimeEncoder

developmentCfg := zap.NewDevelopmentEncoderConfig()
developmentCfg.EncodeLevel = zapcore.CapitalColorLevelEncoder

consoleEncoder := zapcore.NewConsoleEncoder(developmentCfg)
fileEncoder := zapcore.NewJSONEncoder(productionCfg)

core := zapcore.NewTee(
zapcore.NewCore(consoleEncoder, stdout, level),
zapcore.NewCore(fileEncoder, file, level),
)

return zap.New(core)
}

func main() {
logger := createLogger()

defer logger.Sync()

logger.Info("Hello from Zap!")
}
1
2023-05-15T16:15:05.466+0100    INFO    Hello from Zap!
1
{"level":"info","timestamp":"2023-05-15T16:15:05.466+0100","msg":"Hello from Zap!"}

这个示例使用 Lumberjack 包自动旋转日志文件,以防它们变得过大。NewTee()方法将日志条目复制到两个或更多目的地。 在这种情况下,日志以带颜色的纯文本格式发送到标准输出,而 JSON 等效内容发送到logs/app.log文件。

顺便说一句,我们通常建议使用像 Logrotate 这样的外部工具来管理和轮转日志文件,而不是在应用程序本身中进行操作。

为您的日志添加上下文

如前所述,使用 Zap 进行上下文日志记录是通过在日志消息后传递强类型的键值对来完成的,就像这样:

1
2
3
4
5
logger.Warn("User account is nearing the storage limit",
zap.String("username", "john.doe"),
zap.Float64("storageUsed", 4.5),
zap.Float64("storageLimit", 5.0),
)
1
{"level":"warn","ts":1684166023.952419,"caller":"zap/main.go:46","msg":"User account is nearing the storage limit","username":"john.doe","storageUsed":4.5,"storageLimit":5}

使用子记录器,您还可以向特定范围内产生的所有日志添加上下文属性。这有助于避免在日志点处不必要的重复。子记录器是使用 With() 上的 Logger 方法创建的:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
func main() {
logger := zap.Must(zap.NewProduction())

defer logger.Sync()

childLogger := logger.With(
zap.String("service", "userService"),
zap.String("requestID", "abc123"),
)

childLogger.Info("user registration successful",
zap.String("username", "john.doe"),
zap.String("email", "john@example.com"),
)

childLogger.Info("redirecting user to admin dashboard")
}

注意两个日志中都存在 servicerequestID

1
2
{"level":"info","ts":1684164941.7644951,"caller":"zap/main.go:52","msg":"user registration successful","service":"userService","requestID":"abc123","username":"john.doe","email":"john@example.com"}
{"level":"info","ts":1684164941.764551,"caller":"zap/main.go:57","msg":"redirecting user to admin dashboard","service":"userService","requestID":"abc123"}

您可以使用相同的方法向所有日志添加全局元数据。例如,您可以像这样做,将程序的进程ID和编译程序所使用的 Go 版本包含在所有记录中:

1
2
3
4
5
6
7
8
9
10
func createLogger() *zap.Logger {
// . . .
buildInfo, _ := debug.ReadBuildInfo()

return zap.New(samplingCore.With([]zapcore.Field{
zap.String("go_version", buildInfo.GoVersion),
zap.Int("pid", os.Getpid()),
},
))
}

使用 Zap 记录错误

错误是最重要的日志记录目标之一,因此在采用框架之前了解框架如何处理错误是至关重要的。在 Zap 中,您可以使用 Error() 方法记录错误。如果使用 zap.Error() 方法,则输出中还包括 stacktraceerror 属性:

1
2
3
4
5
6
logger.Error("Failed to perform an operation",
zap.String("operation", "someOperation"),
zap.Error(errors.New("something happened")), // the key will be `error` here
zap.Int("retryAttempts", 3),
zap.String("user", "john.doe"),
)

输出:

1
{"level":"error","ts":1684164638.0570025,"caller":"zap/main.go:47","msg":"Failed to perform an operation","operation":"someOperation","error":"something happened","retryAttempts":3,"user":"john.doe","stacktrace":"main.main\n\t/home/ayo/dev/demo/zap/main.go:47\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}

对于更严重的错误,可使用 Fatal() 方法。在写入和刷新日志消息后,它会调用 os.Exit(1)

1
2
3
4
5
logger.Fatal("Something went terribly wrong",
zap.String("context", "main"),
zap.Int("code", 500),
zap.Error(errors.New("An error occurred")),
)

输出:

1
2
{"level":"fatal","ts":1684170760.2103574,"caller":"zap/main.go:47","msg":"Something went terribly wrong","context":"main","code":500,"error":"An error occurred","stacktrace":"main.main\n\t/home/ayo/dev/demo/zap/main.go:47\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
exit status 1

如果错误是可恢复的,您可以使用 Panic() 方法。它记录在 PANIC 级别,并调用 panic() 而不是 os.Exit(1)。 还有一个 DPanic() 级别,只在开发中记录在 DPANIC 级别后才会引发恐慌。在生产环境中,它会在 DPANIC 级别记录,而不会实际引发恐慌。

如果您不想使用非标准级别,比如 PANICDPANIC ,您可以使用以下代码将两种方法都配置为记录在 ERROR 级别:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
func lowerCaseLevelEncoder(
level zapcore.Level,
enc zapcore.PrimitiveArrayEncoder,
) {
if level == zap.PanicLevel || level == zap.DPanicLevel {
enc.AppendString("error")
return
}

zapcore.LowercaseLevelEncoder(level, enc)
}

func createLogger() *zap.Logger {
stdout := zapcore.AddSync(os.Stdout)

level := zap.NewAtomicLevelAt(zap.InfoLevel)

productionCfg := zap.NewProductionEncoderConfig()
productionCfg.TimeKey = "timestamp"
productionCfg.EncodeTime = zapcore.ISO8601TimeEncoder
productionCfg.EncodeLevel = lowerCaseLevelEncoder

jsonEncoder := zapcore.NewJSONEncoder(productionCfg)

core := zapcore.NewCore(jsonEncoder, stdout, level)

return zap.New(core)
}

func main() {
logger := createLogger()

defer logger.Sync()

logger.DPanic(
"this was never supposed to happen",
)
}

输出:

1
{"level":"error","timestamp":"2023-05-15T18:55:33.534+0100","msg":"this was never supposed to happen"}

使用 Zap 进行日志采样

日志抽样是一种技术,通过选择性地捕获和记录日志事件的子集来减少应用程序日志量。其目的是在需要全面记录日志和记录过多数据可能带来的潜在性能影响之间取得平衡。

与捕获每个日志事件不同,日志抽样允许您根据特定标准或规则选择代表性的日志消息子集。这样可以大大减少生成的日志数据量,在高吞吐量系统中尤其有益。

在Zap中,可以通过使用 zapcore.NewSamplerWithOptions() 方法来配置采样,如下所示:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
func createLogger() *zap.Logger {
stdout := zapcore.AddSync(os.Stdout)

level := zap.NewAtomicLevelAt(zap.InfoLevel)

productionCfg := zap.NewProductionEncoderConfig()
productionCfg.TimeKey = "timestamp"
productionCfg.EncodeTime = zapcore.ISO8601TimeEncoder
productionCfg.EncodeLevel = lowerCaseLevelEncoder
productionCfg.StacktraceKey = "stack"

jsonEncoder := zapcore.NewJSONEncoder(productionCfg)

jsonOutCore := zapcore.NewCore(jsonEncoder, stdout, level)

samplingCore := zapcore.NewSamplerWithOptions(
jsonOutCore,
time.Second, // interval
3, // log first 3 entries
0, // thereafter log zero entires within the interval
)

return zap.New(samplingCore)
}

通过记录在指定时间间隔内具有特定级别和消息的前N个条目来采样 Zap 样本。在上述示例中,仅在一秒间隔内记录具有相同级别和消息的前 3 个日志条目。由于此处指定了 0 ,在该间隔内将丢弃每个其他日志条目。

你可以通过登录一个 for 循环来测试这个:

1
2
3
4
5
6
7
8
9
10
func main() {
logger := createLogger()

defer logger.Sync()

for i := 1; i <= 10; i++ {
logger.Info("an info message")
logger.Warn("a warning")
}
}

因此,您应该只看到六个日志条目,而不是观察 20 个。

1
2
3
4
5
6
{"level":"info","timestamp":"2023-05-17T16:00:17.611+0100","msg":"an info message"}
{"level":"warn","timestamp":"2023-05-17T16:00:17.611+0100","msg":"a warning"}
{"level":"info","timestamp":"2023-05-17T16:00:17.611+0100","msg":"an info message"}
{"level":"warn","timestamp":"2023-05-17T16:00:17.611+0100","msg":"a warning"}
{"level":"info","timestamp":"2023-05-17T16:00:17.611+0100","msg":"an info message"}
{"level":"warn","timestamp":"2023-05-17T16:00:17.611+0100","msg":"a warning"}

在这里,只有循环的前三次迭代产生了一些输出。这是因为在其他七次迭代中产生的日志由于采样配置而被丢弃。同样,当类似条目由于负载过重或应用程序出现一连串错误而被记录多次时,Zap 会删除重复条目。

尽管日志抽样可以减少日志量和日志记录的性能影响,但也可能导致一些日志事件被忽略,从而影响故障排除和调试工作。因此,在仔细考虑特定应用程序的要求之后,才应该应用抽样。

在日志中隐藏敏感细节

一种防止意外记录具有敏感字段的类型的技术是在记录点对数据进行编辑或掩码处理。在 Zap 中,可以通过实现 Stringer 接口,然后定义在记录类型时应返回的确切字符串来实现此目的。以下是一个简短的演示:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
type User struct {
ID string `json:"id"`
Name string `json:"name"`
Email string `json:"email"`
}

func main() {
logger := createLogger()

defer logger.Sync()

user := User{
ID: "USR-12345",
Name: "John Doe",
Email: "john.doe@example.com",
}

logger.Info("user login", zap.Any("user", user))
}

输出:

1
{"level":"info","timestamp":"2023-05-17T17:00:59.899+0100","msg":"user login","user":{"id":"USR-12345","name":"John Doe","email":"john.doe@example.com"}}

在这个例子中,整个 user 都被记录下来,不必要地暴露了用户的电子邮件地址。您可以通过以下方式实现 Stringer 接口来防止这种情况发生:

1
2
3
func (u User) String() string {
return u.ID
}

这将在日志中用 ID 字段完全替换 User 类型:

1
{"level":"info","timestamp":"2023-05-17T17:05:01.081+0100","msg":"user login","user":"USR-12345"}

如果您需要更多控制,可以创建自己的 zapcore.Encoder,并将 JSON 编码器用作基础,同时过滤掉敏感字段:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
type SensitiveFieldEncoder struct {
zapcore.Encoder
cfg zapcore.EncoderConfig
}

// EncodeEntry is called for every log line to be emitted so it needs to be
// as efficient as possible so that you don't negate the speed/memory advantages
// of Zap
func (e *SensitiveFieldEncoder) EncodeEntry(
entry zapcore.Entry,
fields []zapcore.Field,
) (*buffer.Buffer, error) {
filtered := make([]zapcore.Field, 0, len(fields))

for _, field := range fields {
user, ok := field.Interface.(User)
if ok {
user.Email = "[REDACTED]"
field.Interface = user
}

filtered = append(filtered, field)
}

return e.Encoder.EncodeEntry(entry, filtered)
}

func NewSensitiveFieldsEncoder(config zapcore.EncoderConfig) zapcore.Encoder {
encoder := zapcore.NewJSONEncoder(config)
return &SensitiveFieldEncoder{encoder, config}
}

func createLogger() *zap.Logger {
. . .

jsonEncoder := NewSensitiveFieldsEncoder(productionCfg)

. . .

return zap.New(samplingCore)
}

这段代码确保 email 属性被编辑,而其他字段保持不变:

1
{"level":"info","timestamp":"2023-05-17T17:38:11.749+0100","msg":"user login","user":{"id":"USR-12345","name":"John Doe","email":"[REDACTED]"}}

当然,如果 User 类型被记录在不同的键下,比如 user_details ,这样做就不会有太大帮助。您可以移除 if field.Key == "user" 条件,以确保无论提供的键是什么,都会执行编辑。

自定义编码器的一些注意事项

在使用Zap的自定义编码时,就像在前一节中一样,您可能还需要在 zapcore.Encoder 接口上实现 Clone() 方法,以便它也适用于使用 With() 方法创建的子记录器:

1
2
child := logger.With(zap.String("name", "main"))
child.Info("an info log", zap.Any("user", u))

在实施 Clone() 之前,您会注意到自定义 EncodeEntry() 不会为子记录器执行,导致电子邮件字段显示为未编辑状态:

1
{"level":"info","timestamp":"2023-05-20T09:14:46.043+0100","msg":"an info log","name":"main","user":{"id":"USR-12345","name":"John Doe","email":"john.doe@example.com"}}

With() 用于创建子记录器时,将执行配置的 Encoder 上的 Clone() 方法来复制它,并确保添加的字段不会影响原始记录器。 如果在自定义编码器类型上未实现此方法,则将调用嵌入的 zapcore.Encoder(在本例中为JSON编码器)上声明的 Clone() 方法,这意味着子记录器将不使用您的自定义编码。

您可以通过以下方式实现 Clone() 方法来纠正这种情况:

1
2
3
4
5
func (e *SensitiveFieldEncoder) Clone() zapcore.Encoder {
return &SensitiveFieldEncoder{
Encoder: e.Encoder.Clone(),
}
}

您现在将观察到正确的已编辑输出:

1
{"level":"info","timestamp":"2023-05-20T09:28:31.231+0100","msg":"an info log","name":"main","user":{"id":"USR-12345","name":"John Doe","email":"[REDACTED]"}}

然而,请注意,自定义编码器不会影响使用 With() 方法附加的字段,因此如果您这样做:

1
2
child := logger.With(zap.String("name", "main"), zap.Any("user", u))
child.Info("an info log")

无论是否实现 Clone(),您都将获得先前的未编辑输出,因为 EncodeEntry() 的参数中只有在日志点添加的字段存在:

1
{"level":"info","timestamp":"2023-05-20T09:31:11.919+0100","msg":"an info log","name":"main","user":{"id":"USR-12345","name":"John Doe","email":"john.doe@example.com"}}

将 Zap 用作 Slog 的后端

Go 语言引入了新的结构化日志包Slog后,开始着手在 Zap 中实现 slog.Handler 接口,以便利用 Slog APIZap 后端。这种集成确保了在各种依赖项中日志 API 的一致性,并便于无需大幅更改代码即可无缝切换日志包。

目前为止,Slog 尚未包含在官方的 Go 发布版本中。因此,ZapSlog 的官方集成已经提供在一个单独的模块中,可以使用以下命令进行安装:

1
go get go.uber.org/zap/exp/zapslog

之后,您可以在您的程序中像这样使用它:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
func main() {
logger := zap.Must(zap.NewProduction())

defer logger.Sync()

sl := slog.New(zapslog.NewHandler(zapL.Core(), nil))

sl.Info(
"incoming request",
slog.String("method", "GET"),
slog.String("path", "/api/user"),
slog.Int("status", 200),
)
}

输出:

1
{"level":"info","ts":1684613929.8395753,"msg":"incoming request","method":"GET","path":"/api/user","status":200}

如果您决定切换到不同的后端,唯一需要更改的是 slog.New() 方法的参数。例如,您可以通过进行以下更改从 Zap 切换到 SlogJSONHandler 后端:

1
2
3
4
5
6
7
8
9
10
func main() {
sl := slog.New(slog.NewJSONHandler(os.Stdout, nil))

sl.Info(
"incoming request",
slog.String("method", "GET"),
slog.String("path", "/api/user"),
slog.Int("status", 200),
)
}

除了日志输出可能会根据您的配置略有不同之外,其他一切都应该继续正常工作。

1
{"time":"2023-05-20T21:21:43.335894635+01:00","level":"INFO","msg":"incoming request","method":"GET","path":"/api/user","status":200}

总结

本文分析了 Zap 包,这是 Go 程序中最受欢迎的日志包之一。文章重点介绍了该包的许多关键特性,还涵盖了一些高级日志技术,以及如何将其与新的标准库 Slog 包集成。

前言

Zerolog 是一个高性能、零内存分配的 Go 日志库。它为不需要垃圾回收的延迟敏感型应用程序提供结构化日志记录功能。您可以以完全零分配的方式使用,这样在初始化记录器对象后,堆上不会再分配其他对象,从而防止触发垃圾回收。

本教程将解释如何在 Go 应用程序中安装、设置和使用 Zerolog 记录器。我们将首先介绍它的 API 和它提供的所有选项,并展示如何以各种方式自定义它们。最后,我们将描述如何在典型的 Web 应用程序中使用它,以便您可以很好地了解如何在您的项目中采用它。

开始使用 Zerolog

我们可以通过下面的命令安装 Zerolog 到我们的 Go 项目中:

1
go get -u github.com/rs/zerolog/log

该库提供了一个预配置且全局可用的 logger,您可以通过 zerolog/log 软件包在任何文件中导入和使用该 logger

1
2
3
4
5
6
7
8
9
package main

import (
"github.com/rs/zerolog/log"
)

func main() {
log.Info().Msg("Hello from Zerolog global logger")
}

上述程序将 JSON 格式的日志条目输出到控制台:

1
{"level":"info","time":"2023-08-18T13:45:51+01:00","message":"Hello from global logger"}

默认情况下,全局 logger 打印为标准错误,并且它还配置为在级别 TRACE 上记录,尽管您可以通过调用主 zerolog 包提供的 SetGlobalLevel() 函数来设置不同的最小级别:

1
2
3
4
5
6
7
8
9
10
11
12
package main

import (
"github.com/rs/zerolog"
"github.com/rs/zerolog/log"
)

func main() {
zerolog.SetGlobalLevel(zerolog.ErrorLevel)
log.Info().Msg("Info message")
log.Error().Msg("Error message")
}
1
{"level":"error","time":"2023-08-18T13:51:44+01:00","message":"Error message"}

除了 JSON 日志记录外,您还可以配置 Zerolog 以输出以 CBOR 格式编码的二进制日志。您可以在编译应用程序时使用 binary_log build 标记来启用它:

1
go build -tags binary_log .

执行生成的二进制文件时,您将看到如下所示的输出:

1
�eleveleerrordtime��A�lׂ�p�gmessagemError message�% 

注意:不是我的文章乱码,而是执行生成的二进制文件输出的就是这样的乱码。这是因为它是二进制的格式的,不是 ASCII 格式的。

您可以使用任何 CBOR 解码器(例如 csd)将此二进制日志条目解码为 JSON:

1
./main 2> >(csd)

输出:

1
{"level":"error","time":"2023-08-31T11:57:18.764748096-07:00","message":"Error message"}

我们的系统可能还没有安装 csd,我们可以通过 go install github.com/toravir/csd@0.1.0 命令来进行安装。

如果您的日志条目很大,并且您希望压缩它们以进行长期存储,您可能会发现以 CBOR 格式输出日志很有用,并且在需要时可以毫不费力地转换回 JSON。

探索 Zerolog API

Zerolog 提供了一个简单易懂的结构化日志记录 API。其 Logger 类型表示写入某个 io.Writer 接口的任何活动记录器,对于全局记录器 (zerolog/log),该接口为 os.Stderr 。您可以使用以下 zerolog.New() 方法创建新的自定义 Logger

1
2
3
4
5
6
7
8
9
10
11
12
package main

import (
"os"

"github.com/rs/zerolog"
)

func main() {
logger := zerolog.New(os.Stdout)
logger.Trace().Msg("Trace message")
}

输出:

1
{"level":"trace","message":"Trace message"}

日志级别

每个记录器都提供了一个对应于 Zerolog 提供的七个日志级别的方法,下面列出了这些级别及其整数优先级值:

  • TRACE(-1):用于跟踪代码执行路径
  • DEBUG(0): 对故障排除有用的信息
  • INFO(1): 描述应用程序正常运行的信息
  • WARNING(2): 对于需要的记录事件,以后可能需要检查
  • ERROR(3): 特定操作的错误信息
  • FATAL(4): 应用程序无法恢复的严重错误。os.Exit(1) 在记录消息后调用
  • PANIC(5): 与 FATAL 类似,但只是名字改成了 PANIC()

您可以通过 Level() 方法将上述任何级别设置为自定义 Logger 的最低级别。您可以传递上面所示的整数优先级数,也可以使用 zerolog 包上提供的级别常量(TraceLevelDebugLevel,等):

1
logger := zerolog.New(os.Stdout).Level(zerolog.InfoLevel)

上述代码片段仅输出比 INFO 更高级别的日志。您还可以通过环境变量设置最小级别(在本教程后面部分演示)。

将上下文数据添加到日志中

当你调用与所选日志级别相对应的方法(Info()Debug()等)时,将返回一个 zerolog.Event 类型,该类型代表一个日志事件。这个 Event 类型提供了几个方法,允许你向其上下文添加属性(以键值对的形式),以便日志条目包含足够的上下文数据,帮助你理解事件。例如,当记录在服务器上创建资源时,你可以在日志中包含用户 ID 或客户端信息(如 IP 地址),这样以后通过这些属性轻松过滤日志。

Event 类型上的大多数方法都返回一个指向 Event 的指针,因此你可以在日志点上根据需要链式调用它们。一旦向 Event 添加了所有必要的上下文,你必须调用其中一个 Msg()Msgf()MsgFunc()Send() 方法来完成 Event 的记录。通常,Msg() 方法将用于通过向日志条目添加消息字段来关闭 Event

1
2
3
4
5
logger.Info().
Str("name", "john").
Int("age", 22).
Bool("registered", true).
Msg("new signup!")

输出:

1
{"level":"info","name":"john","age":22,"registered":true,"message":"new signup!"}

如果要省略该 message 字段,可以调用 Msg() 或改用 Send() 来代替(不传参数):

1
2
3
4
5
logger.Info().
Str("name", "john").
Int("age", 22).
Bool("registered", true).
Send()

输出:

1
{"level":"info","name":"john","age":22,"registered":true}

请注意,必须始终在 zerolog.Event 上最后调用一个事件关闭方法,以便记录相应的条目。如果未使用这些方法,则不会记录日志条目。

1
2
3
4
logger.Info().
Str("name", "john").
Int("age", 22).
Bool("registered", true)

这不会有任何日志记录。

此外,除了要记得调用事件关闭方法外,也不要在一个 event 对象上调用多次事件关闭方法。

向 logger 添加全局上下文

在上一节中,您了解了如何使用 zerolog.Event 类型上的方法将相关上下文添加到日志条目。本节将更进一步,向您展示如何将上下文数据添加到 Logger 其本身,以确保此类数据包含在记录器生成的所有后续记录中。

有两种主要方法可以向 Zerolog Logger 添加上下文。第一种涉及使用返回 zerolog With() 的方法。上下文实例,允许您通过与 zerolog.Event 类型类似的字段方法向键值对中的记录器添加其他属性。然后,在将必要的数据添加到上下文后,必须调用该 Logger() 方法以返回具有更新上下文的新 Logger 对象。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
package main

import (
"os"

"github.com/rs/zerolog"
)

func main() {
logger := zerolog.New(os.Stdout).With().Timestamp().Logger()

logger.Info().Msg("info message")
logger.Debug().Str("username", "joshua").Send()
}

输出日志:

1
2
{"level":"info","time":"2023-08-31T21:00:29+01:00","message":"info message"}
{"level":"debug","username":"joshua","time":"2023-08-31T21:00:29+01:00"}

上面的代码片段将该 time 字段添加到 生成的所有记录中,这很有意义,因为所有日志记录都应包含时间戳。您还可以将文件和行号添加到所有日志条目中,如下所示:

1
2
3
4
5
6
func main() {
logger := zerolog.New(os.Stdout).With().Timestamp().Caller().Logger()

logger.Info().Msg("info message")
logger.Debug().Str("username", "joshua").Send()
}

输出日志:

1
2
{"level":"info","time":"2023-08-31T21:20:04+01:00","caller":"/home/user/dev/main.go:12","message":"info message"}
{"level":"debug","username":"joshua","time":"2023-08-31T21:20:04+01:00","caller":"/home/user/dev/main.go:13"}

由于该方法返回一个全新的 Logger,您可以使用该 Logger() With() 方法实现子记录器,这些子记录器使用相关元数据注释特定范围内的所有日志 Logger,以将它们与其他记录区分开来。下面是一个人为的例子,演示了这是如何工作的:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
package main

import (
"os"

"github.com/rs/zerolog"
)

var logger = zerolog.New(os.Stdout).With().Timestamp().Logger()

func main() {
mainLogger := logger.With().Str("service", "main").Logger()
mainLogger.Info().Msg("main logger message")

auth()
admin()
}

func auth() {
authLogger := logger.With().Str("service", "auth").Logger()
authLogger.Info().Msg("auth logger message")
}

func admin() {
adminLogger := logger.With().Str("service", "admin").Logger()
adminLogger.Info().Msg("admin logger message")
}

输出:

1
2
3
{"level":"info","service":"main","time":"2023-08-31T21:13:51+01:00","message":"main logger message"}
{"level":"info","service":"auth","time":"2023-08-31T21:13:51+01:00","message":"auth logger message"}
{"level":"info","service":"admin","time":"2023-08-31T21:13:51+01:00","message":"admin logger message"}

将元数据全局化为 Logger 的第二种方法是使用 UpdateContext() 方法。此方法就地更新 Logger 的内部上下文(无需创建副本),您可以像这样使用它:

1
2
3
4
5
6
7
8
9
func main() {
logger := zerolog.New(os.Stdout).With().Timestamp().Logger()

logger.UpdateContext(func(c zerolog.Context) zerolog.Context {
return c.Str("name", "john")
})

logger.Info().Msg("info message")
}

输出日志:

1
{"level":"info","name":"john","time":"2023-09-01T09:25:20+01:00","message":"info message"}

在开发中美化日志

在开发环境中,您可能会发现以更易于阅读的格式从应用程序输出日志条目会很有帮助,这样就可以轻松发现各种事件,而不会被不相关的符号和字段分散注意力。Zerolog 提供了一个 ConsoleWriter 类型,用于解析原始 JSON 条目,并将其以彩色格式输出到控制台。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
package main

import (
"os"
"runtime/debug"
"time"

"github.com/rs/zerolog"
)

func main() {
buildInfo, _ := debug.ReadBuildInfo()

logger := zerolog.New(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339}).
Level(zerolog.TraceLevel).
With().
Timestamp().
Caller().
Int("pid", os.Getpid()).
Str("go_version", buildInfo.GoVersion).
Logger()

logger.Trace().Msg("trace message")
logger.Debug().Msg("debug message")
logger.Info().Msg("info message")
logger.Warn().Msg("warn message")
logger.Error().Msg("error message")
logger.WithLevel(zerolog.FatalLevel).Msg("fatal message")
logger.WithLevel(zerolog.PanicLevel).Msg("panic message")
}

输出:

1
2
3
4
5
6
7
2024-01-26T16:12:09+08:00 TRC main.go:23 > trace message go_version=go1.20.2 pid=41079
2024-01-26T16:12:09+08:00 DBG main.go:24 > debug message go_version=go1.20.2 pid=41079
2024-01-26T16:12:09+08:00 INF main.go:25 > info message go_version=go1.20.2 pid=41079
2024-01-26T16:12:09+08:00 WRN main.go:26 > warn message go_version=go1.20.2 pid=41079
2024-01-26T16:12:09+08:00 ERR main.go:27 > error message go_version=go1.20.2 pid=41079
2024-01-26T16:12:09+08:00 FTL main.go:28 > fatal message go_version=go1.20.2 pid=41079
2024-01-26T16:12:09+08:00 PNC main.go:29 > panic message go_version=go1.20.2 pid=41079

上面这个不够直观,下面这个才是实际效果:

您可以使用 ConsoleWriter 类型上提供的选项来自定义输出的外观和格式:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
zerolog.ConsoleWriter{
Out: os.Stderr,
TimeFormat: time.RFC3339,
FormatLevel: func(i interface{}) string {
return strings.ToUpper(fmt.Sprintf("[%s]", i))
},
FormatMessage: func(i interface{}) string {
return fmt.Sprintf("| %s |", i)
},
FormatCaller: func(i interface{}) string {
return filepath.Base(fmt.Sprintf("%s", i))
},
PartsExclude: []string{
zerolog.TimestampFieldName,
},
}

输出:

1
2
3
4
5
6
7
[TRACE] main.go:41 | trace message | go_version=go1.20.2 pid=41171
[DEBUG] main.go:42 | debug message | go_version=go1.20.2 pid=41171
[INFO] main.go:43 | info message | go_version=go1.20.2 pid=41171
[WARN] main.go:44 | warn message | go_version=go1.20.2 pid=41171
[ERROR] main.go:45 | error message | go_version=go1.20.2 pid=41171
[FATAL] main.go:46 | fatal message | go_version=go1.20.2 pid=41171
[PANIC] main.go:47 | panic message | go_version=go1.20.2 pid=41171

实际效果如下:

请注意,时间戳现在是如何从输出中排除的,以及日志级别、调用方信息和日志消息的格式有何不同。格式化的字段也不再着色,但您可以使用 ptermgookit/color 等库来着色输出。

注意不要在生产环境中使用 , ConsoleWriter 因为它会大大减慢日志记录的速度。它只是为了帮助在开发应用程序时使日志更易于阅读。您可以使用环境变量仅在开发中启用 ConsoleWriter 输出:

1
2
3
4
var output io.Writer = zerolog.ConsoleWriter{...}
if os.Getenv("GO_ENV") != "development" {
output = os.Stderr
}

使用 Zerolog 进行日志采样

采样是一种用于有意删除重复日志条目的技术,以便只保留和处理其中的一部分。当您的高流量应用程序生成大量记录时,这很有帮助,并且存储每一条记录将导致过高的存储和处理成本,这可能是不可取的。采样通过防止每秒记录数百或数千次相同的日志来解决此问题,从而防止资源浪费。

以下是使用 Zerolog 对日志进行采样的最基本方法:

1
2
3
4
5
6
7
8
9
10
11
func main() {
log := zerolog.New(os.Stdout).
With().
Timestamp().
Logger().
Sample(&zerolog.BasicSampler{N: 5})

for i := 1; i <= 10; i++ {
log.Info().Msgf("a message from the gods: %d", i)
}
}

在此示例中,配置为每条日志在五次中仅记录一次。这在 for 循环中进行了演示,其中 INFO 消息通常被记录十次,但由于采样,它只被记录两次:

1
2
{"level":"info","time":"2023-09-02T08:05:48+01:00","message":"a message from the gods: 1"}
{"level":"info","time":"2023-09-02T08:05:48+01:00","message":"a message from the gods: 6"}

Zerolog 提供了其他更复杂的采样器,可能更适合您的应用。例如, BurstSampler 可用于限制在一段时间内记录的日志数:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
func main() {
l := zerolog.New(os.Stdout).
With().
Timestamp().
Logger().
Sample(&zerolog.BurstSampler{
Burst: 3,
Period: 1 * time.Second,
})

for i := 1; i <= 10; i++ {
l.Info().Msgf("a message from the gods: %d", i)
l.Warn().Msgf("warn message: %d", i)
l.Error().Msgf("error message: %d", i)
}
}

在这里, BurstSampler 配置限制每 Logger 秒生成三个以上的日志条目。本来应该在指定范围内记录的所有其他记录都将被丢弃。上面的循环应该记录 30 条消息而不进行采样,但由于上面的 for 配置,它只记录了 3 条:

1
2
3
{"level":"info","time":"2023-09-02T08:20:47+01:00","message":"a message from the gods: 1"}
{"level":"warn","time":"2023-09-02T08:20:47+01:00","message":"warn message: 1"}
{"level":"error","time":"2023-09-02T08:20:47+01:00","message":"error message: 1"}

您只能对特定级别进行抽样,如下所示:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
burstSampler := &zerolog.BurstSampler{
Burst: 3,
Period: 1 * time.Second,
NextSampler: &zerolog.BasicSampler{N: 5},
}

l := zerolog.New(os.Stdout).
With().
Timestamp().
Logger().
Sample(zerolog.LevelSampler{
WarnSampler: burstSampler,
InfoSampler: burstSampler,
})

在这里,将仅对 INFOWARN 日志进行采样,而其他日志将照常记录,从而产生以下输出:

1
2
3
4
5
6
7
8
9
10
11
12
13
{"level":"info","time":"2023-09-02T08:26:42+01:00","message":"a message from the gods: 1"}
{"level":"warn","time":"2023-09-02T08:26:42+01:00","message":"warn message: 1"}
{"level":"error","time":"2023-09-02T08:26:42+01:00","message":"error message: 1"}
{"level":"info","time":"2023-09-02T08:26:42+01:00","message":"a message from the gods: 2"}
{"level":"error","time":"2023-09-02T08:26:42+01:00","message":"error message: 2"}
{"level":"error","time":"2023-09-02T08:26:42+01:00","message":"error message: 3"}
{"level":"error","time":"2023-09-02T08:26:42+01:00","message":"error message: 4"}
{"level":"error","time":"2023-09-02T08:26:42+01:00","message":"error message: 5"}
{"level":"error","time":"2023-09-02T08:26:42+01:00","message":"error message: 6"}
{"level":"error","time":"2023-09-02T08:26:42+01:00","message":"error message: 7"}
{"level":"error","time":"2023-09-02T08:26:42+01:00","message":"error message: 8"}
{"level":"error","time":"2023-09-02T08:26:42+01:00","message":"error message: 9"}
{"level":"error","time":"2023-09-02T08:26:42+01:00","message":"error message: 10"}

如您所见, INFO 该消息被记录两次, WARN 记录一次(总共 3 个日志),而所有 10 个 ERROR 日志都被记录下来,因为它没有被采样。如果希望对每个级别进行不同的采样,则必须为每个级别创建不同的采样策略,例如 infoSampler warnSampler 等 。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
func main() {
infoSampler := &zerolog.BurstSampler{
Burst: 3,
Period: 1 * time.Second,
}

warnSampler := &zerolog.BurstSampler{
Burst: 3,
Period: 1 * time.Second,
// Log every 5th message after exceeding the burst rate of 3 messages per
// second
NextSampler: &zerolog.BasicSampler{N: 5},
}

errorSampler := &zerolog.BasicSampler{N: 2}

l := zerolog.New(os.Stdout).
With().
Timestamp().
Logger().
Sample(zerolog.LevelSampler{
WarnSampler: warnSampler,
InfoSampler: infoSampler,
ErrorSampler: errorSampler,
})

for i := 1; i <= 10; i++ {
l.Info().Msgf("a message from the gods: %d", i)
l.Warn().Msgf("warn message: %d", i)
l.Error().Msgf("error message: %d", i)
}
}

在此方案中,为 INFOWARNERROR 级别定义了不同的采样策略,而其他级别则正常记录。infoSampler 是我们在上一个代码片段中使用的示例配置(每秒记录 3 条消息并丢弃所有其他消息),而 warnSampler 使用该 NextSampler 属性在超过突发速率后记录每 5 条消息。errorSampler 使用 BasicSampler 策略,并记录每秒一条日志消息。此配置产生以下结果:

1
2
3
4
5
6
7
8
9
10
11
12
13
{"level":"info","time":"2023-09-02T08:40:58+01:00","message":"a message from the gods: 1"}
{"level":"warn","time":"2023-09-02T08:40:58+01:00","message":"warn message: 1"}
{"level":"error","time":"2023-09-02T08:40:58+01:00","message":"error message: 1"}
{"level":"info","time":"2023-09-02T08:40:58+01:00","message":"a message from the gods: 2"}
{"level":"warn","time":"2023-09-02T08:40:58+01:00","message":"warn message: 2"}
{"level":"info","time":"2023-09-02T08:40:58+01:00","message":"a message from the gods: 3"}
{"level":"warn","time":"2023-09-02T08:40:58+01:00","message":"warn message: 3"}
{"level":"error","time":"2023-09-02T08:40:58+01:00","message":"error message: 3"}
{"level":"warn","time":"2023-09-02T08:40:58+01:00","message":"warn message: 4"}
{"level":"error","time":"2023-09-02T08:40:58+01:00","message":"error message: 5"}
{"level":"error","time":"2023-09-02T08:40:58+01:00","message":"error message: 7"}
{"level":"warn","time":"2023-09-02T08:40:58+01:00","message":"warn message: 9"}
{"level":"error","time":"2023-09-02T08:40:58+01:00","message":"error message: 9"}

请注意消息的记录方式 (在一秒内生成的所有其他 INFO 消息将被丢弃), WARN 消息在突发速率之后记录三次, 并根据 NextSampler 属性中定义的策略再记录两次。最后,ERROR 消息被记录五次,而不是十次(1/2)。

Zerolog 还提供了全局 DisableSampling() 方法,用于在所有 Logger 中启用或禁用所有形式的采样。它采用一个布尔参数来控制是启用还是禁用日志采样,当您需要动态更新配置以响应某些事件时,这可能很有帮助。

Zerolog 中的钩子

Zerolog 提供了一种通过 Hook 接口挂接到日志记录过程的方法,定义如下:

1
2
3
4
type Hook interface {
// Run runs the hook with the event.
Run(e *zerolog.Event, level zerolog.Level, message string)
}

在具体类型上实现 Hook 接口时,可以使用 Logger.Hook() 方法将其应用于 Logger,以便在每次记录日志时执行其 Run() 方法。然后,您可以根据事件的日志级别或一些其他条件运行不同的操作。

下面是一个示例,该示例将记录在 ERROR 级别或更高级别的消息发送到 Telegram 频道:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
package main

import (
"context"
"os"
"time"

"github.com/nikoksr/notify"
"github.com/nikoksr/notify/service/telegram"
"github.com/rs/zerolog"
)

var wg sync.WaitGroup

type TelegramHook struct{}

func (t *TelegramHook) Run(
e *zerolog.Event,
level zerolog.Level,
message string,
) {
if level > zerolog.WarnLevel {
wg.Add(1)
go func() {
_ = notifyTelegram("", message)
wg.Done()
}()
}
}

func notifyTelegram(title, msg string) error {
telegramService, err := telegram.New(
"<telegram bot token>",
)
if err != nil {
return err
}

telegramService.AddReceivers("<chat id>")

notifier := notify.New()

notifier.UseServices(telegramService)

ctx, cancel := context.WithTimeout(
context.Background(),
30*time.Second,
)

defer cancel()

return notifier.Send(ctx, title, msg)
}

func main() {
logger := zerolog.New(os.Stdout).
Level(zerolog.TraceLevel).
With().
Timestamp().
Logger()

logger = logger.Hook(&TelegramHook{})

logger.Trace().Msg("trace message")
logger.Debug().Msg("debug message")
logger.Info().Msg("info message")
logger.Warn().Msg("warn message")
logger.Error().Msg("error message")
logger.WithLevel(zerolog.FatalLevel).Msg("fatal message")
logger.WithLevel(zerolog.PanicLevel).Msg("panic message")

wg.Wait()
}

上面的程序创建了一个 TelegramHook 实现接口的 zerolog.Hook 类型。它的 Run() 方法检查所记录消息的级别,如果它比 WARN 级别更严重,则将其发送到 Telegram 频道。如果运行该程序(在替换上面突出显示的占位符之后),您将观察到每条日志消息都打印到控制台,并且 ERRORFATALPANIC 日志也会发送到配置的 Telegram 通道。

使用 Zerolog 记录错误

使用 Zerolog 记录错误的最简单方法是在 ERROR 级别进行记录,并在 Err() 生成的 zerolog.Event。这会将一个 error 属性添加到日志条目中,其中包含相关错误的详细信息:

1
2
3
logger.Error().
Err(errors.New("file open failed")).
Msg("something happened!")

输出:

1
{"level":"error","error":"file open failed","time":"2023-08-31T22:59:07+01:00","message":"something happened!"}

您可以通过更改以下 zerolog.ErrorFieldName 的值将错误的字段名称更改为其他值:

1
2
3
4
5
zerolog.ErrorFieldName = "err"

logger.Error().
Err(errors.New("file open failed")).
Msg("something happened!")

输出:

1
{"level":"error","err":"file open failed","time":"2023-08-31T22:59:07+01:00","message":"something happened!"}

虽然上面的输出提供了有关所发生错误的详细信息,但它不显示导致错误的代码执行路径,这对于调试问题至关重要。您可以通过 Event 上的 Stack() 方法在错误日志中包含堆栈跟踪来解决此问题,但在它生效之前,必须分配给 zerolog.ErrorStackMarshaler 可以从错误中提取堆栈跟踪的函数。您可以将 pkg/errorszerolog/pkgerrors 帮助程序结合使用,以将堆栈跟踪添加到错误日志中,如下所示:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
package main

import (
"os"

"github.com/pkg/errors"

"github.com/rs/zerolog"
"github.com/rs/zerolog/pkgerrors"
)

func main() {
zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack

logger := zerolog.New(os.Stdout).With().Timestamp().Logger()
logger.Error().
Stack().
Err(errors.New("file open failed!")).
Msg("something happened!")
}

输出:

1
{"level":"error","stack":[{"func":"main","line":"19","source":"main.go"},{"func":"main","line":"250","source":"proc.go"},{"func":"goexit","line":"1594","source":"asm_amd64.s"}],"error":"file open failed!","time":"2023-08-24T21:52:24+01:00","message":"something happened!"}

请注意,该 stack 属性如何包含一个 JSON 格式的堆栈跟踪,该跟踪描述导致错误的程序执行。在调查应用程序中的意外错误时,此信息可能非常宝贵。

还可以使用 FATALPANIC 级别来记录应用程序无法恢复的特别严重的错误。请注意,FATAL 级别在进行日志记录会导致程序立即退出,退出状态为 1。而 PANIC 级别将调用 panic()

1
2
err := errors.New("failed to connect to database")
logger.Fatal().Err(err).Msg("something catastrophic happened!")

输出:

1
2
{"level":"fatal","error":"failed to connect to database","time":"2023-09-01T09:34:49+01:00","message":"something catastrophic happened!"}
exit status 1

如果要在不调用 panic 或者 os.Exit(1) 的情况下记录 FATAL 或者 PANIC 级别的消息,则必须使用如下所示 WithLevel() 的方法:

1
2
3
4
err := errors.New("failed to connect to database")
logger.WithLevel(zerolog.FatalLevel).
Err(err).
Msg("something catastrophic happened!")

程序将不再立即退出,但事件仍记录在适当的级别:

1
{"level":"fatal","error":"failed to connect to database","time":"2023-09-01T09:35:27+01:00","message":"something catastrophic happened!"}

记录到文件

使用 Zerolog 写入日志文件的选项与使用标准库日志包时的选项几乎相同。由于可以将实现 io.Writer 接口的类型传递给 zerolog.New() 方法,因此只要使用适当的权限打开文件,任何 os.File 实例都将按预期工作。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
package main

import (
"os"

"github.com/rs/zerolog"
)

func main() {
file, err := os.OpenFile(
"myapp.log",
os.O_APPEND|os.O_CREATE|os.O_WRONLY,
0664,
)
if err != nil {
panic(err)
}

defer file.Close()

logger := zerolog.New(file).With().Timestamp().Logger()

logger.Info().Msg("Info message")
}

执行上述程序后,您会注意到当前目录中存在一个 myapp.log 文件。您可以查看其内容,以验证登录文件是否按预期工作:

1
cat myapp.log

输出:

1
{"level":"info","time":"2023-08-27T11:38:27+01:00","message":"Info message"}

在 Web 应用程序中使用 Zerolog

我们可以通过下面的方式来定义一个 logger

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
package logger

import (
"io"
"os"
"runtime/debug"
"strconv"
"sync"
"time"

"github.com/rs/zerolog"
"github.com/rs/zerolog/pkgerrors"
"gopkg.in/natefinch/lumberjack.v2"
)

var once sync.Once

var log zerolog.Logger

func Get() zerolog.Logger {
once.Do(func() {
zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack
zerolog.TimeFieldFormat = time.RFC3339Nano

logLevel, err := strconv.Atoi(os.Getenv("LOG_LEVEL"))
if err != nil {
logLevel = int(zerolog.InfoLevel) // 默认为 INFO
}

var output io.Writer = zerolog.ConsoleWriter{
Out: os.Stdout,
TimeFormat: time.RFC3339,
}

if os.Getenv("APP_ENV") != "development" {
fileLogger := &lumberjack.Logger{
Filename: "demo.log",
MaxSize: 5,
MaxBackups: 10,
MaxAge: 14,
Compress: true,
}

output = zerolog.MultiLevelWriter(os.Stderr, fileLogger)
}

var gitRevision string

buildInfo, ok := debug.ReadBuildInfo()
if ok {
for _, v := range buildInfo.Settings {
if v.Key == "vcs.revision" {
gitRevision = v.Value
break
}
}
}

log = zerolog.New(output).
Level(zerolog.Level(logLevel)).
With().
Timestamp().
Str("git_revision", gitRevision).
Str("go_version", buildInfo.GoVersion).
Logger()
})

return log
}

在此文件中,Get() 函数返回一个 zerolog.Logger 实例,该实例已根据 LOG_LEVEL 环境变量(如果存在且是有效数字)配置了最小级别,否则默认为 INFO 级别。 APP_ENV 环境变量还用于指定 ConsoleWriter API 应用于仅在开发环境中美化日志输出(发送到标准错误)。在其他环境(如暂存或生产)中,通过使用 lumberjack 库和 zerolog.MultiLevelWriter() 方法,日志被记录为标准错误和 demo.log 滚动日志文件。

请注意,Logger 初始化是在 once.Do() 方法的函数参数中完成的,因此无论调用多少次 Get() ,它都只初始化一次。

接着,我们就可以在我们的应用程序中使用这个 logger 了:

1
2
l := logger.Get()
l.Fatal().Err(err).Msg("test message")

创建日志记录中间件

现在我们的 Logger 实例已经准备就绪,我们可以创建一个中间件函数,将所有传入的 HTTP 请求记录到服务器。我们将使用它向每个日志条目添加上下文信息,例如请求数据、响应代码等。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
func requestLogger(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
start := time.Now()

l := logger.Get()

next.ServeHTTP(w, r)

l.
Info().
Str("method", r.Method).
Str("url", r.URL.RequestURI()).
Str("user_agent", r.UserAgent()).
Dur("elapsed_ms", time.Since(start)).
Msg("incoming request")
})
}

requestLogger() 函数返回一个 HTTP 处理程序,该处理程序记录有关 HTTP 请求的多个详细信息,例如请求 URL、HTTP 方法、客户端用户代理以及完成请求所花费的时间。您还可以 defer 记录调用,以确保如果处理程序发生崩溃,仍会记录请求,以便找出导致崩溃的原因。

软件开发严重依赖调试技术,这对于有效处理性能问题至关重要。用户在遇到程序执行缓慢时会感到沮丧,这凸显了通过调试工具有效识别和解决潜在问题的重要性。

但是,由于软件的创建和实现过程中涉及庞大的代码库或复杂的系统,因此调试软件中的性能问题可能很困难。

在 Go 中,开发人员可以使用强大的内置工具来帮助诊断和修复性能问题。其中两个工具是 pproftrace 包。

pprof 包允许您分析和分析 Go 程序的执行,而该 trace 包允许您跟踪和可视化事件和 goroutine 活动。当这些工具一起使用时,可以帮我们快速定位 Go 程序中导致性能低下的代码。

了解性能问题

Go 程序或任何软件应用程序中的性能问题都会对用户体验产生重大影响。Go 程序中的性能问题可能由于多种原因而发生。在本节中,我们将介绍性能问题的一些最常见原因以及它们如何影响系统。

  • 低效算法:低效算法会对性能产生重大影响,尤其是在处理大型数据集时。这些算法会占用额外的 CPU 周期和内存资源,这可能会降低整个应用程序的速度。比如暴力搜索方法和无效的排序算法。
  • 阻塞操作:应用程序可能偶尔会等待 I/O 活动完成,例如在磁盘上读取或写入数据或连接到网络。在此过程中,可能会发生阻塞操作并导致执行延迟,从而导致性能下降。当应用程序被阻塞时,它无法执行其他有用的任务,从而导致整体性能下降。
  • 内存使用率过高:使用大量内存的 Go 应用可能会导致性能问题,尤其是在资源不足的系统上。如果应用程序消耗的内存多于系统的可用内存,则系统可能会开始交换到磁盘,从而大大降低应用程序的性能。如果应用程序不能有效地管理内存,从而导致内存泄漏和其他问题,也会发生这种情况。

goroutine 泄漏也会导致内存使用率过高。另外,一些中间价比如 Elasticsearch 等,则建议直接禁用 swap,因为 swap 会导致性能下降,取而代之的是给它足够大的内容。

性能低下的应用程序会导致用户体验差,从而导致用户流失。为了获得最佳体验,优化 Go 应用程序至关重要。

使用 pprof 诊断性能问题

pprof 是 Go 中的一个内置包,它为开发人员提供了一个分析工具,用于观测他们的 Go 程序如何使用 CPU 和内存。然后收集和分析来自此测量的数据。借助 pprof 软件包,开发人员可以轻松测量和识别消耗比正常情况更多的 CPU 内存的函数,以及分配最多内存的程序部分。

让我们假设一个转账 App 使用 Go,并且它具有允许用户使用二维码向朋友汇款的功能。更新该功能后,其开发人员注意到该应用程序的运行速度比平时慢得多,40% 的用户抱怨扫描二维码时延迟长达 15 秒,有时付款失败。为了正确分析问题,开发团队可以在用户扫描二维码时使用 pprof 生成 CPU 分析文件。通过分析文件,他们可能会发现哪些函数占用了过多的 CPU 内存或哪些算法效率低下。在发现问题并修复问题后,他们可以再次测试和使用 pprof ,以确保性能得到提高,体验更快、更无缝。

pprof 的 profile 类型

  1. CPU:用于分析程序的 CPU 使用情况。衡量函数如何消耗不同的 CPU 时间,从而更容易识别哪些函数消耗更多时间,这些就可能是潜在的瓶颈。
  2. Memory:用于分析程序的内存使用情况。衡量应用程序如何使用内存以及应用程序的哪些部分分配更多内存。
  3. Block(阻塞):显示程序阻塞的位置(例如 I/O 或同步原语),从而更容易识别并发低下的区域。
  4. Goroutine(协程):通过返回正在运行、阻塞和等待的状态的 Goroutine,可以轻松检测到并发低下的区域。
  5. Trace:捕获程序执行期间发生的事件的详细日志,例如 goroutine 创建和销毁、调度、网络活动和阻塞操作。它在详细分析应用程序的性能时非常有用。

分析 profile

我们下面以一个例子来讲解一下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
package main

import (
"fmt"
"math/rand"
"os"
"runtime/pprof"
)

func main() {
// 创建一个保存 CPU 分析结果的文件
f, err := os.Create("profile.prof")
if err != nil {
panic(err)
}
defer f.Close()

// 开始采集 CPU 性能指标
if err := pprof.StartCPUProfile(f); err != nil {
panic(err)
}
defer pprof.StopCPUProfile()

// 模拟耗 CPU 的操作
for i := 0; i < 1000000; i++ {
n := rand.Intn(100)
_ = square(n)
}
}

func square(n int) int {
return n * n
}

在上面的代码中:

  • main 函数生成一个介于 1 和 1000 之间的随机数,然后计算其平方根。
  • pprof.StartCPUProfile(f) 函数启动 CPU 分析,从而创建可以在以后分析的 profile 文件。
  • defer pprof.StopCPUProfile() 语句确保在程序结束时停止 CPU 分析,无论程序是正常终止还是由于错误。
  • 我们调用 rand.Intn(100) 1000000 次来模拟 CPU 密集型任务。

接下来,我们执行这个程序:

1
go run main.go

程序运行结束后,会生成一个名为 profile.pprof 的文件,这个文件包含了 CPU 分析的数据。我们可以使用 go tool pprof 命令来分析这个文件:

1
go tool pprof profile.prof

接下来,会输出如下内容,并进入了一个交互式的命令行:

1
2
3
4
5
Type: cpu
Time: Jan 15, 2024 at 5:17pm (CST)
Duration: 205.21ms, Total samples = 10ms ( 4.87%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

我们可以接着输入一些命令,来查看 profile 的数据:

比如,我们可以输入 top 来查看最耗 CPU 的函数:

1
2
3
4
5
6
7
8
(pprof) top
Showing nodes accounting for 10ms, 100% of 10ms total
flat flat% sum% cum cum%
10ms 100% 100% 10ms 100% math/rand.(*Rand).Intn
0 0% 100% 10ms 100% main.main
0 0% 100% 10ms 100% math/rand.Intn (inline)
0 0% 100% 10ms 100% runtime.main
(pprof)

分析内存

若要获取内存配置文件,请修改代码以使用函数 pprof.WriteHeapProfile() 将堆配置文件写入文件。在生成随机数并计算其平方后,您需要添加代码以将内存配置文件写入文件(mem.prof)。您还将添加一个 time.Sleep(5 * time.Second) 调用,以便有时间将内存配置文件写入文件。在下面找到代码的更新版本:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
package main

import (
"fmt"
"math/rand"
"os"
"runtime/pprof"
"time"
)

func main() {
// 创建一个保存 CPU 分析结果的文件
cpuProfileFile, err := os.Create("cpu.prof")
if err != nil {
panic(err)
}
defer cpuProfileFile.Close()

// 开始采集 CPU 性能指标
if err := pprof.StartCPUProfile(cpuProfileFile); err != nil {
panic(err)
}
defer pprof.StopCPUProfile()

// 模拟耗 CPU 的操作
for i := 0; i < 10; i++ {
n := rand.Intn(100)
s := square(n)
fmt.Printf("%d^2 = %d\n", n, s)
}

// 创建一个保存内存分析结果的文件
memProfileFile, err := os.Create("mem.prof")
if err != nil {
panic(err)
}
defer memProfileFile.Close()

// 将内存分析结果写入文件
if err := pprof.WriteHeapProfile(memProfileFile); err != nil {
panic(err)
}
fmt.Println("Memory profile written to mem.prof")

time.Sleep(5 * time.Second)
}

func square(n int) int {
return n * n
}

输出:

1
2
3
4
5
6
7
8
9
10
11
31^2 = 961
83^2 = 6889
88^2 = 7744
86^2 = 7396
14^2 = 196
99^2 = 9801
42^2 = 1764
29^2 = 841
86^2 = 7396
86^2 = 7396
Memory profile written to mem.prof

运行 go run main.go 后,将生成一个 mem.prof 文件。在交互式 shell 中,键入 top 以分析程序的内存使用情况。若要显示此交互式 shell,请运行以下命令:

1
go tool pprof mem.prof

要按 CPU 使用率显示排名靠前的函数,请键入 top 命令:

1
2
3
4
5
6
7
8
9
10
11
➜ go tool pprof mem.prof    
Type: inuse_space
Time: Jan 15, 2024 at 5:22pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 1.72MB, 100% of 1.72MB total
flat flat% sum% cum cum%
1.72MB 100% 100% 1.72MB 100% runtime/pprof.StartCPUProfile
0 0% 100% 1.72MB 100% main.main
0 0% 100% 1.72MB 100% runtime.main
(pprof)

从上面的示例中可以看出,pprof 可以让我们很清楚地知道哪些函数占用了大量的内存或者 CPU。因此,通过将 profile 纳入开发过程,可以很容易地主动识别和解决性能问题,从而实现更快、更高效的应用程序。

在第一个示例中,我们了解了如何使用 pprof 工具创建 CPU 分析文件并对其进行分析。输出显示每个函数的调用次数,以及执行每个函数所花费的总时间。这使我们能够识别消耗最多 CPU 时间的函数,并可能对其进行优化。在第二个示例中,输出显示了每个函数的内存使用情况,包括分配的数量和分配的字节数。这使我们能够识别使用过多内存的函数,并可能对其进行优化以减少内存使用。

使用 trace 追踪

有时,我们需要有关程序如何运行的更多详细信息。在这种情况下,trace 包是一个非常强大和有用的工具。在本节中,我们将对其进行介绍。

trace 是一种工具,可让您收集有关程序运行方式的详细信息。它对于理解 goroutine 是如何创建和调度的、通道的使用方式以及网络请求的处理方式等内容非常有用。它提供了程序执行的时间线视图,可用于识别一段时间内的性能问题和其他类型的错误。

trace 可以收集有关程序运行时发生的各种事件的数据。这些事件包括:Goroutine 创建、销毁、阻塞、取消阻塞、网络活动和垃圾回收。每个 trace 事件都分配了一个时间戳和一个 goroutine ID,允许您查看事件的顺序以及它们之间的关系。

分析 trace 追踪数据

首先,我们将创建一个新的 go 文件,将其命名为 trace.go。若要生成跟踪数据,请导入 runtime/trace 包并在程序开始时调用 trace.Start 。若要停止跟踪收集,请在程序结束时调用 trace.Stop 。下面是它的样子:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
package main

import (
"fmt"
"math/rand"
"os"
"runtime/pprof"
"runtime/trace"
)

func main() {
// 创建一个保存 CPU 分析结果的文件
f, err := os.Create("profile.prof")
if err != nil {
panic(err)
}
defer f.Close()

// 开始采集 CPU 性能指标
if err := pprof.StartCPUProfile(f); err != nil {
panic(err)
}
defer pprof.StopCPUProfile()

// 创建一个保存 trace 追踪结果的文件
traceFile, err := os.Create("trace.out")
if err != nil {
panic(err)
}
defer traceFile.Close()

if err := trace.Start(traceFile); err != nil {
panic(err)
}
defer trace.Stop()

// 模拟耗 CPU 的操作
for i := 0; i < 10; i++ {
n := rand.Intn(100)
_ = square(n)
}
}

func square(n int) int {
return n * n
}

运行以下命令以启动程序:

1
go run main.go

要分析跟踪数据,可以使用 go tool trace 命令,后跟跟踪文件的名称:

1
go tool trace trace.out 

这将启动基于 Web 的跟踪数据可视化,您可以使用它来了解程序的运行方式并识别性能问题。

您还可以查看有关各种 goroutine 以及各种进程如何运行的详细信息!Trace 是了解各种流事件、goroutine 分析等等的绝佳工具!

分析和修复性能问题

使用 pproftrace 收集性能数据后,下一步是分析数据并确定可能的性能问题。

要解释 pprof 的输出,首先需要了解可用的各种类型的分析数据。最常见的配置文件类型是 CPU 和内存配置文件,就像前面引用的示例一样。通过分析这些配置文件,可以识别消耗大量资源并可能成为潜在瓶颈的功能。 pprof 还可以生成其他类型的配置文件,例如互斥锁争用和阻塞配置文件,这有助于确定同步和阻塞问题。例如,较高的互斥锁争用率可能表明多个 goroutine 正在争用同一个锁,这可能导致阻塞和性能不佳。

如前所述,跟踪数据包含有关应用程序行为的更全面的数据,例如 goroutines、阻塞操作和网络流量。跟踪数据分析可用于检测延迟源和其他性能问题,例如网络延迟过长或选择了效率低下的算法。

一旦确定了性能问题,有几种方法可以优化性能。一种常见的策略是通过重用对象来减少内存分配,同时减少大型数据结构的使用。通过减少可分配的内存量和垃圾回收量,可以降低 CPU 使用率并提高整体程序性能。

另一种方法是使用异步 I/O 或非阻塞操作来减少阻塞操作,例如文件 I/O 或网络通信。这有助于减少程序等待 I/O 操作完成所花费的时间,并提高整体程序吞吐量。

此外,优化算法和数据结构可以显著提高性能。通过选择更有效的算法和数据结构,可以减少完成操作所需的 CPU 时间,并提高整体程序性能。

总结

优化 Go 应用程序中的性能以确保它们高效且有效地运行非常重要。通过这样做,我们可以改善用户体验,降低运行应用程序的成本,并提高代码的整体质量。我们可以使用 pproftrace 工具来分析 CPU 和内存使用情况,并识别 Go 应用程序中的瓶颈和其他问题。然后,我们可以根据这些工具的输出对代码进行有针对性的改进,例如减少内存分配、最小化阻塞操作和优化算法。分析工具(如 pproftrace )对于识别和解决性能问题至关重要。

基本在所有的编程语言中,都有 map 这种数据结构,Go 语言也不例外。 我们知道 Go 是一门对并发支持得比较好的语言,但是 map 并不支持并发读写。 比如,下面这种写法是错误的:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
var m = make(map[int]int)
var wg sync.WaitGroup
wg.Add(2)
// 启动两个协程序同时写入 map
go func() {
for i := 0; i < 100; i++ {
m[i] = i
}
wg.Done()
}()
go func() {
for i := 0; i < 100; i++ {
m[i] = i
}
wg.Done()
}()
wg.Wait()

这样写会报错:

1
fatal error: concurrent map writes

为什么 Go map 不支持并发读写

这跟 map 的实现有关,根本原因是:map 的底层是支持自动扩容的,在添加元素的时候,如果发现容量不够,就会自动扩容。 如果允许扩容和访问操作同时发生,那么访问到的数据就不一定就是我们之前存放进去的了,所以 Go 从设计上就禁止了这种操作。 也就是 fail fast 的原则。

至于具体为什么,我们可以看看 map 在扩容时做了什么操作:

grow

上图来源于我之前写的一篇文章:go map 设计与实现

Go 中 map 的扩容是一个渐进的过程,在我们访问 map 的时候,会对 map 底层实际存储数据的桶进行迁移。

如果支持并发读写,就有可能会导致底层定位到的桶是扩容前的,但是实际上数据已经迁移到了新的桶中,这样就会导致访问到的并不是我们想要的数据。

Go map 设计上的考虑

在 Go 官网的博客上有专门针对 Go 不支持并发读写的说明,大概意思是:

经过长时间讨论,Go 团队认为,多数情况下,我们并不需要从多个 goroutine 来对 map 进行安全访问, map 可能是已经实现了同步的某些较大数据结构或计算的一部分。因此,如果底层再去实现 map 的互斥操作, 就会减慢大多数程序的速度,而只能增加少数程序的安全性。

也就是说,他们认为大多数情况下,map 通常是我们自定义数据结构的一部分,而对这个自定义数据结构的访问时,我们一般已经有了锁去保证并发读写安全了,所以没有必要再在底层的 map 上加锁,从而可以保证大多数程序的速度。

但是从语言层面上来说,我们依然可以自行通过互斥锁来实现 map 的的互斥访问。 仅当对 map 在进行更新的时候,map 的读才是不安全的,但是 map 是支持并发读的。

如何解决这个问题 - 互斥锁

关于这一点,同样可以在 Go 官方博客中找到相关的说明,在 Go map 并发这一节也给了对应的 demo。具体来说就是将一般锁跟 map 关联起来,要读写 map 的时候,得先获取这个锁才能访问,这样就避免了对 map 的并发读写了。这是最典型的一种解决方案,也是最简单的。

下面的结构体定义了一个匿名结构体 counter,这个结构体中包含了一个 sync.RWMutex 互斥锁和一个 map

1
2
3
4
var counter = struct{
sync.RWMutex
m map[string]int
}{m: make(map[string]int)}

读的时候,我们可以使用 RLock 获取读锁,然后访问 m 这个 map

1
2
3
4
counter.RLock()
n := counter.m["some_key"]
counter.RUnlock()
fmt.Println("some_key:", n)

RLock 是读锁,多个 goroutine 可以同时获取读锁,读锁释放之前,其他 goroutine 无法获取写锁。

写的时候,我们可以使用 Lock 获取写锁:

1
2
3
counter.Lock()
counter.m["some_key"]++
counter.Unlock()

Lock 是写锁,只有一个 goroutine 可以获取写锁,并且写锁释放之前,其他 goroutine 无法获取读锁,也无法获取写锁。

另一种解决方法 - sync.Map

除了使用互斥锁,我们也可以使用 Go 语言自带的 sync.Map 来解决这个问题:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
var m sync.Map
var wg sync.WaitGroup
wg.Add(2)
go func() {
for i := 0; i < 100; i++ {
m.Store(i, i)
}
wg.Done()
}()
go func() {
for i := 0; i < 100; i++ {
m.Store(i, i)
}
wg.Done()
}()
wg.Wait()

虽然 sync.Map 可以实现并发的读写,但是底层上依然会有较多的竞态条件,所以性能上并不是最好的,本质上还是操作一个 map, 只是通过一些原子操作 + 自旋锁来实现并发安全的读写。

而且 sync.Map 设计出来的时候是为了应对一些特定的场景的,具体来说有以下两个场景:

  1. 当给定 key 的条目只写入一次但读取多次时,如在只会增长的缓存中。(读多写少)
  2. 当多个 goroutine 读取、写入和覆盖不相交的键集的条目。(不同 goroutine 操作不同的 key)

在这两种情况下,可以获得比用 Mutex + mapRWMutex + map 更好的性能,因为很多的锁操作都变成了原子操作。

具体细节可参考我此前的一篇文章:《深入理解 go sync.Map - 基本原理》

互斥锁、sync.Map 还不是最优的解决方案

使用互斥锁或者 sync.Map 的方式,虽然都可以解决 map 并发读写的问题,但是性能上都不是最优的。

因为它们底层还是会有互斥锁的竞争。这就意味着,在进行写 map 操作时,可能会存在较多的锁竞争,从而导致性能下降。

map 分片

如果我们有了解过 MongoDB,就会知道,MongoDB 中也有分片的概念,当数据量过大时, 单个 MongoDB 实例可能无法存储所有的数据,或者单个实例无法处理过多的读写请求, 这时候就需要将数据分片存储到多个 MongoDB 实例中,也就是按照一定的规则将数据存储到不同的机器上, 然后读写数据的请求也会依据一定规则被路由到对应的机器上。

同样的,如果我们的 map 并发请求过多,那么我们也可以将 map 分片, 将不同的 key 存储到不同的 map 中,这样就可以避免 map 的并发读写了。

我们需要做的是:通过 key 来计算其 hash 值,然后根据 hash 值来决定将 key 存储到哪个 map 中, 同时,我们每一个 map 都需要加上互斥锁,这样就可以保证每一个 map 的并发安全了。

具体如下图:

shard

说明:

  1. 图中的 G0~2 表示 goroutinelock0~2 表示不同的互斥锁,map shard 0~2 表示多个 map 分片。
  2. goroutine 中会根据 key 计算出 hash 值,然后根据 hash 值来决定将 key 存储到哪个 map 分片中,然后获取这个分片对应的锁,然后进行读写操作。

虽然上图画起来是 G1 不会访问到 shard 0 或者 shard 2,但实际上是有可能的,上图只是想说明: 多个 goroutine 可以多个锁来访问多个 map 分片,而不用像之前那样多个 goroutine 都来竞争同一把锁了。 也就减少了锁的竞争和等待

代码实现

具体实现已经有一个开源的库了:orcaman/concurrent-map, 可以在 github 上搜到。

下面是它的部分代码:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
var SHARD_COUNT = 32


// A "thread" safe map of type string:Anything.
// To avoid lock bottlenecks this map is dived to several (SHARD_COUNT) map shards.
type ConcurrentMap[K comparable, V any] struct {
shards []*ConcurrentMapShared[K, V]
sharding func(key K) uint32
}

// A "thread" safe string to anything map.
type ConcurrentMapShared[K comparable, V any] struct {
items map[K]V
sync.RWMutex // Read Write mutex, guards access to internal map.
}

// GetShard returns shard under given key
func (m ConcurrentMap[K, V]) GetShard(key K) *ConcurrentMapShared[K, V] {
return m.shards[uint(m.sharding(key))%uint(SHARD_COUNT)]
}

说明:

  1. SHARD_COUNT 是分片数量,也就是底层会有多少个 map 分片。
  2. ConcurrentMap 表示一个支持并发读写的 map,它底层包含了多个 map 分片,以及有一个根据 key 计算分片的函数。
  3. ConcurrentMapShared 表示一个 map 分片,也就是上面提到的 map + RWMutex 组合。
  4. GetShard 根据 key 获取对应的 map 分片。

单从代码的角度,它封装了更多的东西,性能相比单纯的 map + RWMutex 自然会差一点, 但是从并发读写的角度来说,它比单纯 map + RWutex 要好很多。 因为它将原本只支持一个协程写的 map 转换为了支持多个协程写操作的 map,一定程度上提高了并发

但是需要注意的是,我们需要频繁写同一个 key 的操作,上面这种分片的方式也不能带来性能上的提升。 分片的方式更适合那些 key 区分度高的、写操作频繁的场景。

总结

最后再简单回顾一下本文所讲内容:

  1. Go 的 map 设计上不支持并发读写,如果我们有并发读写操作会直接 panic
  2. Go 的设计者们认为,多数情况下,我们并不需要从多个 goroutine 来对 map 进行安全访问,所以他们没有在底层实现 map 的互斥操作。
  3. 有两种方法可以解决 map 并发读写的问题:互斥锁、sync.Map。但是 sync.Map 设计上是应对某些特定场景的,并不合适所有场景。
  4. 我们可以通过分片的方式来解决 map 并发读写的问题,这样可以减少锁的竞争,提高并发读写性能。目前已经有现成的开源库可以使用了。

本文应该是本系列文章最后一篇了,前面留下的一些坑可能后面会再补充一下,但不在本系列文章中了。

整体架构

再来回顾一下我们的整体架构:

arch

在我们的 demo 中,包含了以下几种角色:

  1. 客户端:一般是浏览器,用于接收消息;
  2. Hub:消息中心,用于管理所有的客户端连接,以及将消息推送给客户端;
  3. 调用 /send 发送消息的应用:用于将消息发送给 Hub,然后由 Hub 将消息推送给客户端。

然后,每一个 WebSocket 连接都有一个关联的读协程和写协程, 用于读取客户端发送的消息,以及将消息推送给客户端。

目录结构

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
├── LICENSE  // 协议
├── Makefile // 一些常用的命令
├── README.md
├── authenticator.go // 认证器
├── authenticator_test.go // 认证器测试
├── bytes.go // 字符串和 []byte 之间转换的辅助方法
├── client.go // WebSocket 客户端
├── go.mod // 项目依赖
├── go.sum // 项目依赖
├── hub.go // 消息中心
├── main.go // 程序入口
├── message // 消息记录器
│   ├── db_logger.go
│   ├── db_logger_test.go
│   ├── log.go
│   └── stdout_logger.go
├── server.go // HTTP 服务
└── server_test.go // HTTP 接口的测试

运行

注:需要 Go 1.20 或以上版本

  1. 下载依赖:

可以使用七牛云的代理加速下载。

1
go mod tidy
  1. 启动 WebSocket 服务端:
1
go run main.go

Hub 代码

最终,我们的 Hub 代码演进成了下面这样:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
// bufferSize 通道缓冲区、map 初始化大小
const bufferSize = 128

// Handler 错误处理函数
type Handler func(log message.Log, err error)

// Hub 维护了所有的客户端连接
type Hub struct {
// 注册请求
register chan *Client
// 取消注册请求
unregister chan *Client
// 记录 uid 跟 client 的对应关系
userClients map[string]*Client
// 互斥锁,保护 userClients 以及 clients 的读写
sync.RWMutex
// 消息记录器
messageLogger message.Logger
// 错误处理器
errorHandler Handler
// 验证器
authenticator Authenticator
// 等待发送的消息数量
pending atomic.Int64
}

// 默认的错误处理器
func defaultErrorHandler(log message.Log, err error) {
res, _ := json.Marshal(log)
fmt.Printf("send message: %s, error: %s\n", string(res), err.Error())
}

func newHub() *Hub {
return &Hub{
register: make(chan *Client),
unregister: make(chan *Client),
userClients: make(map[string]*Client, bufferSize),
RWMutex: sync.RWMutex{},
messageLogger: &message.StdoutMessageLogger{},
errorHandler: defaultErrorHandler,
authenticator: &JWTAuthenticator{},
}
}

// 注册、取消注册请求处理
func (h *Hub) run() {
for {
select {
case client := <-h.register:
h.Lock()
h.userClients[client.uid] = client
h.Unlock()
case client := <-h.unregister:
h.Lock()
close(client.send)
delete(h.userClients, client.uid)
h.Unlock()
}
}
}

// 返回 Hub 的当前的关键指标
func metrics(hub *Hub, w http.ResponseWriter) {
pending := hub.pending.Load()
connections := len(hub.userClients)
_, _ = w.Write([]byte(fmt.Sprintf("# HELP connections 连接数\n# TYPE connections gauge\nconnections %d\n", connections)))
_, _ = w.Write([]byte(fmt.Sprintf("# HELP pending 等待发送的消息数量\n# TYPE pending gauge\npending %d\n", pending)))
}

其中:

  • Hub 中的 registerunregister 通道用于处理客户端的注册和取消注册请求;
  • Hub 中的 userClients 用于记录 uidClient 的对应关系;
  • Hub 中的 messageLogger 用于记录消息;
  • Hub 中的 errorHandler 用于处理错误;
  • Hub 中的 authenticator 用于验证客户端的身份;
  • Hub 中的 pending 用于记录等待发送的消息数量。

目前实现存在的问题:

  • registerunregister 通道被消费的时候需要加锁,这样会导致 registerunregister 变成串行的,性能不好;
  • userClients 也是需要加锁的,这样会导致 userClients 的读写也是串行的,性能不好;

对于这两个问题,前面我们讨论过,一种可行的办法分段 map,然后对每一个 map 都有一个对应的 sync.Mutex 互斥锁来保证其读写的安全。

Client 代码

Client 比较关键的方法是:

  • writePump:负责将消息推送给客户端。
  • serveWs:处理 WebSocket 连接请求。
  • send:处理消息发送请求。

writePump

这个方法会从 send 通道中获取消息,然后推送给客户端。 推送失败会调用 errorHandler 处理错误。 推送成功会将 pending 减一。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
// writePump 负责推送消息给 WebSocket 客户端
//
// 该方法在一个独立的协程中运行,我们保证了每个连接只有一个 writer。
// Client 会从 send 请求中获取消息,然后在这个方法中推送给客户端。
func (c *Client) writePump() {
defer func() {
_ = c.conn.Close()
}()

// 从 send 通道中获取消息,然后推送给客户端
for {
messageLog, ok := <-c.send

// 设置写超时时间
_ = c.conn.SetWriteDeadline(time.Now().Add(writeWait))
// c.send 这个通道已经被关闭了
if !ok {
c.hub.pending.Add(int64(-1 * len(c.send)))
return
}

if err := c.conn.WriteMessage(websocket.TextMessage, StringToBytes(messageLog.Message)); err != nil {
c.hub.errorHandler(messageLog, err)
c.hub.pending.Add(int64(-1 * len(c.send)))
return
}

c.hub.pending.Add(int64(-1))
}
}

serveWs

serveWs 方法会处理 WebSocket 连接请求,然后将其注册到 Hub 中。 在连接的时候会对客户端进行认证,认证失败会断开连接。 最后会启动读写协程。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
// serveWs 处理 WebSocket 连接请求
func serveWs(hub *Hub, w http.ResponseWriter, r *http.Request) {
// 升级为 WebSocket 连接
conn, err := upgrader.Upgrade(w, r, nil)
if err != nil {
w.WriteHeader(http.StatusBadRequest)
_, _ = w.Write([]byte(fmt.Sprintf("upgrade error: %s", err.Error())))
return
}

// 认证失败的时候,返回错误信息,并断开连接
uid, err := hub.authenticator.Authenticate(r)
if err != nil {
_ = conn.SetWriteDeadline(time.Now().Add(time.Second))
_ = conn.WriteMessage(websocket.TextMessage, []byte(fmt.Sprintf("authenticate error: %s", err.Error())))
_ = conn.Close()
return
}

// 注册 Client
client := &Client{hub: hub, conn: conn, send: make(chan message.Log, bufferSize), uid: uid}
client.conn.SetCloseHandler(closeHandler)
// register 无缓冲,下面这一行会阻塞,直到 hub.run 中的 <-h.register 语句执行
// 这样可以保证 register 成功之后才会启动读写协程
client.hub.register <- client

// 启动读写协程
go client.writePump()
go client.readPump()
}

send

send 是一个 http 接口,用于处理消息发送请求。 它会从 Hub 中获取 uid 对应的 Client,然后将消息发送给客户端。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
// send 处理消息发送请求
func send(hub *Hub, w http.ResponseWriter, r *http.Request) {
uid := r.FormValue("uid")
if uid == "" {
w.WriteHeader(http.StatusBadRequest)
_, _ = w.Write([]byte("uid is required"))
return
}

// 从 hub 中获取 uid 关联的 client
hub.RLock()
client, ok := hub.userClients[uid]
hub.RUnlock()
if !ok {
w.WriteHeader(http.StatusBadRequest)
_, _ = w.Write([]byte(fmt.Sprintf("client not found: %s", uid)))
return
}

// 记录消息
messageLog := message.Log{Uid: uid, Message: r.FormValue("message")}
_ = hub.messageLogger.Log(messageLog)

// 发送消息
client.send <- messageLog

// 增加等待发送的消息数量
hub.pending.Add(int64(1))
}

github

完整代码可以在 github 上进行查看:https://github.com/eleven26/go-pusher