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

今天在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
}
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 160,706评论 4 366
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 68,002评论 1 301
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 110,462评论 0 250
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 44,375评论 0 216
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 52,763评论 3 294
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 40,849评论 1 224
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 32,033评论 2 317
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 30,768评论 0 204
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 34,490评论 1 246
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,734评论 2 253
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 32,204评论 1 264
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 28,566评论 3 260
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 33,227评论 3 241
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,137评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,934评论 0 201
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 35,926评论 2 283
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 35,774评论 2 274

推荐阅读更多精彩内容