runtime: go1.7beta2 test failures on MacOS 10.12: net/http, runtime, time #16272
Comments
ianlancetaylor
changed the title
ianlancetaylor
changed the title
|
There are three failures here, all cases where the test program is hanging. In net/http In runtime In time The time failure is interesting. The stack trace shows that a call to Is this repeatable? If you reached to testing phase, your Go programs and libraries were installed. Try running |
|
I am able to reproduce the time deadlock 100% of the time on macOS 10.12 Beta (16A239j) by running: package main
import "time"
func main() {
for _ = range time.Tick(100 * time.Millisecond) {
println("ticker")
}
}It will tick an average of maybe 40-70 times before deadlocking. This fails on 1.5.1 and 1.6.2. I haven't tried on tip, but the trace ends up in the same place. |
|
tip seems to be fine on 10.11.5 |
|
Broken for me on tip too: |
|
I'm guessing this has something to do with using MacOS 10.12 beta. What I don't know is whether this is a kernel bug or a Go bug. Can you run your failing test case with the environment variable Note that that will generate a lot of output. |
|
Go test also fails in the same way for TestAfterTick from the time package. It seems to work some of the time. Here is the output using the environment variable you provided: https://gist.github.com/trevorgray/29e73f2b0d98a5b382a9bb0a5f1b9fc1 package foo
import (
"testing"
"time"
)
func TestAfterTick(t *testing.T) {
const Count = 10
Delta := 100 * time.Millisecond
if testing.Short() {
Delta = 10 * time.Millisecond
}
t0 := time.Now()
for i := 0; i < Count; i++ {
<-time.After(Delta)
}
t1 := time.Now()
d := t1.Sub(t0)
target := Delta * Count
if d < target*9/10 {
t.Fatalf("%d ticks of %s too fast: took %s, expected %s", Count, Delta, d, target)
}
if !testing.Short() && d > target*30/10 {
t.Fatalf("%d ticks of %s too slow: took %s, expected %s", Count, Delta, d, target)
}
} |
|
Here's mine with |
|
I'm sorry, I wasn't clear. Please run |
|
Ah, ok!: http://burkelibbey.s3.amazonaws.com/fail.gz I forgot about it for a few minutes, so the log is rather long. |
|
Thanks. I'm working pretty much in the dark, but my current suspicion is that something changed in the function |
|
I don't have access to the source (AFAIK?), but here's the disassemble if it helps: $ otool -tvV /usr/lib/system/libsystem_kernel.dylib | awk '/[^ ]+:/ { lbl = $1 } lbl == "___commpage_gettimeofday:" { print }'
___commpage_gettimeofday:
0000000000012690 pushq %rbp
0000000000012691 pushq %r12
0000000000012693 pushq %r13
0000000000012695 pushq %r14
0000000000012697 subq $0x8, %rsp
000000000001269b movq %rsp, %rbp
000000000001269e movq %rdi, %r12
00000000000126a1 movabsq $0x7fffffe00050, %r13
00000000000126ab movl 0x1c(%r13), %r14d
00000000000126af testl %r14d, %r14d
00000000000126b2 je 0x126fa
00000000000126b4 callq _mach_absolute_time
00000000000126b9 movl 0x28(%r13), %r8d
00000000000126bd subq 0x20(%r13), %rax
00000000000126c1 cmpl 0x1c(%r13), %r14d
00000000000126c5 jne 0x126ab
00000000000126c7 movl $0x3b9aca00, %ecx
00000000000126cc movq %rax, %rdx
00000000000126cf shrq $0x20, %rdx
00000000000126d3 divl %ecx
00000000000126d5 addl %eax, %r8d
00000000000126d8 movl $0x3e8, %ecx
00000000000126dd movl %edx, %eax
00000000000126df xorl %edx, %edx
00000000000126e1 divl %ecx
00000000000126e3 movq %r8, (%r12)
00000000000126e7 movl %eax, 0x8(%r12)
00000000000126ec xorl %eax, %eax
00000000000126ee addq $0x8, %rsp
00000000000126f2 popq %r14
00000000000126f4 popq %r13
00000000000126f6 popq %r12
00000000000126f8 popq %rbp
00000000000126f9 retq
00000000000126fa movl $0x1, %eax
00000000000126ff jmp 0x126eeHere's $ otool -tvV /usr/lib/system/libsystem_kernel.dylib | awk '/[^ ]+:/ { lbl = $1 } lbl == "_mach_absolute_time:" { print }'
_mach_absolute_time:
00000000000118a5 pushq %rbp
00000000000118a6 movq %rsp, %rbp
00000000000118a9 movabsq $0x7fffffe00050, %rsi
00000000000118b3 movl 0x18(%rsi), %r8d
00000000000118b7 testl %r8d, %r8d
00000000000118ba je 0x118b3
00000000000118bc lfence
00000000000118bf rdtsc
00000000000118c1 lfence
00000000000118c4 shlq $0x20, %rdx
00000000000118c8 orq %rdx, %rax
00000000000118cb movl 0xc(%rsi), %ecx
00000000000118ce andl $0x1f, %ecx
00000000000118d1 subq (%rsi), %rax
00000000000118d4 shlq %cl, %rax
00000000000118d7 movl 0x8(%rsi), %ecx
00000000000118da mulq %rcx
00000000000118dd shrdq $0x20, %rdx, %rax
00000000000118e2 addq 0x10(%rsi), %rax
00000000000118e6 cmpl 0x18(%rsi), %r8d
00000000000118ea jne 0x118b3
00000000000118ec popq %rbp
00000000000118ed retq
00000000000118ee nop
00000000000118ef nop |
|
I grabbed the ElCap one too: 0000000000011510 pushq %rbp
0000000000011511 pushq %r12
0000000000011513 pushq %r13
0000000000011515 pushq %r14
0000000000011517 subq $0x8, %rsp
000000000001151b movq %rsp, %rbp
000000000001151e movq %rdi, %r12
0000000000011521 movabsq $0x7fffffe00050, %r13 ## imm = 0x7FFFFFE00050
000000000001152b movl 0x1c(%r13), %r14d
000000000001152f testl %r14d, %r14d
0000000000011532 je 0x1157a
0000000000011534 callq _mach_absolute_time
0000000000011539 movl 0x28(%r13), %r8d
000000000001153d subq 0x20(%r13), %rax
0000000000011541 cmpl 0x1c(%r13), %r14d
0000000000011545 jne 0x1152b
0000000000011547 movl $0x3b9aca00, %ecx ## imm = 0x3B9ACA00
000000000001154c movq %rax, %rdx
000000000001154f shrq $0x20, %rdx
0000000000011553 divl %ecx
0000000000011555 addl %eax, %r8d
0000000000011558 movl $0x3e8, %ecx ## imm = 0x3E8
000000000001155d movl %edx, %eax
000000000001155f xorl %edx, %edx
0000000000011561 divl %ecx
0000000000011563 movq %r8, (%r12)
0000000000011567 movl %eax, 0x8(%r12)
000000000001156c xorl %eax, %eax
000000000001156e addq $0x8, %rsp
0000000000011572 popq %r14
0000000000011574 popq %r13
0000000000011576 popq %r12
0000000000011578 popq %rbp
0000000000011579 retq
000000000001157a movl $0x1, %eax
000000000001157f jmp 0x1156eThe diff: 8c8
< movabsq $0x7fffffe00050, %r13 ## imm = 0x7FFFFFE00050
---
> movabsq $0x7fffffe00050, %r13
11c11
< je 0x1157a
---
> je 0x126fa
16,17c16,17
< jne 0x1152b
< movl $0x3b9aca00, %ecx ## imm = 0x3B9ACA00
---
> jne 0x126ab
> movl $0x3b9aca00, %ecx
22c22
< movl $0x3e8, %ecx ## imm = 0x3E8
---
> movl $0x3e8, %ecx
36,37c36
< jmp 0x1156e
<
---
> jmp 0x126eeAt a glance, it looks the same. |
|
Thanks! Any change in |
|
This one again seems pretty similar: 0000000000010333 pushq %rbp
0000000000010334 movq %rsp, %rbp
0000000000010337 movabsq $0x7fffffe00050, %rsi ## imm = 0x7FFFFFE00050
0000000000010341 movl 0x18(%rsi), %r8d
0000000000010345 testl %r8d, %r8d
0000000000010348 je 0x10341
000000000001034a lfence
000000000001034d rdtsc
000000000001034f lfence
0000000000010352 shlq $0x20, %rdx
0000000000010356 orq %rdx, %rax
0000000000010359 movl 0xc(%rsi), %ecx
000000000001035c andl $0x1f, %ecx
000000000001035f subq (%rsi), %rax
0000000000010362 shlq %cl, %rax
0000000000010365 movl 0x8(%rsi), %ecx
0000000000010368 mulq %rcx
000000000001036b shrdq $0x20, %rdx, %rax
0000000000010370 addq 0x10(%rsi), %rax
0000000000010374 cmpl 0x18(%rsi), %r8d
0000000000010378 jne 0x10341
000000000001037a popq %rbp
000000000001037b retq1,2c1,2
< 0000000000010333
< pushq %rbp
---
> 00000000000118a5
> pushq %rbp
4c4
< movabsq $0x7fffffe00050, %rsi ## imm = 0x7FFFFFE00050
---
> movabsq $0x7fffffe00050, %rsi
6,7c6,7
< testl %r8d, %r8d
< je 0x10341
---
> testl %r8d, %r8d
> je 0x118b3
12c12
< orq %rdx, %rax
---
> orq %rdx, %rax
19c19
< shrdq $0x20, %rdx, %rax
---
> shrdq $0x20, %rdx, %rax
22c22
< jne 0x10341
---
> jne 0x118b3
24a25,27
> nop
> nop
> |
|
I see three differences between the Go computation and the disassembled code.
|
|
Actually the generation checking is not a difference, it's just that the Go code loads everything from memory while the Darwin code does not. |
|
Can you see if the change in https://golang.org/cl/24782 helps at all? |
|
CL https://golang.org/cl/24782 mentions this issue. |
|
Unfortunately that doesn't seem to have changed anything (after applying the patch, nuking all artifacts, and building fresh) |
|
Pity. Thanks for testing it. I guess this is going to need some serious debugging somehow. |
|
I'm looking at a machine with Sierra installed now. The problem seems to be that Specifically, the first call to |
|
Looks like the problem is that that Testing, and will check 386 also. |
|
Is that the only system call with such a change in behavior? I guess we'll see how all.bash does afterwards. |
|
CL https://golang.org/cl/24812 mentions this issue. |
Updates #16272. Change-Id: If5444b8de8678eeb9be10b62a929e2e101d1dd91 Reviewed-on: https://go-review.googlesource.com/24900 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
|
So future versions of OS X will not be able to have Go installed entirely from source (with the 1.4 bootstrap) and we'll need to use binary packages on OS X from here on out? |
|
It's only a problem if the program needs to be quiescent... I suspect we might get lucky and the compilers are never quiescent, so it will work in practice. That still seems scary, though. |
|
CL https://golang.org/cl/24967 mentions this issue. |
In the beta version of the macOS Sierra (10.12) release, the gettimeofday system call changed on x86. Previously it always returned the time in the AX/DX registers. Now, if AX is returned as 0, it means that the system call has stored the values into the memory pointed to by the first argument, just as the libc gettimeofday function does. The libc function handles both cases, and we need to do so as well. Fixes #16272. Fixes #16354. Change-Id: Ibe5ad50a2c5b125e92b5a4e787db4b5179f6b723 Reviewed-on: https://go-review.googlesource.com/24812 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org> Reviewed-on: https://go-review.googlesource.com/24967
Updates #16354 Updates #16272 Change-Id: I73e8df40621a0a17a1990f3b10ea996f4fa738aa Reviewed-on: https://go-review.googlesource.com/25014 Run-TryBot: Ian Lance Taylor <iant@golang.org> Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org>
mikioh
changed the title
|
CL https://golang.org/cl/31729 mentions this issue. |
This is a cherry-pick of https://go-review.googlesource.com/24812 to the release-branch-go1.4 In the beta version of the macOS Sierra (10.12) release, the gettimeofday system call changed on x86. Previously it always returned the time in the AX/DX registers. Now, if AX is returned as 0, it means that the system call has stored the values into the memory pointed to by the first argument, just as the libc gettimeofday function does. The libc function handles both cases, and we need to do so as well. Fixes #16272. Change-Id: I490ed0a82e251fce73becc4722cbe276feebc7b7 Reviewed-on: https://go-review.googlesource.com/31729 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
In the beta version of the macOS Sierra (10.12) release, the gettimeofday system call changed on x86. Previously it always returned the time in the AX/DX registers. Now, if AX is returned as 0, it means that the system call has stored the values into the memory pointed to by the first argument, just as the libc gettimeofday function does. The libc function handles both cases, and we need to do so as well. Fixes golang#16272. Change-Id: Ibe5ad50a2c5b125e92b5a4e787db4b5179f6b723 Reviewed-on: https://go-review.googlesource.com/24812 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
This is a cherry-pick of https://go-review.googlesource.com/24812 to the release-branch-go1.4 In the beta version of the macOS Sierra (10.12) release, the gettimeofday system call changed on x86. Previously it always returned the time in the AX/DX registers. Now, if AX is returned as 0, it means that the system call has stored the values into the memory pointed to by the first argument, just as the libc gettimeofday function does. The libc function handles both cases, and we need to do so as well. Fixes golang#16272. Change-Id: I490ed0a82e251fce73becc4722cbe276feebc7b7 Reviewed-on: https://go-review.googlesource.com/31729 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
This is a cherry-pick of https://go-review.googlesource.com/24812 to the release-branch-go1.4 In the beta version of the macOS Sierra (10.12) release, the gettimeofday system call changed on x86. Previously it always returned the time in the AX/DX registers. Now, if AX is returned as 0, it means that the system call has stored the values into the memory pointed to by the first argument, just as the libc gettimeofday function does. The libc function handles both cases, and we need to do so as well. Fixes golang#16272. Change-Id: I490ed0a82e251fce73becc4722cbe276feebc7b7 Reviewed-on: https://go-review.googlesource.com/31729 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
This is a cherry-pick of https://go-review.googlesource.com/24812 to the release-branch-go1.4 In the beta version of the macOS Sierra (10.12) release, the gettimeofday system call changed on x86. Previously it always returned the time in the AX/DX registers. Now, if AX is returned as 0, it means that the system call has stored the values into the memory pointed to by the first argument, just as the libc gettimeofday function does. The libc function handles both cases, and we need to do so as well. Fixes golang#16272. Change-Id: I490ed0a82e251fce73becc4722cbe276feebc7b7 Reviewed-on: https://go-review.googlesource.com/31729 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
This is a cherry-pick of https://go-review.googlesource.com/24812 to the release-branch-go1.4 In the beta version of the macOS Sierra (10.12) release, the gettimeofday system call changed on x86. Previously it always returned the time in the AX/DX registers. Now, if AX is returned as 0, it means that the system call has stored the values into the memory pointed to by the first argument, just as the libc gettimeofday function does. The libc function handles both cases, and we need to do so as well. Fixes golang#16272. Change-Id: I490ed0a82e251fce73becc4722cbe276feebc7b7 Reviewed-on: https://go-review.googlesource.com/31729 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
This is a cherry-pick of https://go-review.googlesource.com/24812 to the release-branch-go1.4 In the beta version of the macOS Sierra (10.12) release, the gettimeofday system call changed on x86. Previously it always returned the time in the AX/DX registers. Now, if AX is returned as 0, it means that the system call has stored the values into the memory pointed to by the first argument, just as the libc gettimeofday function does. The libc function handles both cases, and we need to do so as well. Fixes golang#16272. Change-Id: I490ed0a82e251fce73becc4722cbe276feebc7b7 Reviewed-on: https://go-review.googlesource.com/31729 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
Please answer these questions before submitting your issue. Thanks!
What version of Go are you using (
go version)?I am building go1.7beta2 from source.
What operating system and processor architecture are you using (
go env)?macOS 10.12 Beta (16A239j)
What did you do?
If possible, provide a recipe for reproducing the error.
A complete runnable program is good.
A link on play.golang.org is best.
I am trying to build the go1.7beta2 from source and the build is failing on the "Testing packages" step.
What did you expect to see?
The build to complete successfully.
What did you see instead?
The build fails on the "Testing packages" step.
The text was updated successfully, but these errors were encountered: