Странное поведение времени.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 процедур, но большинство из них ожидают поступления данных в сокеты.

Я запустил код с GODEBUG=gctrace=1 но распечаток GC не так много, не так много, как количество распечаток моего кода.

РЕДАКТИРОВАТЬ: Кажется, что сохранение результата time.Since() в переменные, как предложено @Verran, решает проблему.

Изменение на fmt в log не помогло, но распечатки больше не синхронизируются.

Похоже, "проблема" в пути fmt обрабатывается в условиях высокой нагрузки. Я надеюсь, что кто-то сможет пролить свет на то, что здесь происходит.

Answer 1

Не думайте, что проблема связана с вашим размещенным кодом. Чтобы найти проблему, я предлагаю напечатать статистику mem, такую ​​как количество вызовов GC и сколько было потрачено в GC между двумя отпечатками. Предлагаю распечатать startTime Кроме того, чтобы быть на 100% уверенным, что два последовательных отпечатка принадлежат одной и той же программе.

Answer 2

Если вы напечатаете единицы измерения длительности (вы печатаете наносекунды), вы увидите, что, как и ожидалось, это всего лишь доля монотонной секунды спустя. Например,

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 дать процессор, позволяющий запускать другие программы.