golang pprof

以常见的one-gouroutine-per-connection模式来介绍pprof的用法

# server.go
func main() {
    ln, err := net.Listen("tcp", ":8972")
    if err != nil {
        panic(err)
    }
    go func() {
        if err := http.ListenAndServe(":6060", nil); err != nil {
            log.Fatalf("pprof failed: %v", err)
        }
    }()
    var connections []net.Conn
    defer func() {
        for _, conn := range connections {
            conn.Close()
        }
    }()
    for {
        conn, e := ln.Accept()
        if e != nil {
            if ne, ok := e.(net.Error); ok && ne.Temporary() {
                log.Printf("accept temp err: %v", ne)
                continue
            }
            log.Printf("accept err: %v", e)
            return
        }
        go handleConn(conn)
        connections = append(connections, conn)
        if len(connections)%100 == 0 {
            log.Printf("total number of connections: %v", len(connections))
        }
    }
}
func handleConn(conn net.Conn) {
    io.Copy(ioutil.Discard, conn)
}
# client.go

var (
	ip          = flag.String("ip", "127.0.0.1", "server IP")
	connections = flag.Int("conn", 1, "number of tcp connections")
)

func main() {
    flag.Parse()
    rand.Seed(time.Now().UnixNano())

    addr := *ip + ":8972"
    var conns []net.Conn
    for i := 0; i < *connections; i++ {
        c, err := net.DialTimeout("tcp", addr, 10*time.Second)
        if err != nil {
            fmt.Println("failed to connect", i, err)
            i--
            continue
        }
        conns = append(conns, c)
        time.Sleep(time.Millisecond)
    }
    defer func() {
        for _, c := range conns {
            c.Close()
        }
    }()
    log.Printf("完成初始化 %d 连接", len(conns))
    wg := sync.WaitGroup{}
    for i := 0; i < len(conns); i++ {
        wg.Add(1)
        go func(conn net.Conn) {
            defer wg.Done()
            for {
                time.Sleep(time.Duration(rand.Int31n(1000)) * time.Millisecond)
                conn.Write([]byte("hello world\r\n"))
            }
        }(conns[i])
    }
    wg.Wait()
}

测试数据

CPU Profiling

go tool pprof http://localhost:6060/debug/pprof/profile?seconds=60
  • flat：给定函数上运行耗时
  • flat%：同上的 CPU 运行耗时总比例
  • sum%：给定函数累积使用 CPU 总比例
  • cum：当前函数加上它之上的调用运行总耗时
  • cum%：同上的 CPU 运行耗时总比例

10000个connection时测试数据

(pprof) top
Showing nodes accounting for 2350ms, 70.57% of 3330ms total
Dropped 34 nodes (cum <= 16.65ms)
Showing top 10 nodes out of 79
      flat  flat%   sum%        cum   cum%
     560ms 16.82% 16.82%      560ms 16.82%  runtime.epollwait /usr/local/go/src/runtime/sys_linux_amd64.s
     560ms 16.82% 33.63%      790ms 23.72%  syscall.Syscall /usr/local/go/src/syscall/asm_linux_amd64.s
     310ms  9.31% 42.94%      310ms  9.31%  runtime.futex /usr/local/go/src/runtime/sys_linux_amd64.s
     210ms  6.31% 49.25%      210ms  6.31%  runtime.usleep /usr/local/go/src/runtime/sys_linux_amd64.s
     170ms  5.11% 54.35%     1490ms 44.74%  io/ioutil.devNull.ReadFrom /usr/local/go/src/io/ioutil/ioutil.go
     120ms  3.60% 57.96%     1210ms 36.34%  internal/poll.(*FD).Read /usr/local/go/src/internal/poll/fd_unix.go
     110ms  3.30% 61.26%      110ms  3.30%  runtime.deferreturn /usr/local/go/src/runtime/panic.go
     110ms  3.30% 64.56%      220ms  6.61%  runtime.netpollready /usr/local/go/src/runtime/netpoll.go
     110ms  3.30% 67.87%      110ms  3.30%  runtime.netpollunblock /usr/local/go/src/runtime/netpoll.go
      90ms  2.70% 70.57%      870ms 26.13%  runtime.netpoll /usr/local/go/src/runtime/netpoll_epoll.go

Heap profiling

go tool pprof http://localhost:6060/debug/pprof/heap
  • -inuse_space：分析应用程序的常驻内存占用情况(default)
  • -alloc_objects：分析应用程序的内存临时分配情况

10000个connection的测试数据

(pprof) top
Showing nodes accounting for 19080.60kB, 100% of 19080.60kB total
Showing top 10 nodes out of 22
      flat  flat%   sum%        cum   cum%
17544.35kB 91.95% 91.95% 17544.35kB 91.95%  io/ioutil.glob..func1 /usr/local/go/src/io/ioutil/ioutil.go
 1024.06kB  5.37% 97.32%  1024.06kB  5.37%  syscall.anyToSockaddr /usr/local/go/src/syscall/syscall_linux.go
  512.19kB  2.68%   100%   512.19kB  2.68%  runtime.malg /usr/local/go/src/runtime/proc.go
         0     0%   100%   512.03kB  2.68%  internal/poll.(*FD).Accept /usr/local/go/src/internal/poll/fd_unix.go
         0     0%   100%   512.03kB  2.68%  internal/poll.accept /usr/local/go/src/internal/poll/sock_cloexec.go
         0     0%   100% 17544.35kB 91.95%  io.Copy /usr/local/go/src/io/io.go
         0     0%   100% 17544.35kB 91.95%  io.copyBuffer /usr/local/go/src/io/io.go
         0     0%   100% 17544.35kB 91.95%  io/ioutil.(*devNull).ReadFrom <autogenerated>
         0     0%   100% 17544.35kB 91.95%  io/ioutil.devNull.ReadFrom /usr/local/go/src/io/ioutil/ioutil.go
         0     0%   100% 17544.35kB 91.95%  main.handleConn /home/gelco/code/go/src/gelco/1m-go-tcp-connection/goroutine-per-conn/server.go

Others

#Block profiling
go tool pprof http://localhost:6060/debug/pprof/block

#Mutex profiling
go tool pprof http://localhost:6060/debug/pprof/mutex