使用go的执行追踪器(execution tracer)

语言: CN / TW / HK

今天在YouTube上看了大神关于执行追踪器的视频,感觉对于go的理解又上升了一个台阶。

首先,我们开始画一个 曼德布洛特复数集合(Mandelbrot set)

这个图片的最终效果为:

曼德布洛特复数集合.png

这个集合有些复杂,首先使用golang创建两个函数:

// pixel returns the color of a Mandelbrot fractal at the given point.
func pixel(i, j, width, height int) color.Color {
    // Play with this constant to increase the complexity of the fractal.
    // In the justforfunc.com video this was set to 4.
    const complexity = 1024

    xi := norm(i, width, -1.0, 2)
    yi := norm(j, height, -1, 1)

    const maxI = 1000
    x, y := 0., 0.

    for i := 0; (x*x+y*y < complexity) && i < maxI; i++ {
        x, y = x*x-y*y+xi, 2*x*y+yi
    }

    return color.Gray{uint8(x)}
}


 func norm(x, total int, min, max float64) float64 {
    return (max-min)*float64(x)/float64(total) - max
}

之后创建一个main函数:

const (
    output     = "out.png"
    width      = 2048
    height     = 2048
    numWorkers = 8
    cpuPprof   = "cpu.pprof"
)

func main()  {

    pprof.StartCPUProfile(os.Stdout)
    defer pprof.StopCPUProfile()

    f , err := os.Create(output)
    if err != nil {
        fmt.Printf("can't not open file err : %v",err.Error())
        return
    }

    img := create(width,height)

    if err = png.Encode(f, img); err != nil {
        log.Fatal(err)
    }

}

这里需要说明 :

pprof.StartCPUProfile(os.Stdout)
      defer pprof.StopCPUProfile()

这里我们创建了一个用于可视化和分析性能分析数据的工具 runtime.pprof

之后我们使用 create 方法来创建这个曼德布洛特复数集合图片。

func create(width , height int) image.Image {
    m := image.NewGray(image.Rect(0,0,width,height))
    for i := 0; i < width; i++ {
        for j := 0; j < height; j++ {
            m.Set(i , j ,pixel(i,j,width,height))
        }
    }

    return m
}

这里我们不需要关心图片是如果画出来的,而是去关心这个图像生成时所需要的时间

一切准备完毕,以下就是最终的代码:

package main

import (
    "fmt"
    "image"
    "image/color"
    "image/png"
    "log"
    "os"
    "runtime/pprof"
)

const (
    output     = "out.png"
    width      = 2048
    height     = 2048
    numWorkers = 8
    cpuPprof   = "cpu.pprof"
)


func main()  {

    pprof.StartCPUProfile(os.Stdout)
    defer pprof.StopCPUProfile()

    f , err := os.Create(output)
    if err != nil {
        fmt.Printf("can't not open file err : %v",err.Error())
        return
    }

    img := create(width,height)

    if err = png.Encode(f, img); err != nil {
        log.Fatal(err)
    }

}

func create(width , height int) image.Image {
    m := image.NewGray(image.Rect(0,0,width,height))
    for i := 0; i < width; i++ {
        for j := 0; j < height; j++ {
            m.Set(i , j ,pixel(i,j,width,height))
        }
    }

    return m
}


// pixel returns the color of a Mandelbrot fractal at the given point.
func pixel(i, j, width, height int) color.Color {
    // Play with this constant to increase the complexity of the fractal.
    // In the justforfunc.com video this was set to 4.
    const complexity = 1024

    xi := norm(i, width, -1.0, 2)
    yi := norm(j, height, -1, 1)

    const maxI = 1000
    x, y := 0., 0.

    for i := 0; (x*x+y*y < complexity) && i < maxI; i++ {
        x, y = x*x-y*y+xi, 2*x*y+yi
    }

    return color.Gray{uint8(x)}
}

func norm(x, total int, min, max float64) float64 {
    return (max-min)*float64(x)/float64(total) - max
}

我们开始执行命令:

go build -o mandelbrot 
time ./mandelbrot > cpu.pprof

这时候我们会输出结果:

./mandelbrot > cpu.pprof  5.02s user 0.03s system 96% cpu 5.210 total

同时会生成一个图像和一个 cpu.pprof 文件

接下来我们执行:

go tool pprof cpu.pprof

ok,我们进入了交互式终端

Type: cpu
Time: Mar 18, 2020 at 12:32am (CST)
Duration: 5.20s, Total samples = 4.60s (88.45%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

这里我们使用命令 top
来查看当前执行程序最耗时的10个方法:

(pprof) top
Showing nodes accounting for 4.50s, 97.83% of 4.60s total
Dropped 21 nodes (cum <= 0.02s)
Showing top 10 nodes out of 51
  flat  flat%   sum%        cum   cum%
 2.99s 65.00% 65.00%      3.61s 78.48%  main.pixel
 0.45s  9.78% 74.78%      0.45s  9.78%  runtime.madvise
 0.45s  9.78% 84.57%      0.48s 10.43%  runtime.mallocgc
 0.18s  3.91% 88.48%      0.24s  5.22%  compress/flate.(*compressor).findMatch
 0.13s  2.83% 91.30%      0.13s  2.83%  runtime.asyncPreempt
 0.09s  1.96% 93.26%      0.09s  1.96%  runtime.nanotime1
 0.09s  1.96% 95.22%      0.09s  1.96%  runtime.usleep
 0.06s  1.30% 96.52%      0.06s  1.30%  compress/flate.matchLen
 0.03s  0.65% 97.17%      0.03s  0.65%  runtime.memmove
 0.03s  0.65% 97.83%      0.03s  0.65%  runtime.pthread_kill

这里我们可以查看里面的方法分析使用 list main.pixel

(pprof) list main.pixel
Total: 4.60s
ROUTINE ======================== main.pixel in /Users/zooeymoon/go/src/concurrency_go_study/concurrency/trace/trace.go
 2.99s      3.61s (flat, cum) 78.48% of Total
     .          .     66:   // Play with this constant to increase the complexity of the fractal.
     .          .     67:   // In the justforfunc.com video this was set to 4.
     .          .     68:   const complexity = 1024
     .          .     69:
     .          .     70:   xi := norm(i, width, -1.0, 2)
     .       10ms     71:   yi := norm(j, height, -1, 1)
     .          .     72:
     .          .     73:   const maxI = 1000
     .          .     74:   x, y := 0., 0.
     .          .     75:
 2.52s      2.65s     76:   for i := 0; (x*x+y*y < complexity) && i < maxI; i++ {
 470ms      470ms     77:       x, y = x*x-y*y+xi, 2*x*y+yi
     .          .     78:   }
     .          .     79:
     .      480ms     80:   return color.Gray{uint8(x)}
     .          .     81:}
     .          .     82:
     .          .     83:func norm(x, total int, min, max float64) float64 {
     .          .     84:   return (max-min)*float64(x)/float64(total) - max
     .          .     85:}

从这里我们可以看出第76行耗时最多。

这里我们可以通过 runtime.pprof 库找到哪里执行的最慢。

不过这里引申出来一个问题:

runtime.pprof 只是记录了程序的执行时间,但是并没有告诉我们这里为什么这么慢,在这么长的运行代码片段里面到底发生了什么。所以我们需要使用 runtime.tracer 来查看代码中到底执行了什么

tracer

你有没有好奇过 Go 运行时是如何调度 goroutine 的?有没有深入研究过为什么有时候加了并发但是性能没有提高? Go 提供了执行跟踪器,可以帮助你诊断性能问题(如延迟、竞争或低并发等)、解决前面那些疑问。

Go 从 1.5 版本开始有执行跟踪器这么一个工具,原理是:监听 Go 运行时的一些特定的事件,如:

  • goroutine的创建、开始和结束。
  • 阻塞/解锁goroutine的一些事件(系统调用,channel,锁)
  • 网络I/O相关事件
  • 系统调用
  • 垃圾回收

追踪器会原原本本地收集这些信息,不做任何聚合或者抽样操作。对于负载高的应用来说,就可能会生成一个比较大的文件,该文件后面可以通过 go tool trace 命令来进行解析。

让我们把上面的代码重新修改一下,把

pprof.StartCPUProfile(os.Stdout)
defer pprof.StopCPUProfile()

替换成

trace.Start(os.Stdout)
defer trace.Stop()

之后我们再重新执行

go build -o mandelbrot 
time ./mandelbrot > m.trace

这里我们可以看到会多生成一个 m.trace 文件

➜  trace git:(master) ✗ time ./mandelbrot > m.trace
./mandelbrot > m.trace  4.80s user 0.02s system 99% cpu 4.821 total
➜  trace git:(master) ✗ ll
total 9288
-rw-r--r--  1 zooeymoon  staff   3.3K  3 18 00:32 cpu.pprof
-rw-r--r--  1 zooeymoon  staff    25K  3 18 01:05 m.trace
-rwxr-xr-x  1 zooeymoon  staff   2.5M  3 18 01:04 mandelbrot
-rw-r--r--  1 zooeymoon  staff   1.4M  3 18 01:05 out.png
-rw-r--r--  1 zooeymoon  staff   1.5K  3 18 01:02 trace.go

这里文件大约是cpu.pprof的7-8倍。

好的,这里我们打开这个文件 go tool trace m.trace ,之后会打开一个浏览器

[View trace](http://127.0.0.1:60662/trace)
[Goroutine analysis](http://127.0.0.1:60662/goroutines)
[Network blocking profile](http://127.0.0.1:60662/io) ([⬇](http://127.0.0.1:60662/io?raw=1))
[Synchronization blocking profile](http://127.0.0.1:60662/block) ([⬇](http://127.0.0.1:60662/block?raw=1))
[Syscall blocking profile](http://127.0.0.1:60662/syscall) ([⬇](http://127.0.0.1:60662/syscall?raw=1))
[Scheduler latency profile](http://127.0.0.1:60662/sched) ([⬇](http://127.0.0.1:60662/sche?raw=1))
[User-defined tasks](http://127.0.0.1:60662/usertasks)
[User-defined regions](http://127.0.0.1:60662/userregions)
[Minimum mutator utilization](http://127.0.0.1:60662/mmu)

我这点击view trace(其他的我暂时没有去研究)

如果在view trace页面是白板,你需要下一个go1.14办法,找到go的安装路径,把对应的文件替换就OK了

trace view

我们暂时使用嵌套for循环线性执行代码,这里没有用到多线程,我们可以使用 sync.waitGroup 来使用协程加快执行速度:

func createPix(width , height int) image.Image {
    m := image.NewGray(image.Rect(0,0,width,height))
    var wg sync.WaitGroup
    wg.Add(width * height)
    for i := 0; i < width; i++ {
        for j := 0; j < height; j++ {
            go func() {
                m.Set(i , j ,pixel(i,j,width,height))
                wg.Done()
            }()

        }
    }

    wg.Wait()

    return m
}

同样的我们把create方法换成creatPixel方法

./mandelbrot > m.trace 34.89s user 12.03s system 726% cpu 6.460 total

但是m.trace文件非常大

-rw-r--r-- 1 zooeymoon staff 3.3K 3 18 00:32 cpu.pprof  -rw-r--r-- 1 zooeymoon staff 138M 3 18 23:38 m.trace  -rwxr-xr-x 1 zooeymoon staff 2.5M 3 18 23:38 mandelbrot  -rw-r--r-- 1 zooeymoon staff 2.2M 3 18 23:38 out.png  -rw-r--r-- 1 zooeymoon staff 1.9K 3 18 23:37 trace.go

再使用 go tool trace 的时候发现解析的时间非常长

这里我们可以继续换一种思路:只开启2048个协程

func createRow(width, height int) image.Image {
    m := image.NewGray(image.Rect(0, 0, width, height))
    var wg sync.WaitGroup
    wg.Add(width * height)
    for i := 0; i < width; i++ {

        go func(i int) {
            for j := 0; j < height; j++ {
                m.Set(i, j, pixel(i, j, width, height))
                wg.Done()
            }
        }(i)

    }

    wg.Wait()

    return m
}

这一次trace文件大大减少!

./mandelbrot > row.trace 5.01s user 0.04s system 651% cpu 0.776 total

我们打开浏览器发现追踪器再开始的时间段创建了大量的协程,但是后来趋于稳定

row.trace

我们再使用多线程的时候还可以用到一个工具channel

这里我们再创建一个channel方法

func createWorkers(width, height int) image.Image {
    m := image.NewGray(image.Rect(0, 0, width, height))
    type px struct {
        i, j int
    }
    var wg sync.WaitGroup
    c := make(chan px)
    wg.Add(8)
    for i := 0; i < 8; i++ {
        go func() {
            for p := range c {
                m.Set(p.i, p.j, pixel(p.i, p.j, width, height))

            }
            wg.Done()
        }()

    }
    for i := 0; i < width; i++ {
        for j := 0; j < height; j++ {
            c <- px{i ,j}
        }
    }
    close(c)
    wg.Wait()
    
    return m
}

这里我们发现channel的速度并没有创建2048个go协程快

./mandelbrot > worker.trace 33.16s user 7.38s system 426% cpu 9.515 total

我们通过trace分析出来原来是channel等待的时间过长,可能是没有buffer的关系,这里我们重新修改代码变成一个有buffer的channel

func createWorkers(width, height int) image.Image {
    m := image.NewGray(image.Rect(0, 0, width, height))
    var wg sync.WaitGroup
    c := make(chan int , width)
    wg.Add(8)
    for i := 0; i < 8; i++ {
        go func() {
            for p := range c {
                for j := 0 ; j < height ; j++ {
                    m.Set(p, j, pixel(p, j, width, height))
                }

            }
            wg.Done()
        }()

    }
    for i := 0; i < width; i++ {
        c <- i
    }
    close(c)
    wg.Wait()

    return m
}

这里我们发现执行的速度非常快

./mandelbrot > worker-width.trace 4.98s user 0.04s system 526% cpu 0.953 total

从这些tracer我们可以分析出我们想要的东西,在做基准测试的时候可能看到程序在什么时候都做了什么这样有助我们协程更优美的代码

最后我贴上所有的代码

package main

import (
    "fmt"
    "image"
    "image/color"
    "image/png"
    "log"
    "os"
    "runtime/trace"
    "sync"
)

const (
    output     = "out.png"
    width      = 2048
    height     = 2048
    numWorkers = 8
    cpuPprof   = "cpu.pprof"
)

func main() {

    trace.Start(os.Stdout)
    defer trace.Stop()

    f, err := os.Create(output)
    if err != nil {
        fmt.Printf("can't not open file err : %v", err.Error())
        return
    }

    img := createWorkers(width, height)

    if err = png.Encode(f, img); err != nil {
        log.Fatal(err)
    }

}

func create(width, height int) image.Image {
    m := image.NewGray(image.Rect(0, 0, width, height))
    for i := 0; i < width; i++ {
        for j := 0; j < height; j++ {
            m.Set(i, j, pixel(i, j, width, height))
        }
    }

    return m
}

func createPix(width, height int) image.Image {
    m := image.NewGray(image.Rect(0, 0, width, height))
    var wg sync.WaitGroup
    wg.Add(width * height)
    for i := 0; i < width; i++ {
        for j := 0; j < height; j++ {
            go func(i, j int) {
                m.Set(i, j, pixel(i, j, width, height))
                wg.Done()
            }(i, j)

        }
    }

    wg.Wait()

    return m
}

func createRow(width, height int) image.Image {
    m := image.NewGray(image.Rect(0, 0, width, height))
    var wg sync.WaitGroup
    wg.Add(width * height)
    for i := 0; i < width; i++ {

        go func(i int) {
            for j := 0; j < height; j++ {
                m.Set(i, j, pixel(i, j, width, height))
                wg.Done()
            }
        }(i)

    }

    wg.Wait()

    return m
}

func createWorkers(width, height int) image.Image {
    m := image.NewGray(image.Rect(0, 0, width, height))
    var wg sync.WaitGroup
    c := make(chan int , width)
    wg.Add(8)
    for i := 0; i < 8; i++ {
        go func() {
            for p := range c {
                for j := 0 ; j < height ; j++ {
                    m.Set(p, j, pixel(p, j, width, height))
                }

            }
            wg.Done()
        }()

    }
    for i := 0; i < width; i++ {
        c <- i
    }
    close(c)
    wg.Wait()

    return m
}

// createCol creates one goroutine per column.
func createCol(width, height int) image.Image {
    m := image.NewGray(image.Rect(0, 0, width, height))
    for i := 0; i < width; i++ {
        for j := 0; j < height; j++ {
            m.Set(i, j, pixel(i, j, width, height))
        }
    }
    return m
}

// pixel returns the color of a Mandelbrot fractal at the given point.
func pixel(i, j, width, height int) color.Color {
    // Play with this constant to increase the complexity of the fractal.
    // In the justforfunc.com video this was set to 4.
    const complexity = 1024

    xi := norm(i, width, -1.0, 2)
    yi := norm(j, height, -1, 1)

    const maxI = 1000
    x, y := 0., 0.

    for i := 0; (x*x+y*y < complexity) && i < maxI; i++ {
        x, y = x*x-y*y+xi, 2*x*y+yi
    }

    return color.Gray{uint8(x)}
}

func norm(x, total int, min, max float64) float64 {
    return (max-min)*float64(x)/float64(total) - max
}
分享到: