原文地址：https://www.ardanlabs.com/blog/2019/05/garbage-collection-in-go-part2-gctraces.html
介绍
在第一篇文章中，我花时间描述了垃圾收集器的行为，并展示了垃圾收集器对正在运行的应用程序造成的延迟。我分享了如何生成和解释GC跟踪，显示堆上的内存如何变化，并解释了GC的不同阶段以及它们如何造成延迟。
该文章的最终结论是，如果减轻堆的压力，则将减少延迟成本，从而提高应用程序的性能。我还指出，通过寻找增加两次收集之间的时间的方法来降低收集开始的速度不是一个好策略。保持一致的速度会更好地保持应用程序以最佳性能运行。
在本文中，我将引导你运行一个实际的Web应用程序，并向你展示如何生成GC跟踪和应用程序配置文件。然后，我将向你展示如何解释这些工具的输出，以便你找到提高应用程序性能的方法。
运行应用程序
看一下我在Go培训中使用的Web应用程序。
图1
图1
https://github.com/ardanlabs/gotraining/tree/master/topics/go/profiling/project
图1显示了该应用程序的外观。该应用程序从不同的新闻提供者那里下载三套rss feed，并允许用户执行搜索。构建Web应用程序后，启动该应用程序。
$ go build
$ GOGC=off ./project > /dev/null
上面的操作显示了如何在将GOGC变量设置为off的情况下启动应用程序，该操作将关闭垃圾回收。日志将重定向到/dev/null。随着应用程序的运行，可以将请求发送到服务器。
$ hey -m POST -c 100 -n 10000 "http://localhost:5000/search?term=topic&cnn=on&bbc=on&nyt=on"
上面的操作显示了如何使用hey工具在服务器上运行使用100个连接发起1万个请求。最终的效果如下。
图2
图2
图2展示了在关闭垃圾回收器的情况下处理10k请求的可视化表示。处理10k请求花了4188ms，服务器每秒处理约2387个请求。
开启垃圾回收
为该应用程序打开垃圾回收会发生什么？
$ GODEBUG=gctrace=1 ./project > /dev/null
GOGC变量已替换为GODEBUG变量。在运行过程中每一个垃圾收集发生时会生成一个GC跟踪。现在再次发送相同的10k请求。
$ GODEBUG=gctrace=1 ./project > /dev/null
gc 3 @3.182s 0%: 0.015+0.59+0.096 ms clock, 0.19+0.10/1.3/3.0+1.1 ms cpu, 4->4->2 MB, 5 MB goal, 12 P
.
.
.
gc 2553 @8.452s 14%: 0.004+0.33+0.051 ms clock, 0.056+0.12/0.56/0.94+0.61 ms cpu, 4->4->2 MB, 5 MB goal, 12 P
上面显示了运行中第三次和最后一次收集的GC跟踪。我没有显示前两次收集，因为要保证收集发生之后没有服务请求的负载影响。最后一次收集显示要处理1万个请求花了2551个集合（减去前两个集合，因为它们不计算在内）。
下面是跟踪中每个部分的细分。
gc 2553 @8.452s 14%: 0.004+0.33+0.051 ms clock, 0.056+0.12/0.56/0.94+0.61 ms cpu, 4->4->2 MB, 5 MB goal, 12 P
gc 2553 : The 2553 GC runs since the program started
@8.452s : Eight seconds since the program started
14% : Fourteen percent of the available CPU so far has been spent in GC
// wall-clock
0.004ms : STW : Write-Barrier - Wait for all Ps to reach a GC safe-point.
0.33ms : Concurrent : Marking
0.051ms : STW : Mark Term - Write Barrier off and clean up.
// CPU time
0.056ms : STW : Write-Barrier
0.12ms : Concurrent : Mark - Assist Time (GC performed in line with allocation)
0.56ms : Concurrent : Mark - Background GC time
0.94ms : Concurrent : Mark - Idle GC time
0.61ms : STW : Mark Term
4MB : Heap memory in-use before the Marking started
4MB : Heap memory in-use after the Marking finished
2MB : Heap memory marked as live after the Marking finished
5MB : Collection goal for heap memory in-use after Marking finished
// Threads
12P : Number of logical processors or threads used to run Goroutines.
上面显示了最后一次收集的数字。因为hey我们可以看见运行的性能结果。
Requests : 10,000
------------------------------------------------------
Requests/sec : 1,882 r/s - Hey
Total Duration : 5,311ms - Hey
Percent Time in GC : 14% - GC Trace
Total Collections : 2,551 - GC Trace
------------------------------------------------------
Total GC Duration : 744.54ms - (5,311ms * .14)
Average Pace of GC : ~2.08ms - (5,311ms / 2,551)
Requests/Collection : ~3.98 r/gc - (10,000 / 2,511)
以下内容提供了所发生事件的更多可视化效果。
图3
image.png
图3直观地显示了发生的情况。打开收集器后，它必须运行约2.5k次才能处理相同的10k请求。每次收集的平均启动速度约为2.0毫秒，运行所有这些收集会增加大约1.1秒的延迟。
图4
image.png
图4显示了应用程序的两次运行的比较。
减少堆分配
获取堆的配置文件，看看是否有可以删除的非生产性分配。
go tool pprof http://localhost:5000/debug/pprof/allocs
上面显示了pprof调用/debug/pprof/allocs从正在运行的应用程序中提取内存配置文件的用法。
import _ "net/http/pprof"
go func() {
http.ListenAndServe("localhost:5000", http.DefaultServeMux)
}()
上面显示了如何将/debug/pprof/allocs绑定到任意应用程序。导入net/http/pprof绑定到默认服务器。然后http.ListenAndServer与http.DefaultServerMux参数一起使用启动端点。
探查器启动后，可使用top命令查看分配最多的前6个方法。
(pprof) top 6 -cum
Showing nodes accounting for 0.56GB, 5.84% of 9.56GB total
Dropped 80 nodes (cum <= 0.05GB)
Showing top 6 nodes out of 51
flat flat% sum% cum cum%
0 0% 0% 4.96GB 51.90% net/http.(*conn).serve
0.49GB 5.11% 5.11% 4.93GB 51.55% project/service.handler
0 0% 5.11% 4.93GB 51.55% net/http.(*ServeMux).ServeHTTP
0 0% 5.11% 4.93GB 51.55% net/http.HandlerFunc.ServeHTTP
0 0% 5.11% 4.93GB 51.55% net/http.serverHandler.ServeHTTP
0.07GB 0.73% 5.84% 4.55GB 47.63% project/search.rssSearch
上面显示了rssSearch函数在列表底部出现。迄今为止，此功能分配了5.96GB中的4.55GB。接下来，使用list命令检查rssSearch功能细节。
(pprof) list rssSearch
Total: 9.56GB
ROUTINE ======================== project/search.rssSearch in project/search/rss.go
71.53MB 4.55GB (flat, cum) 47.63% of Total
. . 117: // Capture the data we need for our results if we find ...
. . 118: for _, item := range d.Channel.Items {
. 4.48GB 119: if strings.Contains(strings.ToLower(item.Description), strings.ToLower(term)) {
48.53MB 48.53MB 120: results = append(results, Result{
. . 121: Engine: engine,
. . 122: Title: item.Title,
. . 123: Link: item.Link,
. . 124: Content: item.Description,
. . 125: })
上面显示了代码。119行突出显示了大部分分配。
. 4.48GB 119: if strings.Contains(strings.ToLower(item.Description), strings.ToLower(term)) {
这个时候我们需要review一下这行代码，看看有什么可以做的。
117 // Capture the data we need for our results if we find the search term.
118 for _, item := range d.Channel.Items {
119 if strings.Contains(strings.ToLower(item.Description), strings.ToLower(term)) {
120 results = append(results, Result{
121 Engine: engine,
122 Title: item.Title,
123 Link: item.Link,
124 Content: item.Description,
125 })
126 }
127 }
上面显示了代码处于循环。调用strings.ToLower正在创建分配，因为它们创建了需要在堆上分配的新字符串。这些调用是不必要的，因为这些调用可以在循环外部完成。
可以更改119行如下。
// Before the code change.
if strings.Contains(strings.ToLower(item.Description), strings.ToLower(term)) {
// After the code change.
if strings.Contains(item.Description, term) {
使用这些新代码更改再次构建项目，并再次通过服务器运行10k请求。
$ go build
$ GODEBUG=gctrace=1 ./project > /dev/null
gc 3 @6.156s 0%: 0.011+0.72+0.068 ms clock, 0.13+0.21/1.5/3.2+0.82 ms cpu, 4->4->2 MB, 5 MB goal, 12 P
.
.
.
gc 1404 @8.808s 7%: 0.005+0.54+0.059 ms clock, 0.060+0.47/0.79/0.25+0.71 ms cpu, 4->5->2 MB, 5 MB goal, 12 P
上面显示了在代码更改之后，现在花了1402个集合来处理相同的10k请求。这些是两次运行的全部结果。
With Extra Allocations Without Extra Allocations
======================================================================
Requests : 10,000 Requests : 10,000
----------------------------------------------------------------------
Requests/sec : 1,882 r/s Requests/sec : 3,631 r/s
Total Duration : 5,311ms Total Duration : 2,753 ms
Percent Time in GC : 14% Percent Time in GC : 7%
Total Collections : 2,551 Total Collections : 1,402
----------------------------------------------------------------------
Total GC Duration : 744.54ms Total GC Duration : 192.71 ms
Average Pace of GC : ~2.08ms Average Pace of GC : ~1.96ms
Requests/Collection : ~3.98 r/gc Requests/Collection : 7.13 r/gc
上面展示了比较的结果。以下内容提供了所发生事件的更多可视化效果。
图5
image.png
图5直观地显示了发生的情况。这次，收集器的处理量减少了1149次（分别为1,402和2,551）。这导致总GC时间占比从14％降低到7％。这使应用程序的运行速度提高了48％，收集时间减少了74％。
图6
图6
图6显示了该应用程序所有不同运行的对比效果。
我们学到了什么
正如我在上一篇文章中所述，优化垃圾收集关键在于减轻堆的分配压力。请记住，压力可以定义为应用程序在给定的时间内在堆上分配所有可用内存的速度。当压力减小时，收集造成的延迟将减小。正是这些延迟使你的应用程序变慢。
这并不是要放慢收集速度。这实际上是在每个收集之间或收集期间完成更多工作。你可以做的就是通过减少分配给堆的压力。
With Extra Allocations Without Extra Allocations
======================================================================
Requests : 10,000 Requests : 10,000
----------------------------------------------------------------------
Requests/sec : 1,882 r/s Requests/sec : 3,631 r/s
Total Duration : 5,311ms Total Duration : 2,753 ms
Percent Time in GC : 14% Percent Time in GC : 7%
Total Collections : 2,551 Total Collections : 1,402
----------------------------------------------------------------------
Total GC Duration : 744.54ms Total GC Duration : 192.71 ms
Average Pace of GC : ~2.08ms Average Pace of GC : ~1.96ms
Requests/Collection : ~3.98 r/gc Requests/Collection : 7.13 r/gc
上面展示了启用了垃圾回收的两个版本的应用程序的结果。很明显，删除4.48GB的分配可以使应用程序运行得更快。有趣的是，每个收集（两个版本）的平均速度几乎相同，大约为2.0ms。这两个版本之间的根本变化是，每个集合之间要完成的工作量。该应用程序从3.98 r / gc变为7.13 r / gc。完成的工作量增加了79.1％。
在任何两个收集的开始之间完成更多工作有助于将所需的收集数量从2551个减少到1402个，减少了45％。该应用程序将总GC时间从745ms减少了193ms到74ms，减少了74％，并且每个收集版本的总GC时间从14％更改为7％。当你运行不带垃圾回收的应用程序的优化版本时，性能差异仅13％，应用程序将2753ms缩短为2398ms。
结论
如果你花时间专注于减少内存分配，那么作为Go开发人员的你正在尽一切努力来优化垃圾回收器。你不可能编写出零分配的应用程序，因此重要的是要认识到生产性分配（有助于应用程序的分配）和非生产性分配（有害于应用程序的分配）之间的区别。然后，你只需对垃圾收集器充满信心和信任，使堆保持健康，并使你的应用程序持续运行。
拥有一个垃圾收集器是一个不错的权衡。我将承担垃圾收集的代价，以此来减少我负担内存管理的代价。Go希望让你作为开发人员提高工作效率同时仍然编写足够快的应用程序。垃圾收集器是实现这一目标的重要组成部分。在下一篇文章中，我将分享另一个程序，该程序显示如何分析Go应用程序并找到最佳的回收路径。
网友评论