5

I am running a GO (1.9.2) program and I have code similar to:

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)))

(The two fmt statements are on consecutive lines)

I expected that the printout would be of similar time but here are some results of the print:

921 (1)    2000100
921 (F) 3040173800

(3 seconds)

360 (1)    2000100
360 (F) 1063060800

(1 second)

447 (1)    4000200
447 (F) 2564146700

(2.5 seconds)

The time difference is consistently high between the two printouts.

What could be the explanation of this phenomenon?

Extra info: According to pprof there are ~15000 goroutines running at the time of the prints but most of them are waiting for incoming data on sockets.

I ran the code with GODEBUG=gctrace=1 but there aren't many GC printouts, not nearly as many as the number of printouts of my code.

EDIT: It seems that storing the result of time.Since() into variables as suggested by @Verran solves the issue.

Changing to fmt to log didn't help but the prints are no longer synchronized.

It appears the "problem" is in the way fmt is handled in a high load environment. I hope someone could shed some light to what is going on here.

Buzzy
  • 2,905
  • 3
  • 22
  • 31
  • 1. Three seconds elapsed between the two time.Since calls, 2. Monotonic time. – Volker Dec 12 '17 at 13:09
  • It might not be related, but it would be better to use a synchronized method of output to make sure you're not interleaving writes to stdout. Plus, if you use `log` you can also get absolute timestamps to further corroborate your findings. – JimB Dec 12 '17 at 15:45
  • Note that printing to console (or file) involves a syscall, which often results in the goroutine in question being rescheduled. If you have a ton of goroutines running, it might be a bit before this goroutine is scheduled again and can proceed to the second print statement. – Kaedys Dec 12 '17 at 19:27
  • What does it look like if you write the two Durations to variables and then print them out together in one `fmt.Printf("%v\n%v\n", since1, since2)` statement? – Verran Dec 13 '17 at 00:28
  • @Verran If fixes the problem if I do that. The numbers match. – Buzzy Dec 13 '17 at 09:42
  • 1
    I'd say that pretty much confirms in my mind that it's context switching on the fmt.Println and not getting back to the next time.Since() call for a while because there are so many other goroutines waiting for a chance to run. – Verran Dec 13 '17 at 19:33

2 Answers2

0

Don't think the problem is related to your posted code. To find the problem I suggest printing mem stats like number of GC calls and how much was spent in GC between two prints. I suggest to print startTime too to be 100% sure that two consecutive print belongs to same goroutine.

Arman Ordookhani
  • 6,031
  • 28
  • 41
  • Each user runs its own goroutine so as long as the ids match its the same one. I thought that if I set gctrace to 1 I will see all GC actions. – Buzzy Dec 12 '17 at 15:37
0

If you print the duration units (you are printing nanoseconds), you will see, as expected, it's just a fraction of a monotonic second later. For example,

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)
}

Output:

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

time.Since and fmt.Printf yield the processor, allowing other goroutines to run.

peterSO
  • 158,998
  • 31
  • 281
  • 276
  • It's not a fraction of second it's 3 seconds for example in the first case. – Arman Ordookhani Dec 12 '17 at 13:19
  • @ArmanOrdookhani: There are "~15000 goroutines running at the time of the prints." What else is running on the machine? – peterSO Dec 12 '17 at 13:24
  • @peterSO the original code would print with units and it was anywhere between 100ms and 100 seconds. The machine is dedicated to this particular application but there are a lot of users connecting via sockets so there are a bunch of listeners and other stuff going on. – Buzzy Dec 12 '17 at 15:35
  • I added the time in seconds to the question – Buzzy Dec 12 '17 at 15:40