4

我正在运行一个 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 打印输出，几乎没有我的代码打印输出的数量那么多。

编辑： 似乎将 time.Since() 的结果存储到@Verran 建议的变量中解决了这个问题。

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

看来“问题”是在fmt高负载环境中处理的方式。我希望有人能对这里发生的事情有所了解。

4

2 回答 2

0

如果您打印持续时间单位（您正在打印纳秒），您将看到，正如预期的那样，它只是单调秒的一小部分。例如，

package main

import (
    "fmt"
    "time"
)

func main() {
    var user_uid string
    startTime := time.Now()
    since := time.Since(startTime)
    fmt.Printf("%v (1) %v %v\n", user_uid, int64(since), since)
    since = time.Since(startTime)
    fmt.Printf("%v (F) %v %v\n", user_uid, int64(since), since)
}

输出：

 (1) 142 142ns
 (F) 22036 22.036µs

time.Since并fmt.Printf让出处理器，允许其他 goroutine 运行。

于 2017-12-12T13:15:02.610 回答
0

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

于 2017-12-12T13:10:35.927 回答