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

如何 检测 golang 协成的连续执行时间?

  •  
  •   helloworld12 · 2018-10-23 17:43:29 +08:00 · 2812 次点击
    这是一个创建于 2259 天前的主题,其中的信息可能已经有所发展或是发生改变。

    嗯,推断说,某个协程连续执行了大段的时间,导致服务端卡住(其他协成无法得到 CPU 时间)

    现在的问题是要怎么找出这个协成,即如何获取某个携程的连续执行时间(不是测量函数执行时间,而是协程连续运行,不让渡 CPU 的持续时间)

    第 1 条附言  ·  2018-10-23 22:04:35 +08:00
    嗯, golang tool trace 这个工具似乎有用, 需要研究下 有什么好的教程呢?
    7 条回复    2018-10-26 01:54:37 +08:00
    keakon
        1
    keakon  
       2018-10-23 20:41:42 +08:00
    协程的三种写法。。
    helloworld12
        2
    helloworld12  
    OP
       2018-10-23 22:03:47 +08:00
    @keakon #1 ?
    reus
        3
    reus  
       2018-10-24 08:53:37 +08:00
    难道不是改代码?
    死循环是会触发调度器 bug 的
    yufpga
        4
    yufpga  
       2018-10-24 09:19:47 +08:00
    协程调度的问题可能性不大吧,生成火焰图看一下。工具很多,可以参考: https://github.com/uber/go-torch
    helloworld12
        5
    helloworld12  
    OP
       2018-10-24 18:48:15 +08:00
    @yufpga #4 cpu 火焰图,是 cpu 累计时间吧。。。查 latency 应该不是查这个吧?
    yufpga
        6
    yufpga  
       2018-10-24 19:50:55 +08:00   ❤️ 1
    @helloworld12 不知道楼主问题解决没有?我不知道楼主得到这个推断的理由是什么,我的想法是这样子的,你说服务端卡住,猜测是某个协程连续执行了大段时间,这里是两个要素,一个大段时间,二是连续执行。如果是连续执行,那么本质上是怀疑 go 的协程调度出现了一些问题, 说实话,这个结果我是不敢相信的。另一个要素是大段时间,这个可以通过火焰图看出来。我没有用过 go tool trace,没办法给出针对性意见。我不知道楼主更具体的情况,所以没有办法肯定一定是 cpu 卡,而不是 io 或是别的什么卡,我的方法可能还是利用 go tool pprof,可以着重看其中的两个指标 block 和 profile, 如果真是 cpu 的问题,profile 指标和火焰图应该能够分析出来。
    helloworld12
        7
    helloworld12  
    OP
       2018-10-26 01:54:37 +08:00
    @yufpga #6 嗯,谢谢, 应该是 block 问题

    50 多个连接, 负载不是很大, 占了 15%~20% 的 CPU

    查了下, profile,
    970ms 21.85% 21.85% 970ms 21.85% runtime.futex

    [futex 好像是 linux 的用户空间的快速锁]( https://zh.wikipedia.org/wiki/Futex)

    应该是 cas 的模式吧...然后怀疑 futex 是 spinlock, 接着查询到 [futex 是支持 futex_wait 和 futex_wake 就是支持唤醒机制]( http://blog.sina.com.cn/s/blog_e59371cc0102v29b.html)

    既然 futex 支持唤醒机制,为什么会这么耗 CPU, 在锁上耗 CPU,不是因为不断的尝试获取锁吗?

    (pprof) tree
    Showing nodes accounting for 3.53s, 79.50% of 4.44s total
    Dropped 281 nodes (cum <= 0.02s)
    Showing top 80 nodes out of 240
    ----------------------------------------------------------+-------------
    flat flat% sum% cum cum% calls calls% + context
    ----------------------------------------------------------+-------------
    0.41s 42.27% | runtime.futexsleep
    0.31s 31.96% | runtime.systemstack
    0.24s 24.74% | runtime.startm
    0.01s 1.03% | runtime.unlock
    0.97s 21.85% 21.85% 0.97s 21.85% | runtime.futex
    ----------------------------------------------------------+-------------
    0.24s 55.81% | syscall.Write
    0.19s 44.19% | internal/poll.(*FD).Read
    0.33s 7.43% 29.28% 0.43s 9.68% | syscall.Syscall
    0.09s 20.93% | runtime.reentersyscall
    0.01s 2.33% | runtime.exitsyscall
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   实用小工具   ·   2829 人在线   最高记录 6679   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 22ms · UTC 14:19 · PVG 22:19 · LAX 06:19 · JFK 09:19
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.