Skip to content

cmd/go: test gets hung #27720

New issue
New issue
Closed
Closed
cmd/go: test gets hung#27720
Labels
FrozenDueToAgeNeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
 
Go1.12
@alecthomas

Description

@alecthomas
alecthomas
opened on Sep 18, 2018

What version of Go are you using (go version)?

go version go1.11 darwin/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/aat/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/aat/.go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/go1.11"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go1.11/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/aat/Downloads/gap/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/db/mz_hvw_x54q6mcrbgmslnq7400042q/T/go-build995577183=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

[aat@cavern:~/Downloads/gap]go test -x -v ./...
^\SIGQUIT: quit
PC=0x7fff5606ccee m=0 sigcode=0

goroutine 0 [idle]:
runtime.pthread_cond_wait(0x1961440, 0x1961400, 0x7ffe00000000)
	/usr/local/go/src/runtime/sys_darwin.go:302 +0x51
runtime.semasleep(0xffffffffffffffff, 0x100bf64)
	/usr/local/go/src/runtime/os_darwin.go:54 +0x70
runtime.notesleep(0x1961200)
	/usr/local/go/src/runtime/lock_sema.go:167 +0xe3
runtime.stopm()
	/usr/local/go/src/runtime/proc.go:2016 +0xe3
runtime.exitsyscall0(0xc000094f00)
	/usr/local/go/src/runtime/proc.go:3193 +0x107
runtime.mcall(0x1056eeb)
	/usr/local/go/src/runtime/asm_amd64.s:299 +0x5b

goroutine 1 [sync.Cond.Wait, 19 minutes]:
sync.runtime_notifyListWait(0xc00050c1c8, 0x9)
	/usr/local/go/src/runtime/sema.go:510 +0xeb
sync.(*Cond).Wait(0xc00050c1b8)
	/usr/local/go/src/sync/cond.go:56 +0x92
cmd/go/internal/par.(*Work).runner(0xc00050c180)
	/usr/local/go/src/cmd/go/internal/par/work.go:87 +0x33
cmd/go/internal/par.(*Work).Do(0xc00050c180, 0xa, 0xc00040cf60)
	/usr/local/go/src/cmd/go/internal/par/work.go:69 +0xbf
cmd/go/internal/modload.(*loader).load(0xc000280420, 0xc000151290)
	/usr/local/go/src/cmd/go/internal/modload/load.go:503 +0x73e
cmd/go/internal/modload.ImportPaths(0xc000232830, 0x1, 0x1, 0xc0002aac30, 0xc0002ac140, 0x38)
	/usr/local/go/src/cmd/go/internal/modload/load.go:164 +0x322
cmd/go/internal/load.ImportPaths(0xc000232830, 0x1, 0x1, 0xc000151500, 0x109affd, 0xc0002ac140)
	/usr/local/go/src/cmd/go/internal/load/pkg.go:1888 +0x62
cmd/go/internal/load.PackagesAndErrors(0xc000232830, 0x1, 0x1, 0x5, 0xc, 0x5)
	/usr/local/go/src/cmd/go/internal/load/pkg.go:1842 +0xa3
cmd/go/internal/load.PackagesForBuild(0xc000232830, 0x1, 0x1, 0xc000232830, 0x1, 0x1)
	/usr/local/go/src/cmd/go/internal/load/pkg.go:1897 +0x5d
cmd/go/internal/test.runTest(0x19563a0, 0xc0000d4020, 0x3, 0x3)
	/usr/local/go/src/cmd/go/internal/test/test.go:540 +0x179
main.main()
	/usr/local/go/src/cmd/go/main.go:219 +0x7d4

goroutine 35 [syscall, 19 minutes]:
os/signal.signal_recv(0x0)
	/usr/local/go/src/runtime/sigqueue.go:139 +0x9f
os/signal.loop()
	/usr/local/go/src/os/signal/signal_unix.go:23 +0x22
created by os/signal.init.0
	/usr/local/go/src/os/signal/signal_unix.go:29 +0x41

goroutine 37 [runnable]:
sync.(*Map).Load(0x195f720, 0x14cb620, 0xc0000fd010, 0x14b4400, 0xc000665728, 0x100b108)
	/usr/local/go/src/sync/map.go:104 +0xcb
cmd/go/internal/par.(*Cache).Do(0x195f720, 0x14cb620, 0xc0000fd010, 0xc000665778, 0x1511cc0, 0xc000665790)
	/usr/local/go/src/cmd/go/internal/par/work.go:120 +0x45
cmd/go/internal/modfetch.Lookup(0xc0000bea41, 0x1, 0x0, 0x0, 0x1626b80, 0xc00047c6a0)
	/usr/local/go/src/cmd/go/internal/modfetch/repo.go:193 +0xa4
cmd/go/internal/modload.Query(0xc0000bea41, 0x1, 0x1575012, 0x6, 0x15b2a28, 0x0, 0x1626b80, 0xc00047c6a0)
	/usr/local/go/src/cmd/go/internal/modload/query.go:135 +0x130
cmd/go/internal/modload.QueryPackage(0xc0000bea41, 0x4, 0x1575012, 0x6, 0x15b2a28, 0xc00012ec30, 0xc00054c058, 0xc000665d50, 0x100400d, 0xc000026949, ...)
	/usr/local/go/src/cmd/go/internal/modload/query.go:225 +0x202
cmd/go/internal/modload.Import(0xc0000bea41, 0x4, 0x3, 0x0, 0xc000665f00, 0x11c97bb, 0xc00012eb40, 0x179b59d8a9a5d809, 0xc000665f40, 0x11c999f)
	/usr/local/go/src/cmd/go/internal/modload/import.go:135 +0x6fe
cmd/go/internal/modload.(*loader).doPkg(0xc000280420, 0x14f5fc0, 0xc00043de00)
	/usr/local/go/src/cmd/go/internal/modload/load.go:614 +0x2f3
cmd/go/internal/modload.(*loader).doPkg-fm(0x14f5fc0, 0xc00043de00)
	/usr/local/go/src/cmd/go/internal/modload/load.go:503 +0x3e
cmd/go/internal/par.(*Work).runner(0xc00050c180)
	/usr/local/go/src/cmd/go/internal/par/work.go:101 +0x123
created by cmd/go/internal/par.(*Work).Do
	/usr/local/go/src/cmd/go/internal/par/work.go:67 +0x9b

goroutine 40 [sync.Cond.Wait, 19 minutes]:
sync.runtime_notifyListWait(0xc00050c1c8, 0xc)
	/usr/local/go/src/runtime/sema.go:510 +0xeb
sync.(*Cond).Wait(0xc00050c1b8)
	/usr/local/go/src/sync/cond.go:56 +0x92
cmd/go/internal/par.(*Work).runner(0xc00050c180)
	/usr/local/go/src/cmd/go/internal/par/work.go:87 +0x33
created by cmd/go/internal/par.(*Work).Do
	/usr/local/go/src/cmd/go/internal/par/work.go:67 +0x9b

goroutine 43 [sync.Cond.Wait, 19 minutes]:
sync.runtime_notifyListWait(0xc00050c1c8, 0xd)
	/usr/local/go/src/runtime/sema.go:510 +0xeb
sync.(*Cond).Wait(0xc00050c1b8)
	/usr/local/go/src/sync/cond.go:56 +0x92
cmd/go/internal/par.(*Work).runner(0xc00050c180)
	/usr/local/go/src/cmd/go/internal/par/work.go:87 +0x33
created by cmd/go/internal/par.(*Work).Do
	/usr/local/go/src/cmd/go/internal/par/work.go:67 +0x9b

goroutine 42 [sync.Cond.Wait, 19 minutes]:
sync.runtime_notifyListWait(0xc00050c1c8, 0xb)
	/usr/local/go/src/runtime/sema.go:510 +0xeb
sync.(*Cond).Wait(0xc00050c1b8)
	/usr/local/go/src/sync/cond.go:56 +0x92
cmd/go/internal/par.(*Work).runner(0xc00050c180)
	/usr/local/go/src/cmd/go/internal/par/work.go:87 +0x33
created by cmd/go/internal/par.(*Work).Do
	/usr/local/go/src/cmd/go/internal/par/work.go:67 +0x9b

goroutine 39 [sync.Cond.Wait, 19 minutes]:
sync.runtime_notifyListWait(0xc00050c1c8, 0xa)
	/usr/local/go/src/runtime/sema.go:510 +0xeb
sync.(*Cond).Wait(0xc00050c1b8)
	/usr/local/go/src/sync/cond.go:56 +0x92
cmd/go/internal/par.(*Work).runner(0xc00050c180)
	/usr/local/go/src/cmd/go/internal/par/work.go:87 +0x33
created by cmd/go/internal/par.(*Work).Do
	/usr/local/go/src/cmd/go/internal/par/work.go:67 +0x9b

goroutine 38 [sync.Cond.Wait, 19 minutes]:
sync.runtime_notifyListWait(0xc00050c1c8, 0xe)
	/usr/local/go/src/runtime/sema.go:510 +0xeb
sync.(*Cond).Wait(0xc00050c1b8)
	/usr/local/go/src/sync/cond.go:56 +0x92
cmd/go/internal/par.(*Work).runner(0xc00050c180)
	/usr/local/go/src/cmd/go/internal/par/work.go:87 +0x33
created by cmd/go/internal/par.(*Work).Do
	/usr/local/go/src/cmd/go/internal/par/work.go:67 +0x9b

goroutine 41 [sync.Cond.Wait, 19 minutes]:
sync.runtime_notifyListWait(0xc00050c1c8, 0x6)
	/usr/local/go/src/runtime/sema.go:510 +0xeb
sync.(*Cond).Wait(0xc00050c1b8)
	/usr/local/go/src/sync/cond.go:56 +0x92
cmd/go/internal/par.(*Work).runner(0xc00050c180)
	/usr/local/go/src/cmd/go/internal/par/work.go:87 +0x33
created by cmd/go/internal/par.(*Work).Do
	/usr/local/go/src/cmd/go/internal/par/work.go:67 +0x9b

goroutine 44 [sync.Cond.Wait, 19 minutes]:
sync.runtime_notifyListWait(0xc00050c1c8, 0x8)
	/usr/local/go/src/runtime/sema.go:510 +0xeb
sync.(*Cond).Wait(0xc00050c1b8)
	/usr/local/go/src/sync/cond.go:56 +0x92
cmd/go/internal/par.(*Work).runner(0xc00050c180)
	/usr/local/go/src/cmd/go/internal/par/work.go:87 +0x33
created by cmd/go/internal/par.(*Work).Do
	/usr/local/go/src/cmd/go/internal/par/work.go:67 +0x9b

goroutine 45 [sync.Cond.Wait, 19 minutes]:
sync.runtime_notifyListWait(0xc00050c1c8, 0x7)
	/usr/local/go/src/runtime/sema.go:510 +0xeb
sync.(*Cond).Wait(0xc00050c1b8)
	/usr/local/go/src/sync/cond.go:56 +0x92
cmd/go/internal/par.(*Work).runner(0xc00050c180)
	/usr/local/go/src/cmd/go/internal/par/work.go:87 +0x33
created by cmd/go/internal/par.(*Work).Do
	/usr/local/go/src/cmd/go/internal/par/work.go:67 +0x9b

rax    0x104
rbx    0x13700
rcx    0x7ffeefbfe8f8
rdx    0x13700
rdi    0x1961440
rsi    0x1390100013a00
rbp    0x7ffeefbfe990
rsp    0x7ffeefbfe8f8
r8     0x0
r9     0x60
r10    0x0
r11    0x202
r12    0x1961440
r13    0x7ffeefbfe918
r14    0x1
r15    0x7fff8ef73340
rip    0x7fff5606ccee
rflags 0x203
cs     0x7
fs     0x0
gs     0x0

What did you expect to see?

Completion, error, or a timeout message.

It's probable this was a network issue of some sort, but go mod download completed successfully.

What did you see instead?

One CPU is pegged at 100% usage, and the go command doesn't complete.

Activity

agnivade

agnivade commented on Sep 18, 2018

@agnivade
agnivade
on Sep 18, 2018
Contributor

SIGQUIT will dump the goroutine stack traces. Does the go command not exit after SIGQUIT ? Or it was already hung and you entered SIGQUIT to break out ?

alecthomas

alecthomas commented on Sep 18, 2018

@alecthomas
alecthomas
on Sep 18, 2018
Author

The latter - I SIGQUIT after 20 minutes.

alecthomas

alecthomas commented on Sep 18, 2018

@alecthomas
alecthomas
on Sep 18, 2018
Author

Interestingly this is no longer happening locally on my laptop, but IS still occurring reliably on our CI.

agnivade

agnivade commented on Sep 18, 2018

@agnivade
agnivade
on Sep 18, 2018
Contributor

Very interesting that -x does not show any output at all. Got a sample repo for us to test it out ?

agnivade
changed the title [-]go commands wedging trying to fetch modules[/-] [+]cmd/go: test gets hung[/+] on Sep 18, 2018
agnivade
added
NeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.
on Sep 18, 2018
agnivade
added this to the Go1.12 milestone on Sep 18, 2018
agnivade

agnivade commented on Sep 18, 2018

@agnivade
agnivade
on Sep 18, 2018
Contributor

From the dump, it looks like all the runners are waiting on the mutex to be freed.

alecthomas

alecthomas commented on Sep 18, 2018

@alecthomas
alecthomas
on Sep 18, 2018 · edited by alecthomas
Author

Got a sample repo for us to test it out ?

Unfortunately not, this is in a private corporate repository. Sorry I can't provide much more information than the above.

One other piece of data that may be useful: prior to this, go test was hanging, but also writing log messages about downloading a bunch of repos (eg. golang.org/x/arch/...). Each time I ran it it would attempt to download the same repos again but never succeed. Eventually I manually downloaded them each individually (via go get, if I recall correctly) at which point it no longer printed the message, but still hung.

agnivade

agnivade commented on Sep 18, 2018

@agnivade
agnivade
on Sep 18, 2018
Contributor

Just a shot in the dark. Have you tried go clean -modcache -r ?

alecthomas

alecthomas commented on Sep 18, 2018

@alecthomas
alecthomas
on Sep 18, 2018
Author

I have yes, but also the CI doesn't keep state around, so it downloads from scratch each time.

odeke-em

odeke-em commented on Sep 18, 2018

@odeke-em
odeke-em
on Sep 18, 2018
Member

@alecthomas thank you for reporting this issue and @agnivade too! I'll also tag @randall77 @aclements @ianlancetaylor since this involves the runtime scheduling and signals.

alecthomas

alecthomas commented on Sep 18, 2018

@alecthomas
alecthomas
on Sep 18, 2018
Author

Okay, I think I've find out what the problem is. It's partially my fault, but the behaviour is still very surprising.

This is replicable by having the Go source extracted at the root of my package prior to running go test -x -v ./.... That said, it's pretty surprising that it doesn't complete doing whatever it's doing for >20 minutes.

bcmills

bcmills commented on Sep 19, 2018

@bcmills
bcmills
on Sep 19, 2018
Contributor

I'm not sure that there's anything more to be done here. Please let us know if you have ideas.

bcmills
closed this as completedon Sep 19, 2018
golang
locked and limited conversation to collaborators on Sep 19, 2019
gopherbot
added
FrozenDueToAge
on Sep 19, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    FrozenDueToAgeNeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

      Development

      No branches or pull requests

        Participants

        @alecthomas@agnivade@odeke-em@bcmills@gopherbot

        Issue actions
          cmd/go: test gets hung · Issue #27720 · golang/go