Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

cmd/go: trim build cache incrementally #38939

Open
josharian opened this issue May 8, 2020 · 15 comments
Open

cmd/go: trim build cache incrementally #38939

josharian opened this issue May 8, 2020 · 15 comments
Milestone

Comments

@josharian
Copy link
Contributor

@josharian josharian commented May 8, 2020

Can't reproduce reliably, but...

After running go test, I am sometimes seeing the test complete successfully (prints "ok ... pkg ... time"), and then it appears to hang for an indefinite period of time. Sending SIGINT does not terminate the process. Sending SIGTERM does. This happens with std lib tests (strings, crypto/x509). Each time I passed the -v flag, although I'm not sure that that is necessary. Using commit 5c13cab. This behavior is new, although this is the first time I've run tests in a few days or a week. And it doesn't reproduce 100%, so it's a bit muddled.

I attached lldb to two hung binaries and got similar backtraces from each.

First backtrace
$ lldb -p 55409
(lldb) process attach --pid 55409
Process 55409 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
libsystem_kernel.dylib`__psynch_cvwait:
->  0x7fff71de4ce6 <+10>: jae    0x7fff71de4cf0            ; <+20>
    0x7fff71de4ce8 <+12>: movq   %rax, %rdi
    0x7fff71de4ceb <+15>: jmp    0x7fff71de2a89            ; cerror_nocancel
    0x7fff71de4cf0 <+20>: retq   
Target 0: (go) stopped.

Executable module set to "/Users/josh/go/tip/bin/go".
Architecture set to: x86_64h-apple-macosx-.
(lldb) bt

  • thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    • frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib__psynch_cvwait + 10 frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib_pthread_cond_wait + 701
      frame #2: 0x000000000106ceb0 goruntime.pthread_cond_wait_trampoline + 16 frame #3: 0x000000000106ad8d goruntime.asmcgocall + 173
      frame #4: 0x0000000001054c0c goruntime.libcCall + 108 frame #5: 0x00000000010557d9 goruntime.pthread_cond_wait + 57
      frame #6: 0x0000000001032dcd goruntime.semasleep + 141 frame #7: 0x000000000100dca7 goruntime.notesleep + 231
      frame #8: 0x000000000103c9a5 goruntime.stopm + 197 frame #9: 0x000000000103e15f goruntime.findrunnable + 2687
      frame #10: 0x000000000103edd7 goruntime.schedule + 727 frame #11: 0x000000000103f37d goruntime.park_m + 157
      frame #12: 0x000000000106933b goruntime.mcall + 91 frame #13: 0x00000000010557d9 goruntime.pthread_cond_wait + 57
      frame #14: 0x0000000001032dcd goruntime.semasleep + 141 frame #15: 0x000000000100dca7 goruntime.notesleep + 231
      frame #16: 0x000000000103c9a5 goruntime.stopm + 197 frame #17: 0x000000000103e15f goruntime.findrunnable + 2687
      frame #18: 0x000000000103edd7 goruntime.schedule + 727 frame #19: 0x000000000103f37d goruntime.park_m + 157
      frame #20: 0x000000000106933b goruntime.mcall + 91 frame #21: 0x0000000001032dcd goruntime.semasleep + 141
      frame #22: 0x000000000100dca7 goruntime.notesleep + 231 frame #23: 0x000000000103c9a5 goruntime.stopm + 197
      frame #24: 0x000000000103e15f goruntime.findrunnable + 2687 frame #25: 0x000000000103edd7 goruntime.schedule + 727
      frame #26: 0x000000000103f37d goruntime.park_m + 157 frame #27: 0x000000000106933b goruntime.mcall + 91
      frame #28: 0x000000000100dca7 goruntime.notesleep + 231 frame #29: 0x000000000103c9a5 goruntime.stopm + 197
      frame #30: 0x000000000103e15f goruntime.findrunnable + 2687 frame #31: 0x000000000103edd7 goruntime.schedule + 727
      frame #32: 0x000000000103f37d goruntime.park_m + 157 frame #33: 0x000000000106933b goruntime.mcall + 91
      frame #34: 0x000000000103c9a5 goruntime.stopm + 197 frame #35: 0x000000000103e15f goruntime.findrunnable + 2687
      frame #36: 0x000000000103edd7 goruntime.schedule + 727 frame #37: 0x000000000103f37d goruntime.park_m + 157
      frame #38: 0x000000000106933b goruntime.mcall + 91 frame #39: 0x000000000103e15f goruntime.findrunnable + 2687
      frame #40: 0x000000000103edd7 goruntime.schedule + 727 frame #41: 0x000000000103f37d goruntime.park_m + 157
      frame #42: 0x000000000106933b goruntime.mcall + 91 frame #43: 0x000000000103edd7 goruntime.schedule + 727
      frame #44: 0x000000000103f37d goruntime.park_m + 157 frame #45: 0x000000000106933b goruntime.mcall + 91
      frame #46: 0x000000000103f37d goruntime.park_m + 157 frame #47: 0x000000000106933b goruntime.mcall + 91
      frame #48: 0x000000000106933b goruntime.mcall + 91 frame #49: 0x000000000101edff goruntime.gcBgMarkWorker + 255
      frame #50: 0x000000000106b121 goruntime.goexit + 1 frame #51: 0x000000000106b121 goruntime.goexit + 1
      (lldb) ^D
Second backtrace
$ lldb -p 55473
(lldb) process attach --pid 55473
Process 55473 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
libsystem_kernel.dylib`__psynch_cvwait:
->  0x7fff71de4ce6 <+10>: jae    0x7fff71de4cf0            ; <+20>
    0x7fff71de4ce8 <+12>: movq   %rax, %rdi
    0x7fff71de4ceb <+15>: jmp    0x7fff71de2a89            ; cerror_nocancel
    0x7fff71de4cf0 <+20>: retq   
Target 0: (go) stopped.

Executable module set to "/Users/josh/go/tip/bin/go".
Architecture set to: x86_64h-apple-macosx-.
(lldb) bt

  • thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    • frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib__psynch_cvwait + 10 frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib_pthread_cond_wait + 701
      frame #2: 0x000000000106ceb0 goruntime.pthread_cond_wait_trampoline + 16 frame #3: 0x000000000106ad8d goruntime.asmcgocall + 173
      frame #4: 0x0000000001054c0c goruntime.libcCall + 108 frame #5: 0x00000000010557d9 goruntime.pthread_cond_wait + 57
      frame #6: 0x0000000001032dcd goruntime.semasleep + 141 frame #7: 0x000000000100dca7 goruntime.notesleep + 231
      frame #8: 0x000000000103c9a5 goruntime.stopm + 197 frame #9: 0x000000000103e15f goruntime.findrunnable + 2687
      frame #10: 0x000000000103edd7 goruntime.schedule + 727 frame #11: 0x000000000103f37d goruntime.park_m + 157
      frame #12: 0x000000000106933b goruntime.mcall + 91 frame #13: 0x00000000010557d9 goruntime.pthread_cond_wait + 57
      frame #14: 0x0000000001032dcd goruntime.semasleep + 141 frame #15: 0x000000000100dca7 goruntime.notesleep + 231
      frame #16: 0x000000000103c9a5 goruntime.stopm + 197 frame #17: 0x000000000103e15f goruntime.findrunnable + 2687
      frame #18: 0x000000000103edd7 goruntime.schedule + 727 frame #19: 0x000000000103f37d goruntime.park_m + 157
      frame #20: 0x000000000106933b goruntime.mcall + 91 frame #21: 0x0000000001032dcd goruntime.semasleep + 141
      frame #22: 0x000000000100dca7 goruntime.notesleep + 231 frame #23: 0x000000000103c9a5 goruntime.stopm + 197
      frame #24: 0x000000000103e15f goruntime.findrunnable + 2687 frame #25: 0x000000000103edd7 goruntime.schedule + 727
      frame #26: 0x000000000103f37d goruntime.park_m + 157 frame #27: 0x000000000106933b goruntime.mcall + 91
      frame #28: 0x000000000100dca7 goruntime.notesleep + 231 frame #29: 0x000000000103c9a5 goruntime.stopm + 197
      frame #30: 0x000000000103e15f goruntime.findrunnable + 2687 frame #31: 0x000000000103edd7 goruntime.schedule + 727
      frame #32: 0x000000000103f37d goruntime.park_m + 157 frame #33: 0x000000000106933b goruntime.mcall + 91
      frame #34: 0x000000000103c9a5 goruntime.stopm + 197 frame #35: 0x000000000103e15f goruntime.findrunnable + 2687
      frame #36: 0x000000000103edd7 goruntime.schedule + 727 frame #37: 0x000000000103f37d goruntime.park_m + 157
      frame #38: 0x000000000106933b goruntime.mcall + 91 frame #39: 0x000000000103e15f goruntime.findrunnable + 2687
      frame #40: 0x000000000103edd7 goruntime.schedule + 727 frame #41: 0x000000000103f37d goruntime.park_m + 157
      frame #42: 0x000000000106933b goruntime.mcall + 91 frame #43: 0x000000000103edd7 goruntime.schedule + 727
      frame #44: 0x000000000103f37d goruntime.park_m + 157 frame #45: 0x000000000106933b goruntime.mcall + 91
      frame #46: 0x000000000103f37d goruntime.park_m + 157 frame #47: 0x000000000106933b goruntime.mcall + 91
      frame #48: 0x000000000106933b goruntime.mcall + 91 frame #49: 0x000000000101edff goruntime.gcBgMarkWorker + 255
      frame #50: 0x000000000106b121 goruntime.goexit + 1 frame #51: 0x000000000106b121 goruntime.goexit + 1
      (lldb) ^D
@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented May 8, 2020

Interesting. Those backtraces are normal and just show a thread that has no goroutines to run. The next time this happens can you get backtraces from the other threads?

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented May 8, 2020

Also, go test builds a test binary and runs it. Is it the test binary that is hanging, or the cmd/go binary? If the test binary, can you repeat it using go test -c and running the test binary directly? Thanks.

@josharian
Copy link
Contributor Author

@josharian josharian commented May 8, 2020

I haven’t been able to reproduce since. I’ll keep trying.

@josharian
Copy link
Contributor Author

@josharian josharian commented May 11, 2020

This happened again. Some new information:

  • When this happens, it appears to be a systemwide bad state that affects all invocations of cmd/go, including different Go versions. (I tried 1.14.2 and tip.) I reproduced hangs with go get, go test, and go test -c. Given that the hang is at the end of executing the tests, this all suggests to me some sort of lock or contention writing to a shared resource, probably the build cache.

  • This does eventually resolve itself, if you wait long enough. Here's the end of a run of go test -v strings:

=== RUN   ExampleBuilder
--- PASS: ExampleBuilder (0.00s)
PASS
ok  	strings	1.917s
go test -v strings 10.67s user 48.31s system 37% cpu 2:38.10 total 83360 maxrss

The last line is from zsh, via REPORTTIME, with TIMEFMT set to '%J %U user %S system %P cpu %*E total %M maxrss'.

Observe that the test took ~2s to run, but according to the shell the process was alive well over 2 minutes.

  • I asked lldb to bt all a hung go test -c strings process. Results:
 <summary>bt all</summary>
(lldb) bt all
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x00000000010557ac go`runtime.libcCall + 108
    frame #5: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #6: 0x00000000010335ed go`runtime.semasleep + 141
    frame #7: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #8: 0x000000000103d325 go`runtime.stopm + 197
    frame #9: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #10: 0x000000000103f717 go`runtime.schedule + 727
    frame #11: 0x000000000103fcbd go`runtime.park_m + 157
    frame #12: 0x000000000106a2bb go`runtime.mcall + 91
    frame #13: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #14: 0x00000000010335ed go`runtime.semasleep + 141
    frame #15: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #16: 0x000000000103d325 go`runtime.stopm + 197
    frame #17: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #18: 0x000000000103f717 go`runtime.schedule + 727
    frame #19: 0x000000000103fcbd go`runtime.park_m + 157
    frame #20: 0x000000000106a2bb go`runtime.mcall + 91
    frame #21: 0x00000000010335ed go`runtime.semasleep + 141
    frame #22: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #23: 0x000000000103d325 go`runtime.stopm + 197
    frame #24: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #25: 0x000000000103f717 go`runtime.schedule + 727
    frame #26: 0x000000000103fcbd go`runtime.park_m + 157
    frame #27: 0x000000000106a2bb go`runtime.mcall + 91
    frame #28: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #29: 0x000000000103d325 go`runtime.stopm + 197
    frame #30: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #31: 0x000000000103f717 go`runtime.schedule + 727
    frame #32: 0x000000000103fcbd go`runtime.park_m + 157
    frame #33: 0x000000000106a2bb go`runtime.mcall + 91
    frame #34: 0x000000000103d325 go`runtime.stopm + 197
    frame #35: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #36: 0x000000000103f717 go`runtime.schedule + 727
    frame #37: 0x000000000103fcbd go`runtime.park_m + 157
    frame #38: 0x000000000106a2bb go`runtime.mcall + 91
    frame #39: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #40: 0x000000000103f717 go`runtime.schedule + 727
    frame #41: 0x000000000103fcbd go`runtime.park_m + 157
    frame #42: 0x000000000106a2bb go`runtime.mcall + 91
    frame #43: 0x000000000103f717 go`runtime.schedule + 727
    frame #44: 0x000000000103fcbd go`runtime.park_m + 157
    frame #45: 0x000000000106a2bb go`runtime.mcall + 91
    frame #46: 0x000000000103fcbd go`runtime.park_m + 157
    frame #47: 0x000000000106a2bb go`runtime.mcall + 91
    frame #48: 0x000000000106a2bb go`runtime.mcall + 91
    frame #49: 0x000000000101f19f go`runtime.gcBgMarkWorker + 255
    frame #50: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #51: 0x000000000106c0a1 go`runtime.goexit + 1
  thread #2
    frame #0: 0x00007fff71de4bba libsystem_kernel.dylib`__semwait_signal + 10
    frame #1: 0x00007fff71d680fa libsystem_c.dylib`nanosleep + 196
    frame #2: 0x00007fff71d67ff4 libsystem_c.dylib`usleep + 53
    frame #3: 0x000000000106dbab go`runtime.usleep_trampoline + 11
    frame #4: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #5: 0x0000000001055cf1 go`runtime.usleep + 49
    frame #6: 0x000000000104426f go`runtime.sysmon + 143
    frame #7: 0x000000000103bec8 go`runtime.mstart1 + 200
    frame #8: 0x000000000103bde6 go`runtime.mstart + 102
    frame #9: 0x0000000001001eec go`crosscall_amd64 + 12
    frame #10: 0x0000000001001ae4 go`threadentry + 36
    frame #11: 0x00007fff71ea5e65 libsystem_pthread.dylib`_pthread_start + 148
    frame #12: 0x00007fff71ea183b libsystem_pthread.dylib`thread_start + 15
  thread #3
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #5: 0x00000000010335ed go`runtime.semasleep + 141
    frame #6: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #7: 0x000000000103d325 go`runtime.stopm + 197
    frame #8: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #9: 0x000000000103f717 go`runtime.schedule + 727
    frame #10: 0x000000000103fcbd go`runtime.park_m + 157
    frame #11: 0x000000000106a2bb go`runtime.mcall + 91
    frame #12: 0x00000000010335ed go`runtime.semasleep + 141
    frame #13: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #14: 0x000000000103d325 go`runtime.stopm + 197
    frame #15: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #16: 0x000000000103f717 go`runtime.schedule + 727
    frame #17: 0x000000000103fcbd go`runtime.park_m + 157
    frame #18: 0x000000000106a2bb go`runtime.mcall + 91
    frame #19: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #20: 0x000000000103d325 go`runtime.stopm + 197
    frame #21: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #22: 0x000000000103f717 go`runtime.schedule + 727
    frame #23: 0x000000000103fcbd go`runtime.park_m + 157
    frame #24: 0x000000000106a2bb go`runtime.mcall + 91
    frame #25: 0x000000000103d325 go`runtime.stopm + 197
    frame #26: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #27: 0x000000000103f717 go`runtime.schedule + 727
    frame #28: 0x000000000103fcbd go`runtime.park_m + 157
    frame #29: 0x000000000106a2bb go`runtime.mcall + 91
    frame #30: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #31: 0x000000000103f717 go`runtime.schedule + 727
    frame #32: 0x000000000103fcbd go`runtime.park_m + 157
    frame #33: 0x000000000106a2bb go`runtime.mcall + 91
    frame #34: 0x000000000103f717 go`runtime.schedule + 727
    frame #35: 0x000000000103fcbd go`runtime.park_m + 157
    frame #36: 0x000000000106a2bb go`runtime.mcall + 91
    frame #37: 0x000000000103fcbd go`runtime.park_m + 157
    frame #38: 0x000000000106a2bb go`runtime.mcall + 91
    frame #39: 0x000000000106a2bb go`runtime.mcall + 91
    frame #40: 0x000000000101f19f go`runtime.gcBgMarkWorker + 255
    frame #41: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #42: 0x000000000106c0a1 go`runtime.goexit + 1
  thread #4
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #5: 0x00000000010335ed go`runtime.semasleep + 141
    frame #6: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #7: 0x000000000103d325 go`runtime.stopm + 197
    frame #8: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #9: 0x000000000103f717 go`runtime.schedule + 727
    frame #10: 0x000000000103fcbd go`runtime.park_m + 157
    frame #11: 0x000000000106a2bb go`runtime.mcall + 91
    frame #12: 0x00000000010335ed go`runtime.semasleep + 141
    frame #13: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #14: 0x000000000103d325 go`runtime.stopm + 197
    frame #15: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #16: 0x000000000103f717 go`runtime.schedule + 727
    frame #17: 0x000000000103fcbd go`runtime.park_m + 157
    frame #18: 0x000000000106a2bb go`runtime.mcall + 91
    frame #19: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #20: 0x000000000103d325 go`runtime.stopm + 197
    frame #21: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #22: 0x000000000103f717 go`runtime.schedule + 727
    frame #23: 0x000000000103fcbd go`runtime.park_m + 157
    frame #24: 0x000000000106a2bb go`runtime.mcall + 91
    frame #25: 0x000000000103d325 go`runtime.stopm + 197
    frame #26: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #27: 0x000000000103f717 go`runtime.schedule + 727
    frame #28: 0x000000000103fcbd go`runtime.park_m + 157
    frame #29: 0x000000000106a2bb go`runtime.mcall + 91
    frame #30: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #31: 0x000000000103f717 go`runtime.schedule + 727
    frame #32: 0x000000000103fcbd go`runtime.park_m + 157
    frame #33: 0x000000000106a2bb go`runtime.mcall + 91
    frame #34: 0x000000000103f717 go`runtime.schedule + 727
    frame #35: 0x000000000103fcbd go`runtime.park_m + 157
    frame #36: 0x000000000106a2bb go`runtime.mcall + 91
    frame #37: 0x000000000103fcbd go`runtime.park_m + 157
    frame #38: 0x000000000106a2bb go`runtime.mcall + 91
    frame #39: 0x000000000106a2bb go`runtime.mcall + 91
    frame #40: 0x000000000102454a go`runtime.scavengeSleep + 202
    frame #41: 0x0000000001024825 go`runtime.bgscavenge + 677
    frame #42: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #43: 0x0000000001024825 go`runtime.bgscavenge + 677
    frame #44: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #45: 0x000000000106c0a1 go`runtime.goexit + 1
  thread #5
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #5: 0x00000000010335ed go`runtime.semasleep + 141
    frame #6: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #7: 0x000000000103d325 go`runtime.stopm + 197
    frame #8: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #9: 0x000000000103f717 go`runtime.schedule + 727
    frame #10: 0x000000000103fcbd go`runtime.park_m + 157
    frame #11: 0x000000000106a2bb go`runtime.mcall + 91
    frame #12: 0x00000000010335ed go`runtime.semasleep + 141
    frame #13: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #14: 0x000000000103d325 go`runtime.stopm + 197
    frame #15: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #16: 0x000000000103f717 go`runtime.schedule + 727
    frame #17: 0x000000000103fcbd go`runtime.park_m + 157
    frame #18: 0x000000000106a2bb go`runtime.mcall + 91
    frame #19: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #20: 0x000000000103d325 go`runtime.stopm + 197
    frame #21: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #22: 0x000000000103f717 go`runtime.schedule + 727
    frame #23: 0x000000000103fcbd go`runtime.park_m + 157
    frame #24: 0x000000000106a2bb go`runtime.mcall + 91
    frame #25: 0x000000000103d325 go`runtime.stopm + 197
    frame #26: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #27: 0x000000000103f717 go`runtime.schedule + 727
    frame #28: 0x000000000103fcbd go`runtime.park_m + 157
    frame #29: 0x000000000106a2bb go`runtime.mcall + 91
    frame #30: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #31: 0x000000000103f717 go`runtime.schedule + 727
    frame #32: 0x000000000103fcbd go`runtime.park_m + 157
    frame #33: 0x000000000106a2bb go`runtime.mcall + 91
    frame #34: 0x000000000103f717 go`runtime.schedule + 727
    frame #35: 0x000000000103fcbd go`runtime.park_m + 157
    frame #36: 0x000000000106a2bb go`runtime.mcall + 91
    frame #37: 0x000000000103fcbd go`runtime.park_m + 157
    frame #38: 0x000000000106a2bb go`runtime.mcall + 91
    frame #39: 0x000000000106a2bb go`runtime.mcall + 91
    frame #40: 0x000000000101f19f go`runtime.gcBgMarkWorker + 255
    frame #41: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #42: 0x000000000106c0a1 go`runtime.goexit + 1
  thread #6
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x00000000010557ac go`runtime.libcCall + 108
    frame #5: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #6: 0x00000000010335ed go`runtime.semasleep + 141
    frame #7: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #8: 0x000000000103d23a go`runtime.templateThread + 250
    frame #9: 0x000000000103bec8 go`runtime.mstart1 + 200
    frame #10: 0x000000000103bde6 go`runtime.mstart + 102
    frame #11: 0x0000000001001eec go`crosscall_amd64 + 12
    frame #12: 0x0000000001001ae4 go`threadentry + 36
    frame #13: 0x00007fff71ea5e65 libsystem_pthread.dylib`_pthread_start + 148
    frame #14: 0x00007fff71ea183b libsystem_pthread.dylib`thread_start + 15
  thread #7
    frame #0: 0x00007fff71de6bce libsystem_kernel.dylib`kevent + 10
    frame #1: 0x000000000106dc5e go`runtime.kevent_trampoline + 30
    frame #2: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #3: 0x000000000106dc40 go`runtime.kqueue_trampoline + 32
    frame #4: 0x0000000001056199 go`runtime.kevent + 57
    frame #5: 0x000000000103316e go`runtime.netpoll + 174
    frame #6: 0x000000000103e7fd go`runtime.findrunnable + 1917
    frame #7: 0x000000000103f717 go`runtime.schedule + 727
    frame #8: 0x000000000103fcbd go`runtime.park_m + 157
    frame #9: 0x000000000106a2bb go`runtime.mcall + 91
    frame #10: 0x000000000103316e go`runtime.netpoll + 174
    frame #11: 0x000000000103e7fd go`runtime.findrunnable + 1917
    frame #12: 0x000000000103f717 go`runtime.schedule + 727
    frame #13: 0x000000000103fcbd go`runtime.park_m + 157
    frame #14: 0x000000000106a2bb go`runtime.mcall + 91
    frame #15: 0x000000000103e7fd go`runtime.findrunnable + 1917
    frame #16: 0x000000000103f717 go`runtime.schedule + 727
    frame #17: 0x000000000103fcbd go`runtime.park_m + 157
    frame #18: 0x000000000106a2bb go`runtime.mcall + 91
    frame #19: 0x000000000103f717 go`runtime.schedule + 727
    frame #20: 0x000000000103fcbd go`runtime.park_m + 157
    frame #21: 0x000000000106a2bb go`runtime.mcall + 91
    frame #22: 0x000000000103fcbd go`runtime.park_m + 157
    frame #23: 0x000000000106a2bb go`runtime.mcall + 91
    frame #24: 0x000000000106a2bb go`runtime.mcall + 91
    frame #25: 0x0000000001024825 go`runtime.bgscavenge + 677
    frame #26: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #27: 0x000000000106c0a1 go`runtime.goexit + 1
  thread #8
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #5: 0x00000000010335ed go`runtime.semasleep + 141
    frame #6: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #7: 0x000000000103d325 go`runtime.stopm + 197
    frame #8: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #9: 0x000000000103f717 go`runtime.schedule + 727
    frame #10: 0x000000000103fcbd go`runtime.park_m + 157
    frame #11: 0x000000000106a2bb go`runtime.mcall + 91
    frame #12: 0x00000000010335ed go`runtime.semasleep + 141
    frame #13: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #14: 0x000000000103d325 go`runtime.stopm + 197
    frame #15: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #16: 0x000000000103f717 go`runtime.schedule + 727
    frame #17: 0x000000000103fcbd go`runtime.park_m + 157
    frame #18: 0x000000000106a2bb go`runtime.mcall + 91
    frame #19: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #20: 0x000000000103d325 go`runtime.stopm + 197
    frame #21: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #22: 0x000000000103f717 go`runtime.schedule + 727
    frame #23: 0x000000000103fcbd go`runtime.park_m + 157
    frame #24: 0x000000000106a2bb go`runtime.mcall + 91
    frame #25: 0x000000000103d325 go`runtime.stopm + 197
    frame #26: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #27: 0x000000000103f717 go`runtime.schedule + 727
    frame #28: 0x000000000103fcbd go`runtime.park_m + 157
    frame #29: 0x000000000106a2bb go`runtime.mcall + 91
    frame #30: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #31: 0x000000000103f717 go`runtime.schedule + 727
    frame #32: 0x000000000103fcbd go`runtime.park_m + 157
    frame #33: 0x000000000106a2bb go`runtime.mcall + 91
    frame #34: 0x000000000103f717 go`runtime.schedule + 727
    frame #35: 0x000000000103fcbd go`runtime.park_m + 157
    frame #36: 0x000000000106a2bb go`runtime.mcall + 91
    frame #37: 0x000000000103fcbd go`runtime.park_m + 157
    frame #38: 0x000000000106a2bb go`runtime.mcall + 91
    frame #39: 0x000000000106a2bb go`runtime.mcall + 91
    frame #40: 0x000000000102454a go`runtime.scavengeSleep + 202
    frame #41: 0x0000000001024825 go`runtime.bgscavenge + 677
    frame #42: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #43: 0x0000000001024825 go`runtime.bgscavenge + 677
    frame #44: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #45: 0x000000000106c0a1 go`runtime.goexit + 1
  thread #9
    frame #0: 0x00007fff71de3796 libsystem_kernel.dylib`stat$INODE64 + 10
    frame #1: 0x000000000106dedf go`runtime.syscall + 31
    frame #2: 0x000000000106bcd0 go`runtime.asmcgocall + 112
    frame #3: 0x000000000103bd80 go`runtime.startTheWorldWithSema + 576
    frame #4: 0x0000000001068cd1 go`syscall.syscall + 81
    frame #5: 0x00000000010b8a98 go`syscall.Stat + 184
    frame #6: 0x00000000010df41c go`os.statNolog + 92
    frame #7: 0x00000000010deeed go`os.Stat + 77
    frame #8: 0x000000000137625d go`cmd/go/internal/cache.(*Cache).trimSubdir + 413
    frame #9: 0x0000000001375e0b go`cmd/go/internal/cache.(*Cache).Trim + 747
    frame #10: 0x0000000001451ab4 go`cmd/go/internal/work.(*Builder).Do + 1012
    frame #11: 0x0000000001526605 go`cmd/go/internal/test.runTest + 3781
    frame #12: 0x00000000015422cd go`main.main + 1421
    frame #13: 0x0000000001039363 go`runtime.main + 547
    frame #14: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #15: 0x00000000010b8a98 go`syscall.Stat + 184
    frame #16: 0x00000000010df41c go`os.statNolog + 92
    frame #17: 0x00000000010deeed go`os.Stat + 77
    frame #18: 0x000000000137625d go`cmd/go/internal/cache.(*Cache).trimSubdir + 413
    frame #19: 0x0000000001375e0b go`cmd/go/internal/cache.(*Cache).Trim + 747
    frame #20: 0x0000000001451ab4 go`cmd/go/internal/work.(*Builder).Do + 1012
    frame #21: 0x0000000001526605 go`cmd/go/internal/test.runTest + 3781
    frame #22: 0x00000000015422cd go`main.main + 1421
    frame #23: 0x0000000001039363 go`runtime.main + 547
    frame #24: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #25: 0x00000000010df41c go`os.statNolog + 92
    frame #26: 0x00000000010deeed go`os.Stat + 77
    frame #27: 0x000000000137625d go`cmd/go/internal/cache.(*Cache).trimSubdir + 413
    frame #28: 0x0000000001375e0b go`cmd/go/internal/cache.(*Cache).Trim + 747
    frame #29: 0x0000000001451ab4 go`cmd/go/internal/work.(*Builder).Do + 1012
    frame #30: 0x0000000001526605 go`cmd/go/internal/test.runTest + 3781
    frame #31: 0x00000000015422cd go`main.main + 1421
    frame #32: 0x0000000001039363 go`runtime.main + 547
    frame #33: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #34: 0x00000000010deeed go`os.Stat + 77
    frame #35: 0x000000000137625d go`cmd/go/internal/cache.(*Cache).trimSubdir + 413
    frame #36: 0x0000000001375e0b go`cmd/go/internal/cache.(*Cache).Trim + 747
    frame #37: 0x0000000001451ab4 go`cmd/go/internal/work.(*Builder).Do + 1012
    frame #38: 0x0000000001526605 go`cmd/go/internal/test.runTest + 3781
    frame #39: 0x00000000015422cd go`main.main + 1421
    frame #40: 0x0000000001039363 go`runtime.main + 547
    frame #41: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #42: 0x000000000137625d go`cmd/go/internal/cache.(*Cache).trimSubdir + 413
    frame #43: 0x0000000001375e0b go`cmd/go/internal/cache.(*Cache).Trim + 747
    frame #44: 0x0000000001451ab4 go`cmd/go/internal/work.(*Builder).Do + 1012
    frame #45: 0x0000000001526605 go`cmd/go/internal/test.runTest + 3781
    frame #46: 0x00000000015422cd go`main.main + 1421
    frame #47: 0x0000000001039363 go`runtime.main + 547
    frame #48: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #49: 0x0000000001375e0b go`cmd/go/internal/cache.(*Cache).Trim + 747
    frame #50: 0x0000000001451ab4 go`cmd/go/internal/work.(*Builder).Do + 1012
    frame #51: 0x0000000001526605 go`cmd/go/internal/test.runTest + 3781
    frame #52: 0x00000000015422cd go`main.main + 1421
    frame #53: 0x0000000001039363 go`runtime.main + 547
    frame #54: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #55: 0x0000000001451ab4 go`cmd/go/internal/work.(*Builder).Do + 1012
    frame #56: 0x0000000001526605 go`cmd/go/internal/test.runTest + 3781
    frame #57: 0x00000000015422cd go`main.main + 1421
    frame #58: 0x0000000001039363 go`runtime.main + 547
    frame #59: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #60: 0x0000000001526605 go`cmd/go/internal/test.runTest + 3781
    frame #61: 0x00000000015422cd go`main.main + 1421
    frame #62: 0x0000000001039363 go`runtime.main + 547
    frame #63: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #64: 0x00000000015422cd go`main.main + 1421
    frame #65: 0x0000000001039363 go`runtime.main + 547
    frame #66: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #67: 0x0000000001039363 go`runtime.main + 547
    frame #68: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #69: 0x000000000106c0a1 go`runtime.goexit + 1
  thread #10
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #5: 0x00000000010335ed go`runtime.semasleep + 141
    frame #6: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #7: 0x000000000103d325 go`runtime.stopm + 197
    frame #8: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #9: 0x000000000103f717 go`runtime.schedule + 727
    frame #10: 0x000000000103fcbd go`runtime.park_m + 157
    frame #11: 0x000000000106a2bb go`runtime.mcall + 91
    frame #12: 0x00000000010335ed go`runtime.semasleep + 141
    frame #13: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #14: 0x000000000103d325 go`runtime.stopm + 197
    frame #15: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #16: 0x000000000103f717 go`runtime.schedule + 727
    frame #17: 0x000000000103fcbd go`runtime.park_m + 157
    frame #18: 0x000000000106a2bb go`runtime.mcall + 91
    frame #19: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #20: 0x000000000103d325 go`runtime.stopm + 197
    frame #21: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #22: 0x000000000103f717 go`runtime.schedule + 727
    frame #23: 0x000000000103fcbd go`runtime.park_m + 157
    frame #24: 0x000000000106a2bb go`runtime.mcall + 91
    frame #25: 0x000000000103d325 go`runtime.stopm + 197
    frame #26: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #27: 0x000000000103f717 go`runtime.schedule + 727
    frame #28: 0x000000000103fcbd go`runtime.park_m + 157
    frame #29: 0x000000000106a2bb go`runtime.mcall + 91
    frame #30: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #31: 0x000000000103f717 go`runtime.schedule + 727
    frame #32: 0x000000000103fcbd go`runtime.park_m + 157
    frame #33: 0x000000000106a2bb go`runtime.mcall + 91
    frame #34: 0x000000000103f717 go`runtime.schedule + 727
    frame #35: 0x000000000103fcbd go`runtime.park_m + 157
    frame #36: 0x000000000106a2bb go`runtime.mcall + 91
    frame #37: 0x000000000103fcbd go`runtime.park_m + 157
    frame #38: 0x000000000106a2bb go`runtime.mcall + 91
    frame #39: 0x000000000106a2bb go`runtime.mcall + 91
    frame #40: 0x000000000101f19f go`runtime.gcBgMarkWorker + 255
    frame #41: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #42: 0x000000000106c0a1 go`runtime.goexit + 1
  thread #11
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #5: 0x00000000010335ed go`runtime.semasleep + 141
    frame #6: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #7: 0x000000000103d325 go`runtime.stopm + 197
    frame #8: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #9: 0x000000000103f717 go`runtime.schedule + 727
    frame #10: 0x000000000103fcbd go`runtime.park_m + 157
    frame #11: 0x000000000106a2bb go`runtime.mcall + 91
    frame #12: 0x00000000010335ed go`runtime.semasleep + 141
    frame #13: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #14: 0x000000000103d325 go`runtime.stopm + 197
    frame #15: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #16: 0x000000000103f717 go`runtime.schedule + 727
    frame #17: 0x000000000103fcbd go`runtime.park_m + 157
    frame #18: 0x000000000106a2bb go`runtime.mcall + 91
    frame #19: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #20: 0x000000000103d325 go`runtime.stopm + 197
    frame #21: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #22: 0x000000000103f717 go`runtime.schedule + 727
    frame #23: 0x000000000103fcbd go`runtime.park_m + 157
    frame #24: 0x000000000106a2bb go`runtime.mcall + 91
    frame #25: 0x000000000103d325 go`runtime.stopm + 197
    frame #26: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #27: 0x000000000103f717 go`runtime.schedule + 727
    frame #28: 0x000000000103fcbd go`runtime.park_m + 157
    frame #29: 0x000000000106a2bb go`runtime.mcall + 91
    frame #30: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #31: 0x000000000103f717 go`runtime.schedule + 727
    frame #32: 0x000000000103fcbd go`runtime.park_m + 157
    frame #33: 0x000000000106a2bb go`runtime.mcall + 91
    frame #34: 0x000000000103f717 go`runtime.schedule + 727
    frame #35: 0x000000000103fcbd go`runtime.park_m + 157
    frame #36: 0x000000000106a2bb go`runtime.mcall + 91
    frame #37: 0x000000000103fcbd go`runtime.park_m + 157
    frame #38: 0x000000000106a2bb go`runtime.mcall + 91
    frame #39: 0x000000000106a2bb go`runtime.mcall + 91
    frame #40: 0x000000000102454a go`runtime.scavengeSleep + 202
    frame #41: 0x0000000001024825 go`runtime.bgscavenge + 677
    frame #42: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #43: 0x0000000001024825 go`runtime.bgscavenge + 677
    frame #44: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #45: 0x000000000106c0a1 go`runtime.goexit + 1
  thread #12
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #5: 0x00000000010335ed go`runtime.semasleep + 141
    frame #6: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #7: 0x000000000103d325 go`runtime.stopm + 197
    frame #8: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #9: 0x000000000103f717 go`runtime.schedule + 727
    frame #10: 0x000000000103fcbd go`runtime.park_m + 157
    frame #11: 0x000000000106a2bb go`runtime.mcall + 91
    frame #12: 0x00000000010335ed go`runtime.semasleep + 141
    frame #13: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #14: 0x000000000103d325 go`runtime.stopm + 197
    frame #15: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #16: 0x000000000103f717 go`runtime.schedule + 727
    frame #17: 0x000000000103fcbd go`runtime.park_m + 157
    frame #18: 0x000000000106a2bb go`runtime.mcall + 91
    frame #19: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #20: 0x000000000103d325 go`runtime.stopm + 197
    frame #21: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #22: 0x000000000103f717 go`runtime.schedule + 727
    frame #23: 0x000000000103fcbd go`runtime.park_m + 157
    frame #24: 0x000000000106a2bb go`runtime.mcall + 91
    frame #25: 0x000000000103d325 go`runtime.stopm + 197
    frame #26: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #27: 0x000000000103f717 go`runtime.schedule + 727
    frame #28: 0x000000000103fcbd go`runtime.park_m + 157
    frame #29: 0x000000000106a2bb go`runtime.mcall + 91
    frame #30: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #31: 0x000000000103f717 go`runtime.schedule + 727
    frame #32: 0x000000000103fcbd go`runtime.park_m + 157
    frame #33: 0x000000000106a2bb go`runtime.mcall + 91
    frame #34: 0x000000000103f717 go`runtime.schedule + 727
    frame #35: 0x000000000103fcbd go`runtime.park_m + 157
    frame #36: 0x000000000106a2bb go`runtime.mcall + 91
    frame #37: 0x000000000103fcbd go`runtime.park_m + 157
    frame #38: 0x000000000106a2bb go`runtime.mcall + 91
    frame #39: 0x000000000106a2bb go`runtime.mcall + 91
    frame #40: 0x000000000102454a go`runtime.scavengeSleep + 202
    frame #41: 0x0000000001024825 go`runtime.bgscavenge + 677
    frame #42: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #43: 0x0000000001024825 go`runtime.bgscavenge + 677
    frame #44: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #45: 0x000000000106c0a1 go`runtime.goexit + 1
  thread #13
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x000000000102440c go`runtime.wakeScavenger + 76
    frame #5: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #6: 0x00000000010335ed go`runtime.semasleep + 141
    frame #7: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #8: 0x000000000103d325 go`runtime.stopm + 197
    frame #9: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #10: 0x000000000103f717 go`runtime.schedule + 727
    frame #11: 0x000000000103fcbd go`runtime.park_m + 157
    frame #12: 0x000000000106a2bb go`runtime.mcall + 91
    frame #13: 0x00000000010335ed go`runtime.semasleep + 141
    frame #14: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #15: 0x000000000103d325 go`runtime.stopm + 197
    frame #16: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #17: 0x000000000103f717 go`runtime.schedule + 727
    frame #18: 0x000000000103fcbd go`runtime.park_m + 157
    frame #19: 0x000000000106a2bb go`runtime.mcall + 91
    frame #20: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #21: 0x000000000103d325 go`runtime.stopm + 197
    frame #22: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #23: 0x000000000103f717 go`runtime.schedule + 727
    frame #24: 0x000000000103fcbd go`runtime.park_m + 157
    frame #25: 0x000000000106a2bb go`runtime.mcall + 91
    frame #26: 0x000000000103d325 go`runtime.stopm + 197
    frame #27: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #28: 0x000000000103f717 go`runtime.schedule + 727
    frame #29: 0x000000000103fcbd go`runtime.park_m + 157
    frame #30: 0x000000000106a2bb go`runtime.mcall + 91
    frame #31: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #32: 0x000000000103f717 go`runtime.schedule + 727
    frame #33: 0x000000000103fcbd go`runtime.park_m + 157
    frame #34: 0x000000000106a2bb go`runtime.mcall + 91
    frame #35: 0x000000000103f717 go`runtime.schedule + 727
    frame #36: 0x000000000103fcbd go`runtime.park_m + 157
    frame #37: 0x000000000106a2bb go`runtime.mcall + 91
    frame #38: 0x000000000103fcbd go`runtime.park_m + 157
    frame #39: 0x000000000106a2bb go`runtime.mcall + 91
    frame #40: 0x000000000106a2bb go`runtime.mcall + 91
  thread #14
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #5: 0x00000000010335ed go`runtime.semasleep + 141
    frame #6: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #7: 0x000000000103d325 go`runtime.stopm + 197
    frame #8: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #9: 0x000000000103f717 go`runtime.schedule + 727
    frame #10: 0x000000000103fcbd go`runtime.park_m + 157
    frame #11: 0x000000000106a2bb go`runtime.mcall + 91
    frame #12: 0x00000000010335ed go`runtime.semasleep + 141
    frame #13: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #14: 0x000000000103d325 go`runtime.stopm + 197
    frame #15: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #16: 0x000000000103f717 go`runtime.schedule + 727
    frame #17: 0x000000000103fcbd go`runtime.park_m + 157
    frame #18: 0x000000000106a2bb go`runtime.mcall + 91
    frame #19: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #20: 0x000000000103d325 go`runtime.stopm + 197
    frame #21: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #22: 0x000000000103f717 go`runtime.schedule + 727
    frame #23: 0x000000000103fcbd go`runtime.park_m + 157
    frame #24: 0x000000000106a2bb go`runtime.mcall + 91
    frame #25: 0x000000000103d325 go`runtime.stopm + 197
    frame #26: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #27: 0x000000000103f717 go`runtime.schedule + 727
    frame #28: 0x000000000103fcbd go`runtime.park_m + 157
    frame #29: 0x000000000106a2bb go`runtime.mcall + 91
    frame #30: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #31: 0x000000000103f717 go`runtime.schedule + 727
    frame #32: 0x000000000103fcbd go`runtime.park_m + 157
    frame #33: 0x000000000106a2bb go`runtime.mcall + 91
    frame #34: 0x000000000103f717 go`runtime.schedule + 727
    frame #35: 0x000000000103fcbd go`runtime.park_m + 157
    frame #36: 0x000000000106a2bb go`runtime.mcall + 91
    frame #37: 0x000000000103fcbd go`runtime.park_m + 157
    frame #38: 0x000000000106a2bb go`runtime.mcall + 91
    frame #39: 0x000000000106a2bb go`runtime.mcall + 91
  thread #15
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #5: 0x00000000010335ed go`runtime.semasleep + 141
    frame #6: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #7: 0x000000000103d325 go`runtime.stopm + 197
    frame #8: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #9: 0x000000000103f717 go`runtime.schedule + 727
    frame #10: 0x000000000103be93 go`runtime.mstart1 + 147
    frame #11: 0x000000000103bde6 go`runtime.mstart + 102
    frame #12: 0x0000000001001eec go`crosscall_amd64 + 12
    frame #13: 0x0000000001001ae4 go`threadentry + 36
    frame #14: 0x00007fff71ea5e65 libsystem_pthread.dylib`_pthread_start + 148
    frame #15: 0x00007fff71ea183b libsystem_pthread.dylib`thread_start + 15
  thread #16
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #5: 0x00000000010335ed go`runtime.semasleep + 141
    frame #6: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #7: 0x000000000103d325 go`runtime.stopm + 197
    frame #8: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #9: 0x000000000103f717 go`runtime.schedule + 727
    frame #10: 0x000000000103fcbd go`runtime.park_m + 157
    frame #11: 0x000000000106a2bb go`runtime.mcall + 91
    frame #12: 0x00000000010335ed go`runtime.semasleep + 141
    frame #13: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #14: 0x000000000103d325 go`runtime.stopm + 197
    frame #15: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #16: 0x000000000103f717 go`runtime.schedule + 727
    frame #17: 0x000000000103fcbd go`runtime.park_m + 157
    frame #18: 0x000000000106a2bb go`runtime.mcall + 91
    frame #19: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #20: 0x000000000103d325 go`runtime.stopm + 197
    frame #21: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #22: 0x000000000103f717 go`runtime.schedule + 727
    frame #23: 0x000000000103fcbd go`runtime.park_m + 157
    frame #24: 0x000000000106a2bb go`runtime.mcall + 91
    frame #25: 0x000000000103d325 go`runtime.stopm + 197
    frame #26: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #27: 0x000000000103f717 go`runtime.schedule + 727
    frame #28: 0x000000000103fcbd go`runtime.park_m + 157
    frame #29: 0x000000000106a2bb go`runtime.mcall + 91
    frame #30: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #31: 0x000000000103f717 go`runtime.schedule + 727
    frame #32: 0x000000000103fcbd go`runtime.park_m + 157
    frame #33: 0x000000000106a2bb go`runtime.mcall + 91
    frame #34: 0x000000000103f717 go`runtime.schedule + 727
    frame #35: 0x000000000103fcbd go`runtime.park_m + 157
    frame #36: 0x000000000106a2bb go`runtime.mcall + 91
    frame #37: 0x000000000103fcbd go`runtime.park_m + 157
    frame #38: 0x000000000106a2bb go`runtime.mcall + 91
    frame #39: 0x000000000106a2bb go`runtime.mcall + 91
    frame #40: 0x000000000101f19f go`runtime.gcBgMarkWorker + 255
    frame #41: 0x000000000106c0a1 go`runtime.goexit + 1
    frame #42: 0x000000000106c0a1 go`runtime.goexit + 1
  thread #17
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x00000000010557ac go`runtime.libcCall + 108
    frame #5: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #6: 0x00000000010335ed go`runtime.semasleep + 141
    frame #7: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #8: 0x000000000103d325 go`runtime.stopm + 197
    frame #9: 0x000000000104129d go`runtime.exitsyscall0 + 285
    frame #10: 0x000000000106a2bb go`runtime.mcall + 91
    frame #11: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #12: 0x00000000010335ed go`runtime.semasleep + 141
    frame #13: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #14: 0x000000000103d325 go`runtime.stopm + 197
    frame #15: 0x000000000104129d go`runtime.exitsyscall0 + 285
    frame #16: 0x000000000106a2bb go`runtime.mcall + 91
    frame #17: 0x00000000010335ed go`runtime.semasleep + 141
    frame #18: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #19: 0x000000000103d325 go`runtime.stopm + 197
    frame #20: 0x000000000104129d go`runtime.exitsyscall0 + 285
    frame #21: 0x000000000106a2bb go`runtime.mcall + 91
    frame #22: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #23: 0x000000000103d325 go`runtime.stopm + 197
    frame #24: 0x000000000104129d go`runtime.exitsyscall0 + 285
    frame #25: 0x000000000106a2bb go`runtime.mcall + 91
    frame #26: 0x000000000103d325 go`runtime.stopm + 197
    frame #27: 0x000000000104129d go`runtime.exitsyscall0 + 285
    frame #28: 0x000000000106a2bb go`runtime.mcall + 91
    frame #29: 0x000000000104129d go`runtime.exitsyscall0 + 285
    frame #30: 0x000000000106a2bb go`runtime.mcall + 91
    frame #31: 0x000000000106a2bb go`runtime.mcall + 91
  thread #18
    frame #0: 0x00007fff71de4ce6 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff71ea6185 libsystem_pthread.dylib`_pthread_cond_wait + 701
    frame #2: 0x000000000106de30 go`runtime.pthread_cond_wait_trampoline + 16
    frame #3: 0x000000000106bd0d go`runtime.asmcgocall + 173
    frame #4: 0x0000000001056379 go`runtime.pthread_cond_wait + 57
    frame #5: 0x00000000010335ed go`runtime.semasleep + 141
    frame #6: 0x000000000100dd07 go`runtime.notesleep + 231
    frame #7: 0x000000000103d325 go`runtime.stopm + 197
    frame #8: 0x000000000103eaff go`runtime.findrunnable + 2687
    frame #9: 0x000000000103f717 go`runtime.schedule + 727
    frame #10: 0x000000000103be93 go`runtime.mstart1 + 147
    frame #11: 0x000000000103bde6 go`runtime.mstart + 102
    frame #12: 0x0000000001001eec go`crosscall_amd64 + 12
    frame #13: 0x0000000001001ae4 go`threadentry + 36
    frame #14: 0x00007fff71ea5e65 libsystem_pthread.dylib`_pthread_start + 148
    frame #15: 0x00007fff71ea183b libsystem_pthread.dylib`thread_start + 15
(lldb) 

Something is weird about thread #9's backtrace.

@josharian
Copy link
Contributor Author

@josharian josharian commented May 11, 2020

Speculation: Could this just be cmd/go deleting a very large number of expired cache entries?

If so, maybe we need to bound the number of entries deleted during one auto-initiated run, and have cleanup happen incrementally.

cc @bcmills @jayconrod

@josharian josharian changed the title runtime: hang after cmd/go test completes cmd/go: appears to hang occasionally May 11, 2020
@jayconrod
Copy link
Contributor

@jayconrod jayconrod commented May 11, 2020

Could this just be cmd/go deleting a very large number of expired cache entries?

Based on the stack and other comments, this seems likely.

If I remember correctly, the build cache expiration policy is purely time-based. There are some comments in src/cmd/go/internal/cache/cache.go. The go command will attempt to trim the cache at most once per day. It will remove files that haven't been accessed in 5 days.

I don't believe there are any limits on the number or total size of files in the cache. It may not make sense to limit the size of the cache, but we might want to trim files more aggressively when it's very large (#29561).

Trimming incrementally also seems like a good solution. We could limit the time spent trimming for any command to, say 500 ms. We could save where we left off so the next command could restart from that point.

@jayconrod jayconrod changed the title cmd/go: appears to hang occasionally cmd/go: trim build cache incrementally May 11, 2020
@jayconrod jayconrod modified the milestones: Go1.15, Backlog May 11, 2020
@bcmills
Copy link
Member

@bcmills bcmills commented May 11, 2020

We could limit the time spent trimming for any command to, say 500 ms.

I don't think we should limit the trimming time to any fixed duration, because that could lead to a state where the trimming can't keep pace with the rate of creation.

That said, I would expect deleting a file to almost always be faster than creating it. Perhaps we could limit the cleaning time to some multiple of the rest of the running time of the go command so far (with a lower bound to ensure that we can always do some cleaning).

@josharian
Copy link
Contributor Author

@josharian josharian commented May 11, 2020

Another option might be to kick off cleaning the cache at the beginning of the cmd/go run, and let it run concurrently with the rest of the command, except when running benchmarks.

@bcmills
Copy link
Member

@bcmills bcmills commented May 11, 2020

I like that! But I worry it could be a bit racy — is it possible for part of the command to touch part of the cache and make it non-stale again?

@josharian
Copy link
Contributor Author

@josharian josharian commented May 11, 2020

It’s not that terrible to have to recalculate something that you just deleted—that would have happened anyway with slightly different timing of when you ran the commands.

I think the only problem is if you see something is in the cache, decide to use it, and then it gets cleaned up before you can use it. But if you can freshen it in the cache, and if the deletion goroutine always rechecks freshness before deletion, and if there are enough synchronization points, it should be ok. But that is a lot of ifs. :)

@bcmills
Copy link
Member

@bcmills bcmills commented May 11, 2020

Yes, that's exactly the race I'm worried about. 🙂

I guess we could decide which portions of the cache to use, then freshen them, then kick off the cleaner while we do the remaining work. (But we intentionally don't rely on file-locking in the cache, and even if we did there is no atomic lock-check-and-delete operation, so there is in general no way to prevent the cleaner from racing with the consumer. So I don't think we can avoid the need to at least finish freshening the entries before we start the cleaner.)

@josharian
Copy link
Contributor Author

@josharian josharian commented May 11, 2020

Since this is all in one process, could we do our synchronization internally, in a thin intermediate layer?

@bcmills
Copy link
Member

@bcmills bcmills commented May 11, 2020

Internally: yes. Thin: that's subjective. 😉

@josharian
Copy link
Contributor Author

@josharian josharian commented May 11, 2020

Fair enough. Happy to leave all these choices to you. :) I'd be happy enough with a simple 500ms time limit for automatically initialized cache cleanup.

@bcmills
Copy link
Member

@bcmills bcmills commented May 26, 2020

@josharian, I noticed a similar issue tracking down #39183. I started with a test that ran lots of goroutines to try to provoke failures, and found that the test with N=10000 ran very quickly (~1s) but the go command hung for a long time afterward (~10s), on every run (not just when there were existing cache entries to invalidate).

I wonder if there is a bottleneck in producing the cache key itself, rather than merely cleaning the stale entries.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
4 participants
You can’t perform that action at this time.