runtime: spinning CPU on NetBSD calling compat_60__lwp_park

[bradfitz]

The NetBSD builder's buildlet process boots up immediately spinning, using 100% CPU.

$ gomote create netbsd-amd64-8branch
$ gomote ssh user-bradfitz-netbsd-amd64-8branch-0
...
# dtruss -n buildlet 2>&1 | head -500 > x
# cat x
PID/LWP    SYSCALL(args)                 = return
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
   505/2:  compat_60__lwp_park(0xC42003DE58, 0x0, 0xC42002E398)          = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE60, 0x0)                 = 0 0
   505/2:  clock_gettime(0x3, 0xC42003DE00, 0x0)                 = 0 0
....

This seemed to start when I rebuilt the NetBSD-amd64 8.0-BETA VM image yesterday, but I'm not sure.

Filing while I investigate.

/cc @ianlancetaylor @aclements @bsiegert @krytarowski @zoulasc

[bradfitz]

Okay, if I build the buildlet with Go 1.9, it doesn't spin.

So this appears to be some regression at Go master.

[krytarowski]

While there, it looks like golang uses clock_gettime(), while it should use newer syscall __clock_gettime50().

[bradfitz]

Update:

Even with the Go 1.9-built buildlet, we're still getting a column of red failing builds for netbsd because now the go_bootstrap binary is spinning, taking 100% CPU while the rest of the build tries to complete & pass its tests. But many tests fail while competing with a 100% CPU spinner. The spin is the same:

buildlet-netbsd-amd64-8branch-rnc9c727e# dtruss -n go_bootstrap 2>&1 | head -50 > x
buildlet-netbsd-amd64-8branch-rnc9c727e# cat x
PID/LWP    SYSCALL(args)                 = return
  2140/2:  clock_gettime(0x3, 0xC42003FE00, 0x0)                 = 0 0
  2140/2:  compat_60__lwp_park(0xC42003FE58, 0x0, 0xC420030398)          = 0 0
  2140/2:  clock_gettime(0x3, 0xC42003FE60, 0x0)                 = 0 0
  2140/2:  clock_gettime(0x3, 0xC42003FE00, 0x0)                 = 0 0
  2140/2:  compat_60__lwp_park(0xC42003FE58, 0x0, 0xC420030398)          = 0 0
  2140/2:  clock_gettime(0x3, 0xC42003FE60, 0x0)                 = 0 0
  2140/2:  clock_gettime(0x3, 0xC42003FE00, 0x0)                 = 0 0
  2140/2:  compat_60__lwp_park(0xC42003FE58, 0x0, 0xC420030398)          = 0 0
  2140/2:  clock_gettime(0x3, 0xC42003FE60, 0x0)                 = 0 0
  2140/2:  clock_gettime(0x3, 0xC42003FE00, 0x0)                 = 0 0
  2140/2:  compat_60__lwp_park(0xC42003FE58, 0x0, 0xC420030398)          = 0 0
  2140/2:  clock_gettime(0x3, 0xC42003FE60, 0x0)                 = 0 0
  2140/2:  clock_gettime(0x3, 0xC42003FE00, 0x0)                 = 0 0
  2140/2:  compat_60__lwp_park(0xC42003FE58, 0x0, 0xC420030398)          = 0 0
...

Because this all worked the other day before I rebuilt the NetBSD image, I'm curious if any changes in NetBSD-8 happened recently that make Go unhappy.

[gopherbot]

Change https://golang.org/cl/81637 mentions this issue: dashboard: disable NetBSD builders

[zoulasc]

I don't know if/what changed on 8. I can reproduce this on HEAD in one of the regexp tests and with i386 binaries on amd64 in many tests. I am investigating.

[bradfitz]

Thanks, @zoulasc.

[zoulasc]

Here's a patch to make go use the new lwp_park call on NetBSD (untested on arm) and to use CLOCK_MONOTONIC for nanotime(). This also saves a syscall each time we need to sleep for a semaphore...

https://www.netbsd.org/~christos/go-lwp-park-clock-monotonic.diff

With this fix and a tiny kernel patch (kern_lwp.c:1.191) go on amd64 passes all the tests.

[bradfitz]

Thanks. Is there a pullup to the NetBSD-8 branch I should wait for for http://cvsweb.netbsd.org/bsdweb.cgi/src/sys/kern/kern_lwp.c.diff?r1=1.190&r2=1.191&only_with_tag=MAIN ?

Btw, the nanotime change already happened in 2065685.

So were the processes spinning because lwp_park was using the wrong clock and the clock was going backwards sometimes, or ... ?