runtime: time goes backwards on windows-arm64 (frequent TestGcLastTime failures)

[bcmills]

$ greplogs --dashboard -md -l -e FAIL: TestGcLastTime

2021-08-26T19:07:27-1f8d456/windows-arm64-10
2021-08-22T13:14:19-bd68459/windows-arm64-10
2021-08-19T09:11:02-3bdc179/windows-arm64-10
2021-08-16T23:03:03-df9c5d8/windows-arm64-10
2021-08-13T00:20:28-4c8ffb3/windows-arm64-10
2021-06-29T19:30:24-e294b8a/windows-arm64-10
2021-06-08T05:02:19-c20bcb6/windows-arm64-aws
2021-06-05T19:52:26-e1fa260/windows-arm64-aws

[bcmills]

These failures are new as of Go 1.17 because windows-arm64 support itself is new as of Go 1.17, so marking as release-blocker for the next release: we should not allow builder flakiness to increase from one release to the next.

(If we can determine that this test failure does not demonstrate a significant problem on the new platform, it should be skipped on that platform and the issue can be moved to the backlog.)

CC @golang/release

[aclements]

I looked through some of the logs and they all show time (as measured by time.Now().UnixNano()) moving backwards.

What's interesting is they all appear to roll over in the last 8 digits. The more significant digits are the same between the two reads. To me this suggests a shear when reading the time.

1630030642099881100 => 1630030642000853600
1629664923099568500 => 1629664923000568000
1629390290099822500 => 1629390290000990900
1629181133099089200 => 1629181133000075200
1628840582099496300 => 1628840582001301100

But I can't figure out how we would get shear at 8 decimal digits specifically. Time itself is split between seconds and nanoseconds, but nanoseconds are the bottom 9 digits. time.now in runtime/time_windows_arm64.s reads the low 32 bits and high 32 bits of the time separately with no memory barriers (this is the same on all Windows architectures), but those are in units of 100ns, so if that sheared, I would expect it to be at 100<<32 = 429496729600 ns.

@rsc wrote the windows/arm64 time.now. Also cc @zx2c4 .

[aclements]

As an experiment, I did the same comparison in hex. There's no obvious roll-over pattern in hex, so this definitely seems to be related to a decimal representation of time.

0x169f083b**935d848c** => 0x169f083b**8d767a60**
0x169dbb9cf**c439974** => 0x169dbb9cf**65cf8c0**
0x169cc1d**601dedfa4** => 0x169cc1d**5fbfad2b4**
0x169c039bd**923bd30** => 0x169c039bd**33ce7c0**
0x169acde1**23c7ed6c** => 0x169acde1**1ded966c**

[aclements]

Also cc @bufflig and @alexbrainman for thoughts.

I'm not worried about the test itself, but this seems to indicate a more fundamental issue with reading time on windows/arm64.

[aclements]

Actually, it's possible this was caused by #48476, which was fixed three days ago.

[aclements]

Nevermind, #48476 only applied to arm32.

[alexbrainman]

It could be a bug in OS. Not many people use windows-arm64 OS.

Alex

[heschi]

cc @mknyszek

[aclements]

Ping @bufflig

[dmitshur]

CC @jeremyfaller.

[dmitshur]

@jstarks Would you be able to also take a look at this issue? Thanks.

[jstarks]

In runtime·nanotime1, the high-low-high algorithm is used to read the current 64-bit interrupt time as three 32-bit values. This code was probably copied from the AMD64 version. However, ARM64 has a looser memory model than x86/AMD64, so you need some extra memory barriers to make the algorithm work. These are missing (as @aclements points out).

The data points above are consistent with a reordering of the loads, such that the low 32 bits is not correctly matched to the high 32 bits. This can cause the low 32 bits to move backward between measurements, or more generally be wrong when the high bits are changing. The one confusing entry was where it appeared that high value was moving backward too, but that's because aclements's values were multiplied by 100 after they were read.

The fix is not to add memory barriers but to do a single 64-bit read of the time in one instruction. That's what we do in Windows (and I recommend changing the AMD64 code to match, even though there's no race condition due to the stricter memory model).

[bufflig]

I missed the ping due to messed up mail notification config. I'll pick it up.

Thanks for the analysis!

[gopherbot]

Change https://golang.org/cl/361057 mentions this issue: runtime: on windows, read nanotime with one instruction on 64-bit

[zx2c4]

@bufflig I submitted a CL already: https://go-review.googlesource.com/c/go/+/361057

[bufflig]

Ah, awesome. Thanks!

[zx2c4]

That's not really thoroughly tested, so if you want to run it through the paces on various hardware, feel free.

[bufflig]

Ack, I will run it on anything I can get my hands on :)

[aclements]

Dividing by 100 (decimal) and then comparing in hex does indeed reveal a much clearer pattern:

0x39e90ad5f4229b => 0x39e90ad5e50658
0x39e5b7547150e5 => 0x39e5b7546235b0
0x39e337e66b3051 => 0x39e337e65c1bb5
0x39e150eb21a32c => 0x39e150eb128770
0x39de3802eaf593 => 0x39de3802dbf9d3

What I'm still missing is that roll-over seems to be happening at 24 bits. If the two 32-bit reads were inconsistent, shouldn't we see the roll-over at 32 bits?

(Using a single 64-bit load is a clear improvement and may well fix this bug, I'm just not quite seeing how all the dots connect yet. I blame any slowness on my part on baby-induced sleep deprivation. :)

[zx2c4]

If the two 32-bit reads were inconsistent, shouldn't we see the roll-over at 32 bits?

Is this just a matter of the actual timing of the race and the precision of the clock? That is, maybe those top 8 bits just didn't change between reads, because that takes longer?

[bufflig]

I believe that this did not actually fix the problem. On arm64 time still moves backwards. Looking at the assembler, it appears to me that it's rather a typo - it calculates (x / 1000000000, x % 100000000) instead of (x / 1000000000, x % 1000000000) (one zero to few in the x % expression). That I think fits perfectly with the symptoms as well.

Or am I reading it completely wrong?

[jstarks]

Haha! You're right. The comment has the right constant but the code has the wrong one.

go/src/runtime/time_windows_arm64.s

Line 45 in cfd016d

MOVD $100000000, R2

The memory ordering fix is still necessary for correctness but I guess it's not actually hitting in practice.

[zx2c4]

Your reading of the assembly looks correct. And actually, this matches what's in the comment too:

        // Code stolen from compiler output for:
        //
        //      var x uint64
        //      func f() (sec uint64, nsec uint32) { return x / 1000000000, uint32(x % 100000000) }
        //

One less zero in that second expression. But actually, that code is all over the place:

• sys_plan9_amd64.s
• time_windows_amd64.s
• time_windows_arm64.s

Seems like a good catch?

[zx2c4]

Haha! You're right. The comment has the right constant but the code has the wrong one.

Wait, they both look wrong to me...

[jstarks]

The comment has 9 zeroes, the constant has 8.

[zx2c4]

For the modulo?

[zx2c4]

Looks like on the remaining two platforms, the constant is fine and doesn't match the comment. But on ARM64 the constant and comment are both wrong.

Sending a patch.

[ianlancetaylor]

Gah, thanks for spotting that. Perhaps the assembler should support the 1e9 syntax we can use in Go.

[gopherbot]

Change https://golang.org/cl/361474 mentions this issue: runtime: use correct constant when computing nsec remainder

[zx2c4]

@gopherbot please backport this to 1.17

[gopherbot]

Backport issue(s) opened: #49369 (for 1.17).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

[gopherbot]

Change https://golang.org/cl/361476 mentions this issue: [release-branch.go1.17] runtime: use correct constant when computing nsec remainder

[gopherbot]

Change https://golang.org/cl/361475 mentions this issue: [release-branch.go1.17] runtime: on windows, read nanotime with one instruction or issue barrier