V2EX = way to explore
V2EX 是一个关于分享和探索的地方
Sign Up Now
For Existing Member  Sign In
The Go Programming Language
http://golang.org/
Go Playground
Go Projects
Revel Web Framework
dzdh

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

  •  
  •   dzdh · Jul 22, 2022 · 4251 views
    This topic created in 1382 days ago, the information mentioned may be changed or developed.

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

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

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

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

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

    Supplement 1  ·  Jul 22, 2022
    # 没有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")
    }
    
    Supplement 2  ·  Jul 22, 2022
    c.Render(200, "content/index", echo.Map{}) 换成 c.String(200,"...") 一样
    33 replies    2022-07-27 09:58:53 +08:00
    Maboroshii
        1
    Maboroshii  
       Jul 22, 2022 via Android
    writer 本来也有 buffer 吧。你可以搞个写日志的 benchmark 试下,在你的机器上到底什么性能。另外 writer 可能还有锁,这个也有性能消耗。
    Trim21
        2
    Trim21  
       Jul 22, 2022
    不至于这么慢吧,你把 log 输出到 io.Discard 试试?
    xupefei
        3
    xupefei  
       Jul 22, 2022
    >那正式线上服务还需要考虑异步写日志咯?
    不要过度优化。
    msg7086
        4
    msg7086  
       Jul 22, 2022
    你正式上线如果要跑 10w qps 的话还是单独开一台日志服务器吧。
    mstmdev
        5
    mstmdev  
       Jul 22, 2022
    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
        6
    CEBBCAT  
       Jul 22, 2022 via iPhone
    可否详细说明 panic 和落盘的关系?网络服务不一般都对 request 逐个做了 recovery 吗?
    kiwi95
        7
    kiwi95  
       Jul 22, 2022 via Android
    @CEBBCAT 虽然都会有一个 recovery middleware ,但是 request 处理内部会起 goroutine 就可能整个程序 panic ,不做处理的话这可能导致日志会丢失一些
    dzdh
        8
    dzdh  
    OP
       Jul 22, 2022
    @Trim21 嗷嗷快。嗯。
    ToBeHacker
        9
    ToBeHacker  
       Jul 22, 2022
    相比于 echo HelloWorld ,写日志本身就很重了。在高性能场景下,除了 debug 日志都要关掉的
    dzdh
        10
    dzdh  
    OP
       Jul 22, 2022
    @mstmdev

    goos: darwin
    goarch: amd64
    cpu: Intel(R) Core(TM) i7-7820HQ CPU @ 2.90GHz
    BenchmarkStdout-8 10000 261816 ns/op
    sadfQED2
        11
    sadfQED2  
       Jul 22, 2022 via Android
    1.go 语言的输出队列是 1k 还是多大来着,当高并发写日志的时候把输出队列占满了,其他输出就会等待,因此你 qps 就下去了

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

    3.线上服务写日志难道还有人不是异步的?
    dzdh
        12
    dzdh  
    OP
       Jul 22, 2022
    @sadfQED2

    2. 好像更满了....
    3. 这块儿有好用的包吗
    sadfQED2
        13
    sadfQED2  
       Jul 22, 2022 via Android
    @dzdh 开源的不知道,我呆过的公司日志框架都是内部实现的。写日志都是异步操作
    lwch
        14
    lwch  
       Jul 22, 2022
    估计是你这个日志库里有锁,或者队列长度比较短导致大量调用被 block 住了
    misaka19000
        15
    misaka19000  
       Jul 22, 2022
    写日志到磁盘肯定慢啊,磁盘和网络内存 CPU 比起来实在是太慢了
    misaka19000
        16
    misaka19000  
       Jul 22, 2022
    写日志必须是异步的操作,不然会影响业务性能
    tairan2006
        17
    tairan2006  
       Jul 22, 2022   ❤️ 1
    用 uber/zap
    iseki
        18
    iseki  
       Jul 22, 2022 via Android
    Java 那边一般也不会 System.out.println ,一般库都是异步的,go 也一样
    awanabe
        19
    awanabe  
       Jul 22, 2022
    io 和 捕捉异常 都很耗时
    sujin190
        20
    sujin190  
       Jul 22, 2022 via Android
    stdout 输出到控制台的写性能确实不高,stdout 重定向到文件的区别应该不大吧
    zhengkai
        21
    zhengkai  
       Jul 22, 2022
    盲猜一个每次文件都打开关闭,而 stdout 没有用 tmux 之类的,没有缓存真就会碰到阻塞

    其实你应该贴 Logger 函数里面的内容,反倒贴了一堆没用的
    nmap
        22
    nmap  
       Jul 22, 2022
    用 zap 写文件试试
    dzdh
        23
    dzdh  
    OP
       Jul 22, 2022
    zhengkai
        24
    zhengkai  
       Jul 22, 2022
    @dzdh 你标题已经说了走的 stdout ,我说的是 stdout 可能在 terminal 这层被阻塞,结果你还是在重复说你走的 stdout ,估计是没听懂

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

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

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

    你这里,如果是个复杂的 log ,还有颜色高亮什么的,可能拼 log 的时间远大于写 log 的时间,但再大再复杂的 log 也不应该每秒 4k
    Trim21
        25
    Trim21  
       Jul 22, 2022
    楼主代码用得应该是 echo 示例里面给的这个

    https://github.com/labstack/echo/blob/master/middleware/logger.go#L227
    CEBBCAT
        26
    CEBBCAT  
       Jul 22, 2022
    @kiwi95 应该着眼于怎么消除 goroutine 里面的代码缺陷带来的 panic 吧。我觉得,欢迎交流
    lsp7572
        27
    lsp7572  
       Jul 22, 2022
    火焰图看看就知道,之前分析过日志,如果日志里有很多 format ,没处理好会涉及到很多反射调用,QPS 一大就非常耗性能,用 uber 的 zap 试试
    pastor
        28
    pastor  
       Jul 22, 2022
    @msg7086 #4 "你正式上线如果要跑 10w qps 的话还是单独开一台日志服务器吧"
    都写到日志服务器难道不比写本机更慢吗。。。


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

    @misaka19000 #16 同上面的回复

    最后, @dzdh OP 可以按业务需要做日志选型,比如我上面说的。并且安全等级要求高的,比如金融级的,不差这点堆机器的硬件成本。如果是普通业务,异步也可
    sadfQED2
        29
    sadfQED2  
       Jul 22, 2022 via Android
    @pastor 金融级别的,核心日志肯定得写数据库了,而且还得使用数据库事务提交。

    如果要求日志不能丢,那只能控制日志的量了,线上服务使用 warning 以上的日志级别,并且严格控制日志数量
    pastor
        30
    pastor  
       Jul 22, 2022
    @sadfQED2 #29
    不一样的,写数据库的那叫操作日志之类的,记录的东西不一样,比如 admin 操作之类的,是给管理人员用的。
    程序日志主要是用于 debug 日志的,是给程序员用的。
    msg7086
        31
    msg7086  
       Jul 23, 2022
    @pastor
    1. 写到日志服务器可以异步
    2. 金融级服务如果宕机,应该找硬件或操作系统公司索赔。
    再者,如果是金融级服务,可以搞高可用,前端 LB 后端集群,基本不需要考虑宕机的问题。
    不管怎么说,一旦量级到了 10w qps ,就不是一个人在一个论坛上问问就能搞定的了,怎么都需要一个团队和专业的有经验的架构师来搞了。
    pastor
        32
    pastor  
       Jul 24, 2022
    @msg7086
    我说的是写日志服务器比写本机更慢,用相同的方式,都同步或者都异步,肯定是本机快。如果不考虑日志安全级别、也即不需要考虑异步的丢日志问题,那当然也能异步写本地了。
    另外就是,异步写到日志服务器的硬件、配置耦合更高、还需要考虑短线重连之类的稳定性问题,而且是业务进程内的模块,远不如 ELK 拉日志之类的解耦(当然,也额外增加了运维成本,但是开发和代码相对解脱了一些)

    索赔是依赖第三方的正常商业行为,但是在依赖第三方之前,自家的 debug 、故障修复能力也是应该尽量自己提升的。
    这个安全级别日志是单节点的稳定性、故障恢复、debug 能力的范畴; LB 是处理扩容问题、分布式范畴。一个是单点内的问题,一个是集群扩容能力的问题,所以 LB 跟这个问题没有直接关系
    lysS
        33
    lysS  
       Jul 27, 2022
    不是很重要的日志可以加个缓冲
    About   ·   Help   ·   Advertise   ·   Blog   ·   API   ·   FAQ   ·   Solana   ·   2478 Online   Highest 6679   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 148ms · UTC 07:16 · PVG 15:16 · LAX 00:16 · JFK 03:16
    ♥ Do have faith in what you're doing.