Go版本
go版本 go1.22.4 linux/amd64
在你的模块/工作区的go env输出：
GO111MODULE='on'
GOARCH='amd64'
GOBIN=''
GOCACHE='/home/user/.cache/go-build'
GOENV='/home/user/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/home/user/go-repos/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='/home/user/go-repos:/opt/go/path:/home/user/go-code'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/home/user/go/src/github.com/golang/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/home/user/go/src/github.com/golang/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.22.4'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='g++'
CGO_ENABLED='1'
GOMOD='/home/user/go/src/github.com/uber-go/zap/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build1740765925=/tmp/go-build -gno-record-gcc-switches'你做了什么？
我们一直在进行Go tip在Uber的性能测试，以准备Go 1.23。
你看到了什么？
我们注意到在拥有大量核心(96个)的linux机器上，Zap的所有Field日志基准测试中出现了约8%的性能下降。这些基准测试看起来像这样：
logger := New(
zapcore.NewCore(
zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig),
&ztest.Discarder{}, // No actual i/o, logs get discarded.
DebugLevel,
),
)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
log.Info("Boolean.", Bool("foo", true))
}由于我们没有可用的隔离linux环境，因此这些结果可能会受到轻微的邻居问题的影响，但我们始终在这些基准测试中看到一定程度的性能下降：
$ go version
go version go1.22.4 linux/amd64
$ go test -bench Field -run nounittests -count 25 . | tee go1224.log
$ ~/go/src/github.com/golang/go4/bin/go version
go version devel go1.23-93bbf719a6 Wed Jun 5 17:30:16 2024 +0000 linux/amd64
$ go test -bench Field -run nounittests -count 25 . | tee 93bbf719a6.log
$ benchstat go1224.log 93bbf719a6.log
goos: linux
goarch: amd64
pkg: go.uber.org/zap
cpu: AMD EPYC 7B13
│ go1.22.4.log │ 93bbf719a6.log │
│ sec/op │ sec/op vs base │
BoolField-96 110.6n ± 6% 127.9n ± 8% +15.64% (p=0.001 n=25)
ByteStringField-96 139.7n ± 1% 149.9n ± 2% +7.30% (p=0.000 n=25)
Float64Field-96 112.2n ± 4% 125.2n ± 4% +11.59% (p=0.000 n=25)
IntField-96 108.7n ± 3% 116.2n ± 2% +6.90% (p=0.000 n=25)
Int64Field-96 105.9n ± 4% 113.2n ± 2% +6.89% (p=0.009 n=25)
StringField-96 104.4n ± 2% 115.4n ± 4% +10.54% (p=0.000 n=25)
StringerField-96 105.4n ± 3% 115.5n ± 4% +9.58% (p=0.000 n=25)
TimeField-96 109.6n ± 2% 117.4n ± 2% +7.12% (p=0.000 n=25)
DurationField-96 111.6n ± 3% 121.9n ± 3% +9.23% (p=0.000 n=25)
ErrorField-96 108.4n ± 2% 115.7n ± 4% +6.73% (p=0.000 n=25)
ErrorsField-96 184.1n ± 2% 205.1n ± 4% +11.41% (p=0.000 n=25)
StackField-96 713.0n ± 3% 813.3n ± 3% +14.07% (p=0.000 n=25)
ObjectField-96 117.2n ± 2% 130.9n ± 3% +11.69% (p=0.000 n=25)
ReflectField-96 317.6n ± 2% 346.0n ± 3% +8.94% (p=0.000 n=25)
10Fields-96 584.7n ± 2% 622.4n ± 4% +6.45% (p=0.000 n=25)
100Fields-96 5.919µ ± 3% 5.630µ ± 5% ~ (p=0.073 n=25)
geomean 196.5n 213.4n +8.61%我们稍微调整了GOMAXPROCS,并注意到性能下降确实与并行性有关。
我们在CPU分析中没有看到很多内容，除了运行时包中大约增加了2-4%的样本。
我们能够使用git bisect来确定e995aa95cb5f379c1df5d5511ee09970261d877f是其中一个原因。具体来说，对这些高度并行化的基准测试添加的调用nanotime()似乎会导致性能下降。然而，这个提交本身似乎不足以解释整个性能下降：
$ ~/go/src/github.com/golang/go3/bin/go version
go version devel go1.23-e995aa95cb Mon Apr 8 21:43:16 2024 +0000 linux/amd64
$ ~/go/src/github.com/golang/go3/bin/go test -bench Field -run nounittests -count 25 . | tee e995aa95cb.log
$ benchstat go1224.log e995aa95cb.log
goos: linux
goarch: amd64
pkg: go.uber.org/zap
cpu: AMD EPYC 7B13
│ go1.22.4.log │ e995aa95cb.log │
│ sec/op │ sec/op vs base │
BoolField-96 110.6n ± 6% 121.1n ± 6% +9.49% (p=0.004 n=25)
ByteStringField-96 139.7n ± 1% 145.9n ± 2% +4.44% (p=0.002 n=25)
Float64Field-96 112.2n ± 4% 121.1n ± 1% +7.93% (p=0.000 n=25)
IntField-96 108.7n ± 3% 112.5n ± 2% +3.50% (p=0.009 n=25)
Int64Field-96 105.9n ± 4% 111.4n ± 3% ~ (p=0.200 n=25)
StringField-96 104.4n ± 2% 111.5n ± 2% +6.80% (p=0.000 n=25)
StringerField-96 105.4n ± 3% 113.4n ± 3% +7.59% (p=0.000 n=25)
TimeField-96 109.6n ± 2% 117.6n ± 2% +7.30% (p=0.000 n=25)
DurationField-96 111.6n ± 3% 116.8n ± 2% +4.66% (p=0.000 n=25)
ErrorField-96 108.4n ± 2% 113.7n ± 2% +4.89% (p=0.002 n=25)
ErrorsField-96 184.1n ± 2% 201.7n ± 4% +9.56% (p=0.000 n=25)
StackField-96 713.0n ± 3% 770.9n ± 2% +8.12% (p=0.000 n=25)
ObjectField-96 117.2n ± 2% 127.2n ± 3% +8.53% (p=0.000 n=25)
ReflectField-96 317.6n ± 2% 349.4n ± 5% +10.01% (p=0.000 n=25)
10Fields-96 584.7n ± 2% 620.5n ± 5% +6.12% (p=0.005 n=25)
100Fields-96 5.919µ ± 3% 6.046µ ± 25% ~ (p=0.064 n=25)
geomean 196.5n 209.5n +6.62%我们无法可靠地识别出除此之外的任何其他提交，它们可以解释更多的性能下降。
注意：这不是#67857的重复，而是对不同的Zap基准测试性能下降的调查。
你期望看到什么？
实际性能没有下降。
8条答案
按热度按时间roqulrg31#
CC @golang/runtime
hrirmatl2#
这些日志基准测试似乎涉及到非常紧密的循环，这使我相信这可能是由于不幸的微架构效应导致的 - 请参阅我对 #67857 的评论。
我的下一个问题是：这是否以任何方式对应于生产级别的回归？除非世界被停止了很多次，否则我不希望 15*
GOMAXPROCSCPU 纳秒的 CPU 时间对任何实际程序的性能产生任何有意义的影响(参考您的二分查找结果)。我 可能会在停止世界的微基准测试中看到它产生影响。我可能会建议尝试设置
GOMEMLIMIT=<something big>和GOGC=off在您的基准测试中，以尝试消除或最小化基准测试的 GC 成本(尽管仍然会测量分配成本，但我认为您关心这个问题)。我之所以这么说，是因为微基准测试在某种程度上可能会成为 GC 的折磨测试，从而使基准测试变得不那么有用。换句话说，支配您基准测试的成本并不反映您代码在现实世界中的实际成本。例如，一个在循环中分配内存、立即释放内存并具有极小活动堆(与大多数微基准测试非常相似！)的基准测试将看到非常、非常高的 GC 周期数，因为它将处于最小总堆大小为 4 MiB 的位置。这意味着大量的 STWs 和 CPU 时间花费在标记工作上，这些工作根本不会转化为具有可观活动堆的实际生产系统。GC 的棘手之处在于其频率(因此其成本)与您的活动堆成正比，通过
GOGC计算得出，因此将 GC 视为“基准测试的一部分”实际上是非常困难的。如果基准测试测量某些更大的端到端系统的性能，就会容易得多。我很好奇设置
GOMEMLIMIT为某个大值和GOGC=off是否会使问题完全消失。如果是这样，我就不太担心这些回归了。如果不是这样，那么我认为解决这个问题就变得更加重要了。此外，如果这个回归出现在更多的端到端基准测试或生产环境中，那就更值得警惕了。我还想知道，您是否能够比较使用 (
pprof -diff_base=old.prof new.prof)前后的配置文件？即使是 8% 的回归也应该像痣一样显眼。b4qexyjb3#
嘿@mknyszek -感谢快速的回复和想法！
你关于微基准测试是垃圾回收折磨测试的解释很有道理 -这些测试正在快速分配内存，这些内存很快就会变得无用 -这导致了一致分配但目标内存较低的情况，从而经常触发垃圾回收。我想这会加剧在大型基准测试/应用程序中原本微不足道的任何垃圾回收性能下降。
不幸的是，我们实际测试Go tip在生产环境中并不现实 -但我们可能可以在标记了rc版本后进行此操作。
我确实关闭了GC并重新运行了这些基准测试，正如你所预测的，这似乎确实导致了两个版本之间的性能没有下降。如我之前提到的，我们在两个版本之间很难辨别出任何差异，但我试图通过强制更多的GC(GOGC=50)来使问题变得更糟，希望两个版本之间的差异能更好地显现出来，并且确实发现
gcBgMarkWorker在使用这个时CPU时间大约增加了3% -这似乎与你的解释相符。我没有发现其他显著的差异(如果有帮助的话，我很乐意分享分析结果)。gcxthw6b4#
嘿 @mknyszek -感谢快速的回复和想法！
没问题。这些报告很重要。：)我希望我的回复没有阻止未来的报告。感谢你们对 tip 进行的全面问题排查 - 你们这样做确实有助于性能测试。
关于微基准测试是垃圾回收折磨测试的说法，你的解释是有道理的 - 这些测试会快速分配内存，但很快就会变得无用 - 这会导致一致分配但目标内存较低的情况，从而经常触发垃圾回收。我想这会加剧在大型基准测试/应用程序中原本微不足道的任何垃圾回收性能下降。
是的，生成这种基准测试很容易，有点不幸。
不幸的是，我们实际上无法在生产环境中测试 Go tip - 但我们可能可以在标记了 rc 版本后进行测试。
可以理解。希望 RC 能给我们一些反馈。
我确实关闭了 GC 并重新运行了这些基准测试，正如你所预测的那样，这似乎确实导致了两个版本之间的性能没有下降。就像我之前提到的，我们在两个版本之间很难区分性能差异，但我试图通过强制更多的 GC(GOGC=50)来使问题变得更糟，希望性能差异能更好地显现出来，并确实发现
gcBgMarkWorker在这种情况下 CPU 时间增加了约 3% - 这与你的解释相符。我没有发现其他显著的差异(如果有帮助的话，我很乐意分享性能分析)。明白了，很高兴知道这一点！感谢你的检查。
我们很难在两个版本之间区分性能差异
这是不幸的；只是为了澄清一下，即使是在自动化差异化的情况下吗？我唯一可能建议的另一件事是，如果你能做到的话，对 Linux 上的
perf做类似的差异化性能分析，这通常会产生更准确的整体结果。我会暂时将此问题保留，同时调查 #67822 ,以防它变得相关。
6xfqseft5#
相似问题
(如果这个有帮助或无帮助，请给表情投票；欢迎在 this discussion 中提供更详细的反馈。)
gcmastyq6#
我在我的高核心2插槽机器上运行了这些基准测试，有链接时间随机化(如本注解中所述：#67822 (评论))。
下面是我在没有随机化的情况下看到的情况；稳定：
现在，当我添加文本布局随机化(10个示例的-count=3运行，每个都有一个随机种子)时，会发生什么：
请注意
p值，它们现在都在Map上。所以我强烈怀疑除了@mknyszek提到的垃圾回收器痕迹之外，一些额外的表观衰减可能是由于循环对齐(例如，在一个情况下恰好得到“正确的”对齐，而在另一个情况下得到“错误的”对齐)。vsdwdz237#
一些表观降解的额外部分是由于环对齐引起的。
嗯...顺便说一下，我无法使用第67822号脚本(评论)中的脚本，包括相同的10个种子来重现这个问题。也许我做错了什么。
没有链接器随机化：
链接器随机化：
我对go是否被正确调用进行了合理性检查。
非常奇怪。
cedebl8k8#
有趣的是，看起来机器类型(微架构)在这里起着很大的作用，我本应该一直预料到这一点。我没有访问到2个插槽(96核心)的AMD EPYC 7B13,但我确实有一个单插槽的AMD EPYC 7B13,我可以像你提到的那样看到性能下降。无论是有布局随机化还是没有布局随机化，我得到的结果大致相同。谢谢。