有日志(stdout or file) qps 4k，没日志 qps 10w. why?

[dzdh]

很简单的一个 echo 的 hello world 小 demo 。

wrk -c2000 -d10s -t6 http://localhost:8000/

use(logger)就 4k 的 qps （默认是 stdout ），不 use 就 10w 的 qps ??

因为同步输出到 stdout 需要时间嘛？那正式线上服务还需要考虑异步写日志咯？

搞个有 buffer 的 writer ？那 panic 的时候没来得及刷盘的日志咋弄。

# 没有use(logger)
# wrk -c2000 -d10s -t6 http://localhost:8000/
Running 10s test @ http://localhost:8000/
  6 threads and 2000 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     2.50ms    3.47ms  57.16ms   88.65%
    Req/Sec    15.91k     3.05k   33.29k    72.17%
  950515 requests in 10.03s, 0.93GB read
  Socket errors: connect 1753, read 97, write 0, timeout 0
Requests/sec:  94757.42
Transfer/sec:     94.80MB

# use(logger)
# wrk -c2000 -d10s -t6 http://localhost:8000/
Running 10s test @ http://localhost:8000/
  6 threads and 2000 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency   378.75ms  118.71ms   1.51s    84.82%
    Req/Sec   106.91     46.29   282.00     64.64%
  6369 requests in 10.06s, 6.37MB read
  Socket errors: connect 1753, read 86, write 0, timeout 0
Requests/sec:    632.87
Transfer/sec:    648.32KB

func main() {
	app := echo.New()
	app.HideBanner = true

	app.Use(middleware.Logger())# <- 就这里
	app.Use(middleware.Recover())
	app.Use(middleware.RequestID())

	app.GET("/", func(c echo.Context) error {
		return c.Render(200, "content/index", echo.Map{})
	})
        app.Start(":8000")
}

c.Render(200, "content/index", echo.Map{}) 换成 c.String(200,"...") 一样

[Maboroshii]

writer 本来也有 buffer 吧。你可以搞个写日志的 benchmark 试下，在你的机器上到底什么性能。另外 writer 可能还有锁，这个也有性能消耗。

[Trim21]

不至于这么慢吧，你把 log 输出到 io.Discard 试试?

[xupefei]

>那正式线上服务还需要考虑异步写日志咯？
不要过度优化。

[msg7086]

你正式上线如果要跑 10w qps 的话还是单独开一台日志服务器吧。

[mstmdev]

goos: windows
goarch: amd64
go:1.18.1
cpu: Intel(R) Core(TM) i7-6800K CPU @ 3.40GHz

BenchmarkPrintln-12 18981 110532 ns/op 24 B/op 1 allocs/op
BenchmarkStdout-12 15235 84465 ns/op 24 B/op 1 allocs/op
BenchmarkBufio-12 56409 25036 ns/op 163 B/op 0 allocs/op
BenchmarkDiscard-12 348340519 3.703 ns/op 0 B/op 0 allocs/op

简单测试了一下，光打印“hello world\n”，性能相差还是很大的，Stdout 底层有系统调用和锁，访问量大的话还是会影响性能的。java 的 System.out.println 应该也有类似的问题。

[CEBBCAT]

可否详细说明 panic 和落盘的关系？网络服务不一般都对 request 逐个做了 recovery 吗？

[kiwi95]

@CEBBCAT 虽然都会有一个 recovery middleware ，但是 request 处理内部会起 goroutine 就可能整个程序 panic ，不做处理的话这可能导致日志会丢失一些

[dzdh]

@Trim21 嗷嗷快。嗯。

[ToBeHacker]

相比于 echo HelloWorld ，写日志本身就很重了。在高性能场景下，除了 debug 日志都要关掉的

[dzdh]

@mstmdev

goos: darwin
goarch: amd64
cpu: Intel(R) Core(TM) i7-7820HQ CPU @ 2.90GHz
BenchmarkStdout-8 10000 261816 ns/op

[sadfQED2]

1.go 语言的输出队列是 1k 还是多大来着，当高并发写日志的时候把输出队列占满了，其他输出就会等待，因此你 qps 就下去了

2.你应该把日志改成写文件再试试

3.线上服务写日志难道还有人不是异步的？

[dzdh]

@sadfQED2

2. 好像更满了....
3. 这块儿有好用的包吗

[sadfQED2]

@dzdh 开源的不知道，我呆过的公司日志框架都是内部实现的。写日志都是异步操作

[lwch]

估计是你这个日志库里有锁，或者队列长度比较短导致大量调用被 block 住了

[misaka19000]

写日志到磁盘肯定慢啊，磁盘和网络内存 CPU 比起来实在是太慢了

[misaka19000]

写日志必须是异步的操作，不然会影响业务性能

[tairan2006]

用 uber/zap

[iseki]

Java 那边一般也不会 System.out.println ，一般库都是异步的，go 也一样

[awanabe]

io 和 捕捉异常 都很耗时

[sujin190]

stdout 输出到控制台的写性能确实不高，stdout 重定向到文件的区别应该不大吧

[zhengkai]

盲猜一个每次文件都打开关闭，而 stdout 没有用 tmux 之类的，没有缓存真就会碰到阻塞

其实你应该贴 Logger 函数里面的内容，反倒贴了一堆没用的

[nmap]

用 zap 写文件试试

[dzdh]

@zhengkai
https://github.com/labstack/gommon/blob/master/log/log.go#L74

func output() return os.Stdout

[zhengkai]

@dzdh 你标题已经说了走的 stdout ，我说的是 stdout 可能在 terminal 这层被阻塞，结果你还是在重复说你走的 stdout ，估计是没听懂

要不这样，你启动的时候结尾加上 >/tmp/log.txt 2>&1 ，再跑一次看有区别没

看你贴的代码，这是你用的 log 库吧，说的是你怎么调的 Logger ，不是问你调的什么 Logger……

你骑共享单车 100 次、每次骑 10 米，跟你一次骑车骑 1000 米，是不一样的。扫码、解锁、停车、关锁的开销这一套下来，可能还没你走着快。这样能理解么

你这里，如果是个复杂的 log ，还有颜色高亮什么的，可能拼 log 的时间远大于写 log 的时间，但再大再复杂的 log 也不应该每秒 4k

[Trim21]

楼主代码用得应该是 echo 示例里面给的这个

https://github.com/labstack/echo/blob/master/middleware/logger.go#L227

[CEBBCAT]

@kiwi95 应该着眼于怎么消除 goroutine 里面的代码缺陷带来的 panic 吧。我觉得，欢迎交流

[lsp7572]

火焰图看看就知道，之前分析过日志，如果日志里有很多 format ，没处理好会涉及到很多反射调用，QPS 一大就非常耗性能，用 uber 的 zap 试试

[pastor]

@msg7086 #4 "你正式上线如果要跑 10w qps 的话还是单独开一台日志服务器吧"
都写到日志服务器难道不比写本机更慢吗。。。


@sadfQED2 #11 "3.线上服务写日志难道还有人不是异步的？"
比如金融级的业务，资金很重要，如果用异步、刚好宕机日志丢失了，那就不好了
#13 "开源的不知道，我呆过的公司日志框架都是内部实现的。写日志都是异步操作"
这些业务的安全等级不需要那么高，所以可以允许异步日志

@misaka19000 #16 同上面的回复

最后， @dzdh OP 可以按业务需要做日志选型，比如我上面说的。并且安全等级要求高的，比如金融级的，不差这点堆机器的硬件成本。如果是普通业务，异步也可

[sadfQED2]

@pastor 金融级别的，核心日志肯定得写数据库了，而且还得使用数据库事务提交。

如果要求日志不能丢，那只能控制日志的量了，线上服务使用 warning 以上的日志级别，并且严格控制日志数量

[pastor]

@sadfQED2 #29
不一样的，写数据库的那叫操作日志之类的，记录的东西不一样，比如 admin 操作之类的，是给管理人员用的。
程序日志主要是用于 debug 日志的，是给程序员用的。

[msg7086]

@pastor
1. 写到日志服务器可以异步
2. 金融级服务如果宕机，应该找硬件或操作系统公司索赔。
再者，如果是金融级服务，可以搞高可用，前端 LB 后端集群，基本不需要考虑宕机的问题。
不管怎么说，一旦量级到了 10w qps ，就不是一个人在一个论坛上问问就能搞定的了，怎么都需要一个团队和专业的有经验的架构师来搞了。

[pastor]

@msg7086
我说的是写日志服务器比写本机更慢，用相同的方式，都同步或者都异步，肯定是本机快。如果不考虑日志安全级别、也即不需要考虑异步的丢日志问题，那当然也能异步写本地了。
另外就是，异步写到日志服务器的硬件、配置耦合更高、还需要考虑短线重连之类的稳定性问题，而且是业务进程内的模块，远不如 ELK 拉日志之类的解耦（当然，也额外增加了运维成本，但是开发和代码相对解脱了一些）

索赔是依赖第三方的正常商业行为，但是在依赖第三方之前，自家的 debug 、故障修复能力也是应该尽量自己提升的。
这个安全级别日志是单节点的稳定性、故障恢复、debug 能力的范畴； LB 是处理扩容问题、分布式范畴。一个是单点内的问题，一个是集群扩容能力的问题，所以 LB 跟这个问题没有直接关系

[lysS]

不是很重要的日志可以加个缓冲