server,etc: Add detailed tracing to the startup process

[bdarnell]

This will allow us to test the hypothesis in #8694 that our startup
time is resulting in a 20-second timeout in GRPC's TLS handshake.

---

This change is

[bdarnell]

@cockroachdb/stability

[RaduBerinde]

Hi Ben,

The change LGTM, however it's going to conflict on develop with #8625 which plumbs a "base" context through to Store (CCing @andreimatei as well)

---

Review status: 0 of 6 files reviewed at latest revision, all discussions resolved, some commit checks failed.

---

Comments from Reviewable

[bdarnell]

Are there changes that could be made to this PR that would minimize the conflicts, or are you volunteering for the next master -> develop merge?

[RaduBerinde]

I can work on the merge. I'm not entirely sure how to best implement it under the model we've been working on, but we'll figure it out. Can you leave some basic instructions in the commit message on how you tested the change?

@tamird: I think the best strategy would be to merge everything up to this commit, then I will work on a PR for this, and once that's merged the normal process can resume.

---

Review status: 0 of 6 files reviewed at latest revision, all discussions resolved, some commit checks failed.

---

Comments from Reviewable

[petermattis]

I made some comments below about adding more detail to the trace, but as I think about it now, that probably isn't necessary if you're primarily looking at this for timing information.

Was there a strong reason to use tracing to gather this information? Seems like you could have also used standard log messages.

---

Review status: 0 of 10 files reviewed at latest revision, 5 unresolved discussions, some commit checks failed.

---

cli/start.go, line 356 [r1] (raw file):

  if err := serverCtx.InitStores(stopper); err != nil {
      return fmt.Errorf("failed to initialize stores: %s", err)
  }

log.Trace(startCtx, "initialized engines")?

---

server/node.go, line 402 [r1] (raw file):

  for _, e := range engines {
      s := storage.NewStore(n.ctx, e, &n.Descriptor)
      log.Trace(ctx, "created store object")

Can/should we output the store and engine?

log.Tracef(ctx, "created store: %s [%s] ", s, e)

---

server/node.go, line 462 [r1] (raw file):

      n.initNodeID(0)
      n.initialBoot = true
      log.Trace(ctx, "allocated node ID")

Output node ID?

---

server/server.go, line 329 [r1] (raw file):

      return err
  }
  log.Tracef(ctx, "bound to port %s", s.ctx.Addr)

Well, we're listening too, right? s/bound to port/listening on/g

---

server/server.go, line 468 [r1] (raw file):

      netutil.FatalIfUnexpected(m.Serve())
  })
  log.Trace(ctx, "starting to accept connections")

s/starting to accept/accepting/g

---

Comments from Reviewable

[bdarnell]

Re: tracing vs logging: traces are much more accessible than logging. The beta cluster is currently retaining less than a day's worth of logging history (which is a problem in its own right...) and even if it were there we'd have to grep through a lot of rotated log files to find the one that contained the server start. The trace makes it network-accessible and retains it for the life of the server (it would be even better if we refactored to let us use the net/trace "family" parameter; for now we're relying on the fact that this trace is a duration outlier). I also don't think we'd be happy with this level of verbosity in log files, but it's fine in a trace.

To test this, I've been applying this patch to basictracer-go/events/event_nettrace.go:

diff --git a/events/event_nettrace.go b/events/event_nettrace.go
index 08dcc81..e3d540a 100644
--- a/events/event_nettrace.go
+++ b/events/event_nettrace.go
@@ -13,6 +13,7 @@ var NetTraceIntegrator = func() func(basictracer.SpanEvent) {
        switch t := e.(type) {
        case basictracer.EventCreate:
            tr = trace.New("tracing", t.OperationName)
+           tr.SetMaxEvents(100)
        case basictracer.EventFinish:
            tr.Finish()
        case basictracer.EventLog:

and viewing the results in the UI at http://localhost:8080/debug/requests?fam=tracing&b=4&exp=1.

---

Review status: 0 of 10 files reviewed at latest revision, 5 unresolved discussions, some commit checks pending.

---

cli/start.go, line 356 [r1] (raw file):

Previously, petermattis (Peter Mattis) wrote…

log.Trace(startCtx, "initialized engines")?

The method name InitStores is misleading; it's just parsing the store-related command-line flags here.

---

server/node.go, line 402 [r1] (raw file):

Previously, petermattis (Peter Mattis) wrote…

Can/should we output the store and engine?

log.Tracef(ctx, "created store: %s [%s] ", s, e)

The store isn't initialized enough to have a useful string representation, but added the engine.

---

server/node.go, line 462 [r1] (raw file):

Previously, petermattis (Peter Mattis) wrote…

Output node ID?

Done.

---

server/server.go, line 329 [r1] (raw file):

Previously, petermattis (Peter Mattis) wrote…

Well, we're listening too, right? s/bound to port/listening on/g

Done.

---

Comments from Reviewable

[tamird]

Reviewed 4 of 10 files at r1, 5 of 6 files at r2.
Review status: 9 of 10 files reviewed at latest revision, 5 unresolved discussions, some commit checks failed.

---

server/server.go, line 329 [r1] (raw file):

Previously, bdarnell (Ben Darnell) wrote…

Done.

s.ctx.Addr is more than just a port

---

Comments from Reviewable