builder: upgrade to go1.12.5

[petermattis]

Release note (general change): Upgrade the build environment to use
go1.12.5.

[cockroach-teamcity]

This change is 

[petermattis]

@bdarnell Are there any known go1.12 issues still open?

[petermattis]

This isn't good. The run below was using a cockroach binary built with go1.12.5:

~ roachtest run --cloud aws 'kv95/enc=false/nodes=3$'
...
_elapsed___errors_____ops(total)___ops/sec(cum)__avg(ms)__p50(ms)__p95(ms)__p99(ms)_pMax(ms)__result
  600.0s        0       11456822        19094.7     10.1      3.0     44.0     71.3    260.0

The same roachtest run against a cockroach binary built with go1.11.6:

~ roachtest run --cloud aws 'kv95/enc=false/nodes=3$'
...
_elapsed___errors_____ops(total)___ops/sec(cum)__avg(ms)__p50(ms)__p95(ms)__p99(ms)_pMax(ms)__result
  600.0s        0       29194446        48657.3      3.9      3.1     12.1     18.9    209.7

[petermattis]

Nothing obvious showed up on cpu profiles. The mutex contention profile shows that the hlc.Clock mutex is much more heavily contended on go1.12. Here is a CPU profile of that method:

         .          .    264:func (c *Clock) Now() Timestamp {
      20ms      1.39s    265:   c.mu.Lock()
         .       40ms    266:   defer c.mu.Unlock()
         .      850ms    267:   if physicalClock := c.getPhysicalClockAndCheckLocked(); c.mu.timestamp.WallTime >= physicalClock {
         .          .    268:           // The wall time is ahead, so the logical clock ticks.
         .          .    269:           c.mu.timestamp.Logical++
         .          .    270:   } else {
         .          .    271:           // Use the physical clock, and reset the logical one.
         .          .    272:           c.mu.timestamp.WallTime = physicalClock
         .          .    273:           c.mu.timestamp.Logical = 0
         .          .    274:   }
         .          .    275:
         .       10ms    276:   c.enforceWallTimeWithinBoundLocked()
         .      230ms    277:   return c.mu.timestamp
         .          .    278:}

On go1.11.6 that function looks like:

         .          .    264:func (c *Clock) Now() Timestamp {
      10ms      100ms    265:   c.mu.Lock()
      10ms       30ms    266:   defer c.mu.Unlock()
         .       40ms    267:   if physicalClock := c.getPhysicalClockAndCheckLocked(); c.mu.timestamp.WallTime >= physicalClock {
         .          .    268:           // The wall time is ahead, so the logical clock ticks.
         .          .    269:           c.mu.timestamp.Logical++
         .          .    270:   } else {
         .          .    271:           // Use the physical clock, and reset the logical one.
         .          .    272:           c.mu.timestamp.WallTime = physicalClock
         .          .    273:           c.mu.timestamp.Logical = 0
         .          .    274:   }
         .          .    275:
         .       10ms    276:   c.enforceWallTimeWithinBoundLocked()
         .       90ms    277:   return c.mu.timestamp
         .          .    278:}

All of the excess time is being spent in Clock.physicalClock. That is implemented by hlc.UnixNano. I'm not sure if the profile is messed up, but it isn't obvious where the time is being spent:

      30ms      840ms    125:func UnixNano() int64 {
         .       10ms    126:   return timeutil.Now().UnixNano()
         .          .    127:}

Disassembly shows:

   125         30ms      840ms           func UnixNano() int64 { 
                20ms       20ms   e96f30:     MOVQ FS:0xfffffd00, CX                                                       hlc.go:125
                10ms       10ms   e96f39:     CMPQ 0x10(CX), SP                                                            hlc.go:125
                   .          .   e96f3d:     JBE 0xe96fb7                                                                 hlc.go:125
                   .          .   e96f3f:     SUBQ $0x20, SP                                                               hlc.go:125
                   .          .   e96f43:     MOVQ BP, 0x18(SP)                                                            hlc.go:125
                   .          .   e96f48:     LEAQ 0x18(SP), BP                                                            hlc.go:125
                                     ⋮
                   .      810ms   e96fb7:     CALL runtime.morestack_noctxt(SB)                                            hlc.go:125
                   .          .   e96fbc:     ?                                                                            hlc.go:125
                   .          .   e96fbd:     OUTSD DS:0(SI), DX                                                           hlc.go:125
                   .          .   e96fbe:     ?                                                                            hlc.go:125
                   .          .   e96fbf:     ?                                                                            hlc.go:125

Not sure what is going on here. Perhaps the stacks in go1.12 are deeper causing lots of stack growth to happen in hlc.Now. Perhaps the growStack hack in server/node.go was broken by go1.12.

[petermattis]

Yep, growStack is broken on go1.12. I have an additional hack to reenable it which seems to completely fix performance. But knowing more about Go assembly now, I think the right thing to do is to implement growStack in assembly so that we don't have to worry about the compiler getting more intelligent in the future and optimizing it out of existence.

It is pretty incredible that disabling growStack causes such a huge performance hit.

[petermattis]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @bdarnell)

---

pkg/util/log/clog.go, line 364 at r1 (raw file):

// NewEntryDecoder creates a new instance of EntryDecoder.
func NewEntryDecoder(in io.Reader) *EntryDecoder {
	d := &EntryDecoder{scanner: bufio.NewScanner(in), re: entryRE.Copy()}

This was to appease one of the linters: pkg/util/log/clog.go:364:56: entryRE.Copy is deprecated: In earlier releases, when using a Regexp in multiple goroutines, giving each goroutine its own copy helped to avoid lock contention. As of Go 1.12, using Copy is no longer necessary to avoid lock contention. Copy may still be appropriate if the reason for its use is to make two copies with different Longest settings. (SA1019)

[bdarnell]

Reviewed 3 of 3 files at r1.
Reviewable status: complete! 0 of 0 LGTMs obtained

[bdarnell]

But knowing more about Go assembly now, I think the right thing to do is to implement growStack in assembly

Funny, I was going to say that knowing more about go assembly, I think the right thing to do is implement growStack in C. :)

Reviewable status: complete! 0 of 0 LGTMs obtained

[petermattis]

bors r=bdarnell

[craig]

Build succeeded

• GitHub CI (Cockroach)