runtime/trace: generated timestamps have a jump in them

[mbertschler]

I discovered a problem with a trace file that was generated on a linux/arm device (Beaglebone Black ARMv7). The program was cross-compiled on my laptop go version go1.6 darwin/amd64 with GOOS=linux GOARCH=arm GOARM=7.

I generated the trace file with runtime/trace packages Start/Stop functions.
Then I transfered the file to my laptop and ran go tool trace. Web browser opened, but when clicking on something it produced the error failed to parse trace: time stamps out of order.
The check that produces this error is here: internal/trace/parser.go

I modified the source code to print the index and timestamps of the relevant events in the tracefile:

index= 1191701   ev.Ts=  147573700100
index= 1191702   ev.Ts=  147573703108
index= 1191703   ev.Ts=  147573707524
index= 1191704   ev.Ts=  147573711028
index= 1191705   ev.Ts=  147573735572
index= 1191706   ev.Ts=  147573865188
index= 1191707   ev.Ts=  147573867444
index= 1191708   ev.Ts=  147573888900
index= 1191709   ev.Ts=  147573893780
index= 1191710   ev.Ts= -147573193487
index= 1191711   ev.Ts= -147573190607
index= 1191712   ev.Ts= -147573186191
index= 1191713   ev.Ts= -147573182815
index= 1191714   ev.Ts= -147573158159
index= 1191715   ev.Ts= -147573029439
index= 1191716   ev.Ts= -147573027279
index= 1191717   ev.Ts= -147573005983
index= 1191718   ev.Ts= -147573001071
index= 1191719   ev.Ts= -147572190527

This is the tracefile: trace_1.zip
Do you also need the code? It is <200LOC but dependent on 32bit Linux system calls.

So except one jump, that looks like just the switch of the sign, everything is consistent.
I was not able to reproduce this. What could have happened here?

[dvyukov]

Please try the following patch:

diff --git a/src/runtime/os_linux_arm.go b/src/runtime/os_linux_arm.go
index 8fdfb58..f483b33 100644
--- a/src/runtime/os_linux_arm.go
+++ b/src/runtime/os_linux_arm.go
@@ -71,5 +71,5 @@ func cputicks() int64 {
        // Currently cputicks() is used in blocking profiler and to seed fastrand1().
        // nanotime() is a poor approximation of CPU ticks that is enough for the profiler.
        // randomNumber provides better seeding of fastrand1.
-       return nanotime() + int64(randomNumber)
+       return nanotime()// + int64(randomNumber)
 }

[dvyukov]

Or you are not able to reproduce it at all? If so, I guess it is it.

[minux]

But randomNumber doesn't change after program startup, so I don't understand how that could affect the sequence in this way.

[dvyukov]

@minux I meant that maybe randomNumber causes cputicks overflow, and then overflow somehow causes the jump. But randomNumber is int32, so it should not cause int64 overflow.

[gopherbot]

CL https://golang.org/cl/21730 mentions this issue.

[mbertschler]

@dvyukov I just tried my "corrupted" file again and with your change it works!
It also makes sense why the *1e9 causes the int64 to overflow here.

ev.Ts = (ev.Ts - minTs) * 1e9 / ticksPerSec