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

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