延迟日志捕获

由于 Go 语言中的日志记录操作过于耗时，导致使用 httprouter 框架的 HTTP API 速度明显下降。通过使用缓冲 I/O 和从协程写入日志记录信息，可以大幅提升日志记录的效率，从而缓解 API 速度下降的问题。

为什么 go log 包让我的 http api 速度如此之慢？有那么慢吗？

这是我使用 httprouter 的路由器示例，没有日志记录：

package main

import (
    "fmt"
    "log"
    "net/http"
    "time"

    "github.com/julienschmidt/httprouter"
)

func main() {
    handler := httprouter.new()
    handler.get("/hello", f)
    http.listenandserve(fmt.sprintf(":%d", 8080), handler)
}

func f(w http.responsewriter, r *http.request, ps httprouter.params) {
    w.writeheader(http.statusok)
    fmt.fprint(w, "world")
}

使用 wrk 对该端点进行基准测试，我得到了这个：

$ wrk -t1 -d1s -c100 http://localhost:8080/hello
running 1s test @ http://localhost:8080/hello
  1 threads and 100 connections
  thread stats   avg      stdev     max   +/- stdev
    latency     1.15ms  197.55us   2.84ms   80.02%
    req/sec    84.58k     6.15k   99.01k    80.00%
  83904 requests in 1.01s, 9.68mb read
requests/sec:  83380.37
transfer/sec:      9.62mb

当我添加用于日志记录的中间件时：

package main

import (
    "fmt"
    "log"
    "net/http"
    "time"

    "github.com/julienschmidt/httprouter"
)

func main() {
    handler := httprouter.new()
    handler.get("/hello", logger(f))
    fmt.println("httprouter")
    http.listenandserve(fmt.sprintf(":%d", 8080), handler)
}

func logger(next httprouter.handle) httprouter.handle {
    return func(w http.responsewriter, r *http.request, ps httprouter.params) {
        start := time.now()
        next(w, r, ps)
        elapsed := time.since(start)
        log.printf("%s | %s | %s | %d\n", time.now().format(time.rfc3339), r.method, r.url.path, elapsed)
    }
}

func f(w http.responsewriter, r *http.request, ps httprouter.params) {
    w.writeheader(http.statusok)
    fmt.fprint(w, "world")
}

速度减慢至 4 倍：

$ wrk -t1 -d1s -c100 http://localhost:8080/hello
running 1s test @ http://localhost:8080/hello
  1 threads and 100 connections
  thread stats   avg      stdev     max   +/- stdev
    latency     5.25ms    4.34ms  26.47ms   60.23%
    req/sec    20.51k     2.19k   24.28k    70.00%
  20449 requests in 1.01s, 2.36mb read
requests/sec:  20330.66
transfer/sec:      2.35mb

我在本地测试了它：

MacBook Pro 13inches
2 GHz Quad-Core Intel Core i5
Memory 16GB

I use default Go max proc without modifying anything after installed.

log 包有那么慢吗？有什么建议如何改进吗？

解决方案

此答案总结了对该问题的评论。

• 使用了缓冲 io
• 从 goroutine 写入以减少其他日志记录 goroutine 的阻塞。

代码如下：

type writer chan []byte

func (w writer) write(p []byte) (int, error) {
    w <- append(([]byte)(nil), p...)
    return len(p), nil
}

func writepump(w writer) {
    bw := bufio.newwriter(os.stderr)
    for p := range w {
        bw.write(p)

        // slurp up buffered messages in flush. this ensures
        // timely output.
        n := len(w)
        for i := 0; i < n; i++ {
            bw.write(<-w)
        }
        bw.flush()
    }
}

设置如下：

w := make(writer, 16) // adjust capacity to meet your needs
go writePump(w)
log.SetOutput(w)

今天关于《延迟日志捕获》的内容介绍就到此结束，如果有什么疑问或者建议，可以在golang学习网公众号下多多回复交流；文中若有不正之处，也希望回复留言以告知！