go - runtime._ExternalCode Cpu 使用率过高，高达 80%

Question

我用golang写了一个tcp handler，每秒大概300个连接。刚投产的程序没有问题。但是运行了大约 10 天后，我看到 cpu 使用率高达 100%。我使用 golang 工具“go tool pprof”来获取 cpu 使用信息:

File: gateway-w
Type: cpu
Time: Nov 7, 2018 at 5:38pm (CST)
Duration: 30.14s, Total samples = 30.13s (  100%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 27.42s, 91.01% of 30.13s total
Dropped 95 nodes (cum <= 0.15s)
Showing top 10 nodes out of 28
      flat  flat%   sum%        cum   cum%
    24.69s 81.94% 81.94%     24.69s 81.94%  runtime._ExternalCode /usr/local/go/src/runtime/proc.go
     0.57s  1.89% 83.84%      0.57s  1.89%  runtime.lock /usr/local/go/src/runtime/lock_futex.go
     0.56s  1.86% 85.70%      0.56s  1.86%  runtime.unlock /usr/local/go/src/runtime/lock_futex.go
     0.26s  0.86% 86.56%      5.37s 17.82%  gateway-w/connect/connect-tcp.tcpStartSession /go/src/gateway-w/connect/connect-tcp/tcp_framework.go
     0.25s  0.83% 87.39%      1.67s  5.54%  net.(*conn).Read /usr/local/go/src/net/net.go
     0.24s   0.8% 88.18%      1.41s  4.68%  net.(*netFD).Read /usr/local/go/src/net/fd_unix.go
     0.23s  0.76% 88.95%      0.23s  0.76%  runtime.nanotime /usr/local/go/src/runtime/sys_linux_amd64.s
     0.22s  0.73% 89.68%      0.22s  0.73%  internal/poll.(*fdMutex).incref /usr/local/go/src/internal/poll/fd_mutex.go
     0.21s   0.7% 90.38%      0.21s   0.7%  internal/poll.(*fdMutex).rwunlock /usr/local/go/src/internal/poll/fd_mutex.go
     0.19s  0.63% 91.01%      0.19s  0.63%  internal/poll.(*fdMutex).rwlock /usr/local/go/src/internal/poll/fd_mutex.go

我的 tcpHandle 代码是这样的:

func tcpStartSession(conn net.Conn) {

    defer closeTcp(conn)

    var (last, n int
        err     error
        buff    []byte
    )

    last, n, err, buff =
        0, 0, nil,
        make([]byte, MAX_PACKET_LEN)

    for {
        // set read timeout
        conn.SetReadDeadline(time.Now().Add(time.Duration(tcpTimeOutSec) * time.Second))
        n, err = conn.Read(buff[last:])

        if err != nil {
            log.Info("tcp read error maybe timeout , ", err)
            break
        }
        if n == 0 {
            log.Debug("empty packet, continue")
            continue
        }
        log.Debug("read bytes ", n)

        log.Info("get a raw package：", hex.EncodeToString(buff[:last+n]))
        last += n
        ...

        for {
            if last == 0 {
                break
            }

            ret, err := protoHandle.IsWhole(buff[:last])
            if err != nil {
                log.Warn("proto handle check iswhole error", err)
            }

            log.Debug("rest buffer len = %d\n", ret)
            if ret < 0 {
                //wait for more tcp fragment.
                break
            }
            packetLen := last - ret
            packetBuf := make([]byte, packetLen)
            copy(packetBuf, buff[:packetLen])

            last = ret

            if last > 0 {
                copy(buff, buff[packetLen:packetLen+last])
            }

            ...

        }
    }
}

我不明白 runtime._ExternalCode 是什么意思。这是golang里面的函数。

我的golang版本是:go version go1.9.2 linux/amd64

我的程序在docker上运行

my docker version is : 1.12.6

我希望有人能帮助我。非常感谢!

---

我尝试将golang版本升级到1.10.3。跑了大半年没问题。最近也出现了同样的问题，但是我没有改程序代码。我怀疑这段代码有问题:

conn.SetReadDeadline(time.Now().Add(time.Duration(tcpTimeOutSec) * time.Second))

需要你的帮助，谢谢。

Answer 1

正如您已确认您的程序不是使用 CGO_ENABLED=0 构建的

问题(可能)出在程序的 C go 部分。 pprof 无法分析 C 库的内部部分

我相信还有一些其他的东西可以算作“_External”，比如时间。现在在某些系统上