stability: basictracer-go memory usage

[petermattis]

Gamma significant Go memory usage:

A heap profile from one of the nodes shows a significant chunk coming out of the basictracer-go package:

(pprof) top5
939.13MB of 1415.52MB total (66.35%)
Dropped 1313 nodes (cum <= 7.08MB)
Showing top 5 nodes out of 145 (cum >= 131.01MB)
      flat  flat%   sum%        cum   cum%
  261.56MB 18.48% 18.48%   261.56MB 18.48%  github.com/opentracing/basictracer-go.(*spanImpl).Log
  213.04MB 15.05% 33.53%   219.54MB 15.51%  fmt.Sprintf
  185.01MB 13.07% 46.60%   258.12MB 18.24%  context.WithCancel
  162.02MB 11.45% 58.04%   162.02MB 11.45%  github.com/opentracing/basictracer-go.(*tracerImpl).getSpan
  117.50MB  8.30% 66.35%   131.01MB  9.26%  github.com/cockroachdb/cockroach/util/log.eventInternal

I'm guessing we're going to start OOM'ing soon.

[tamird]

https://godoc.org/github.com/opentracing/basictracer-go#Options includes EnableSpanPool, which might help some.

On Fri, Sep 9, 2016 at 8:12 PM, Peter Mattis notifications@github.com wrote:

Gamma significant Go memory usage:

[image: screen shot 2016-09-09 at 8 03 30 pm] https://cloud.githubusercontent.com/assets/6201335/18406330/7189fc94-76c9-11e6-9f25-a9a58b250073.png

A heap profile https://github.com/cockroachdb/cockroach/files/465051/pprof001.svg.zip from one of the nodes shows a significant chunk coming out of the basictracer-go package:

(pprof) top5 939.13MB of 1415.52MB total (66.35%) Dropped 1313 nodes (cum <= 7.08MB) Showing top 5 nodes out of 145 (cum >= 131.01MB) flat flat% sum% cum cum% 261.56MB 18.48% 18.48% 261.56MB 18.48% github.com/opentracing/basictracer-go.(_spanImpl).Log 213.04MB 15.05% 33.53% 219.54MB 15.51% fmt.Sprintf 185.01MB 13.07% 46.60% 258.12MB 18.24% context.WithCancel 162.02MB 11.45% 58.04% 162.02MB 11.45% github.com/opentracing/basictracer-go.(_tracerImpl).getSpan 117.50MB 8.30% 66.35% 131.01MB 9.26% github.com/cockroachdb/cockroach/util/log.eventInternal

I'm guessing we're going to start OOM'ing soon.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/cockroachdb/cockroach/issues/9252, or mute the thread https://github.com/notifications/unsubscribe-auth/ABdsPJN-uql5N4i27dBDmf61SZayxiosks5qofXegaJpZM4J5lHR .

[petermattis]

This is inuse_objects from the same heap profile:

(pprof) top10
13015565 of 14616203 total (89.05%)
Dropped 1328 nodes (cum <= 73081)
Showing top 10 nodes out of 130 (cum >= 131079)
      flat  flat%   sum%        cum   cum%
   3199586 21.89% 21.89%    3391734 23.21%  github.com/cockroachdb/cockroach/util/log.eventInternal
   2449592 16.76% 38.65%    2456157 16.80%  context.WithCancel
   2326633 15.92% 54.57%    2326633 15.92%  context.WithValue
   1265110  8.66% 63.22%    1444368  9.88%  fmt.Sprintf
   1218526  8.34% 71.56%    1218526  8.34%  github.com/opentracing/basictracer-go.(*spanImpl).Log
   1179809  8.07% 79.63%    1179809  8.07%  github.com/opentracing/basictracer-go.(*tracerImpl).getSpan
    884763  6.05% 85.69%    4608007 31.53%  google.golang.org/grpc/transport.(*http2Client).NewStream
    229379  1.57% 87.26%     229379  1.57%  runtime/pprof.writeHeap
    131088   0.9% 88.15%     135187  0.92%  github.com/cockroachdb/cockroach/storage.(*timestampCache).AddRequest
    131079   0.9% 89.05%     131079   0.9%  github.com/cockroachdb/cockroach/roachpb.(*Span).Unmarshal

884763 inuse http2 (a.k.a. GRPC) client streams seems a bit excessive.

[petermattis]

EnableSpanPool looks like it would reduce allocation/GC costs. What the profile is showing is some kind of leak.

[tamird]

The leak could be something new exposed by #9234.

[petermattis]

Yeah, that's a possibility. Too bad we had to disable tracing in GRPC. It would likely highlight which streams we're leaving dangling in /debug/{requests,events}.

[petermattis]

Cc @cockroachdb/stability

[tamird]

Although now that we're sending far fewer snapshots, perhaps we could consider re-enabling GRPC tracing...

On Fri, Sep 9, 2016 at 8:27 PM, Peter Mattis notifications@github.com wrote:

Cc @cockroachdb/stability https://github.com/orgs/cockroachdb/teams/stability

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/cockroachdb/cockroach/issues/9252#issuecomment-246074506, or mute the thread https://github.com/notifications/unsubscribe-auth/ABdsPJrp80KUm3xKNdIfM3iw5UVfK_bBks5qofmDgaJpZM4J5lHR .

[tbg]

What's even using basictracer? Gamma is using lightstep, so basictracer should really not be used except for snowball tracing.

[tbg]

lightstep-tracer is just a basictracer. We restarted gamma without the lightstep token (so we can get the net/trace endpoint back to see the running traces; we should see what's leaked there).

[tbg]

My current working theory is that we're overloading lightstep's collector. I'm not very sure of this theory because they seem to have code that would drop spans when they don't ship out in time, but if we don't flat-out leak traces (as we can see on net/trace now; none leaked so far after ~15min) perhaps that is what is happening.

Since #9230 has dramatically increased our throughput, it has at the same time increased the amount of pressure on the trace collector.

We should know in a couple of hours as we're not using the upstream lightstep collector right now.

[tbg]

We're continuing to leak Go memory, so this theory doesn't seem to hold.

[tbg]

All nodes seem to be leaking memory uniformly. I picked a random node and net/trace shows no long-running traces. Ok, new unsubstantiated theory. The following code would leak all the traces' memory:

ctx := context.Background()
for {
  sp := make_span()
  ctx = opentracing.ContextWithSpan(ctx, sp)
  sp.Finish()
}

even though it would finish all traces.

Perhaps we are somewhere creating traces but then leaking a reference to them in some "eternal" context.

This is pure speculation.

[tbg]

I may have to take that back. The memory usage seems to be dipping down.

I did disable the photos app (see #9247). A wedged transaction, caught in an infinite retry loop, could cause runaway memory consumption in its trace (which may not have happened earlier before #9234) . If the memory usage remains bounded for the next few hours, we should reenable photos and confirm that those wedged transactions play a role.

[bdarnell]

I think there may be another GRPC leak.

The presence of context.WithCancel caught my attention, and in the SVG we can see that it's being called in the GPRC HTTP/2 client. guru shows that while transport.Stream.cancel is called in http2_server.go, there is no other reference to it in client-side code, so GRPC is creating a cancel function and never using it.

The implementation of context.WithCancel has two modes: when the parent context is not cancelable, it's trivial: the cancelCtx just holds a reference to the parent. When the parent context is cancelable, though, it creates bidirectional references between the two contexts, and these references stay in place until one or the other is canceled.

My hypothesis is that we now have an unbroken chain of contexts from incoming SQL connections (canceled when the connection drops) to outgoing KV RPCs, so the GRPC context.WithCancel call creates the bidirectional links. Previously the memory consumption of this leak was bounded by the timeout in kv, but since #9234 the leaked contexts will be held for the lifetime of the SQL session.

I don't think this leak explains the whole story, though - the contexts created inside GRPC wouldn't create new spans (since we have GRPC tracing disabled), so they wouldn't make us accumulate more data in basictracer.

[bdarnell]

I've reproduced the leak and filed grpc/grpc-go#888.

[tbg]

I don't think this leak explains the whole story, though - the contexts created inside GRPC wouldn't create new spans (since we have GRPC tracing disabled), so they wouldn't make us accumulate more data in basictracer.

GRPC tracing goes directly to net/trace, so that wouldn't actually show up in basictracer-go but in net/trace, I think.

Doesn't your analysis explain the whole story though? We're leaking the context, which already holds a basictracer-span and a bunch of log entries (usually from TxnCoordSender down to SendNext). With lightstep, we were using a basictracer with trivial options internally. This would not clear out the log messages from the span after recording it, so we would leak those as well, which would let our memory usage grow fairly rapidly.

After I restarted without the lightstep token, we're still leaking but the logs aren't held in memory any more. That's expected because we use the DebugAssertUseAfterFinish option, which clears out the logs after recording. So the amount of memory leaked per context is smaller (and the slope of the leak is now, too).

New svg: svg.zip

[petermattis]

Looks like #9258 fixed all the leaks:

Showing top 5 nodes out of 186 (cum >= 6.51MB)
      flat  flat%   sum%        cum   cum%
      26MB 19.98% 19.98%       26MB 19.98%  github.com/cockroachdb/cockroach/util/encoding.EncodeBytesAscending
   24.50MB 18.83% 38.81%    29.51MB 22.68%  github.com/cockroachdb/cockroach/storage.(*timestampCache).AddRequest
      11MB  8.45% 47.27%       11MB  8.45%  github.com/cockroachdb/cockroach/roachpb.(*Span).Unmarshal
      11MB  8.45% 55.72%    65.02MB 49.97%  github.com/cockroachdb/cockroach/storage.(*Replica).endCmds
    6.51MB  5.00% 60.72%     6.51MB  5.00%  github.com/coreos/etcd/raft/raftpb.(*Entry).Unmarshal

[bdarnell]

GRPC tracing goes directly to net/trace, so that wouldn't actually show up in basictracer-go but in net/trace, I think.

Right, that's why I'm surprised that this worked. There are two classes of sessions in play here: one long-lived (I'm guessing it's attached to the SQL session but don't know for sure), and one short-lived created by GRPC. All the tracing stuff is on the former, but that lives a long time no matter what GRPC does. The GRPC leak should only be affecting the latter, which wouldn't hold on to any trace information that's not already being held somewhere.

The context tree must be more complex than this two-level structure. Perhaps it's a cancelable context at the top level with no spans, then contexts with spans under that. The contexts with spans are being held alive by GRPC but they would otherwise be short-lived. Anyway, we have the empirical evidence that this worked so we don't need to dig too much more.

[tbg]

The trace spans are currently added only in TxnCoordSender, so that's pretty late and that is the context grpc got a hold of. I think that showed in the heap too. Andrei's PR which merged today changes that since it bases operations on a txn-lifetimed context, so TxnCoordSender won't wrap the context since there is already a higher level trace there. In effect that should give the same result but let's keep our eyes open.

On Sat, Sep 10, 2016, 21:40 Ben Darnell notifications@github.com wrote:

Closed #9252 https://github.com/cockroachdb/cockroach/issues/9252.

— You are receiving this because you are on a team that was mentioned.

Reply to this email directly, view it on GitHub https://github.com/cockroachdb/cockroach/issues/9252#event-785077354, or mute the thread https://github.com/notifications/unsubscribe-auth/AE135HKMHQbKzuTxgzGL_tEHf1yNe_giks5qo1wYgaJpZM4J5lHR .

-- Tobias