go - time.Since() 的奇怪行为

Question

我正在运行一个 GO (1.9.2) 程序，我的代码类似于:

startTime := time.Now()
...
...
fmt.Printf("%v (1) %v \n", user.uid, int64(time.Since(startTime)))
fmt.Printf("%v (F) %v \n", user.uid, int64(time.Since(startTime)))

(两个fmt语句在连续的行上)

我预计打印输出的时间会差不多，但这里是打印的一些结果:

921 (1)    2000100
921 (F) 3040173800

(3 秒)

360 (1)    2000100
360 (F) 1063060800

(1 秒)

447 (1)    4000200
447 (F) 2564146700

(2.5 秒)

两次打印输出之间的时间差一直很高。

这种现象的解释是什么？

额外信息:根据 pprof，打印时大约有 15000 个 goroutine 正在运行，但其中大部分正在等待套接字上的传入数据。

我用 GODEBUG=gctrace=1 运行了代码，但是没有很多 GC 打印输出，几乎没有我代码的打印输出数量那么多。

编辑:似乎按照@Verran 的建议将 time.Since() 的结果存储到变量中可以解决问题。

将 fmt 更改为 log 没有帮助，但打印不再同步。

似乎“问题”在于 fmt 在高负载环境中的处理方式。我希望有人可以阐明这里发生的事情。

Answer 1

不要认为问题与您发布的代码有关。为了找到问题，我建议打印 mem stats比如 GC 调用的次数以及两次打印之间在 GC 上花费了多少。我建议也打印 startTime 以 100% 确定两次连续打印属于同一个 goroutine。