V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
The Go Programming Language
http://golang.org/
Go Playground
Go Projects
Revel Web Framework
dzdh
V2EX  ›  Go 编程语言

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

  •  
  •   dzdh · 2022-07-22 00:29:54 +08:00 · 3556 次点击
    这是一个创建于 857 天前的主题,其中的信息可能已经有所发展或是发生改变。

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

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

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

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

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

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

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

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

    3.线上服务写日志难道还有人不是异步的?
    dzdh
        12
    dzdh  
    OP
       2022-07-22 08:56:37 +08:00
    @sadfQED2

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

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

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

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

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

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

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


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

    @misaka19000 #16 同上面的回复

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

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

    索赔是依赖第三方的正常商业行为,但是在依赖第三方之前,自家的 debug 、故障修复能力也是应该尽量自己提升的。
    这个安全级别日志是单节点的稳定性、故障恢复、debug 能力的范畴; LB 是处理扩容问题、分布式范畴。一个是单点内的问题,一个是集群扩容能力的问题,所以 LB 跟这个问题没有直接关系
    lysS
        33
    lysS  
       2022-07-27 09:58:53 +08:00
    不是很重要的日志可以加个缓冲
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   实用小工具   ·   4548 人在线   最高记录 6679   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 29ms · UTC 04:07 · PVG 12:07 · LAX 20:07 · JFK 23:07
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.