jaeger has a memory leak when use badger

[lichenglin]

Describe the bug I'm doing a stress on badger and found that jaeger has a memory leak .

To Reproduce Steps to reproduce the behavior:

1. start jaeger with docker docker run --rm --name jaeger-badger -p 16831:6831/udp -p 16832:6832/udp -p 15778:5778 -p 15775:5775 -p 26686:16686 -p 24269:14269 -e SPAN_STORAGE_TYPE=badger -e BADGER_EPHEMERAL=false -e BADGER_DIRECTORY_VALUE=/badger/data -e BADGER_DIRECTORY_KEY=/badger/key jaegertracing/all-in-one:1.19 --badger.span-store-ttl 1m --badger.truncate

2.run a stress application to send data to jaeger. My application send 7000/s span data to jaeger with udp sender.

3.monitoring the memory of CONTAINER ;

Expected behavior jaeger's memory should be stable at some point not always increase.

Screenshots If applicable, add screenshots to help explain your problem.

as time goes on ,the memory become higher.

Version (please complete the following information):

• OS: centos7
• Jaeger version: 1.9
• Deployment: docker

What troubleshooting steps did you try? I try to adjust some param. such as --collector.queue-size,--collector.queue-size-memory --badger.span-store-ttl ,--badger.consistency,--badger.maintenance-interval

Additional context

[jpkrohling]

I investigated a possible memory leak some time ago, and documented my findings here: https://issues.redhat.com/browse/TRACING-1071 . Would you mind going over that and checking if your findings match mine?

[lichenglin]

I investigated a possible memory leak some time ago, and documented my findings here: https://issues.redhat.com/browse/TRACING-1071 . Would you mind going over that and checking if your findings match mine?

I have checked.It is the same issue.

I use linux command and found the jaeger process use about 10g memory.

But when I use pprof. It shows this.

what should I do? Just set env GODEBUG=madvdontneed=1?

[jpkrohling]

A good first step would indeed be to use GODEBUG=madvdontneed=1. If you are on a container environment, setting the limits and requests should also help.

[joe-elliott]

FWIW we have had success leaving the new Go memory behavior alone. It does obscure the amount of memory used by a process, but we have switched to using go_memstats_heap_alloc_bytes to watch for memory leaks. The new behavior is designed for better performance and responds well to linux memory pressure and cgroup limits.

[lichenglin]

I have use docker to start jaeger and give a memory limit 1g. here is my command

docker run -it --rm -p16686:16686 -p14269:14269 -p6831:6831/udp --memory 1g -v /badger:/badger -e SPAN_STORAGE_TYPE=badger -e BADGER_EPHEMERAL=false -e BADGER_DIRECTORY_VALUE=/badger/data -e BADGER_DIRECTORY_KEY=/badger/key jaegertracing/all-in-one:1.19 --badger.span-store-ttl 1m --badger.truncate --collector.queue-size 1000 --badger.consistency --badger.maintenance-interval 1m

after a while jaeger quit with a memory allocate failed.here is the log

{"level":"error","ts":1599787084.0791428,"caller":"grpc/reporter.go:74","msg":"Could not send spans over gRPC","error":"rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp :14250: socket: cannot allocate memory\"","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/reporter/grpc.(*Reporter).send\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/reporter/grpc/reporter.go:74\ngithub.com/jaegertracing/jaeger/cmd/agent/app/reporter/grpc.(*Reporter).EmitBatch\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/reporter/grpc/reporter.go:53\ngithub.com/jaegertracing/jaeger/cmd/agent/app/reporter.(*MetricsReporter).EmitBatch\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/reporter/metrics.go:85\ngithub.com/jaegertracing/jaeger/cmd/agent/app/reporter.(*ClientMetricsReporter).EmitBatch\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/reporter/client_metrics.go:121\ngithub.com/jaegertracing/jaeger/thrift-gen/agent.(*agentProcessorEmitBatch).Process\n\tgithub.com/jaegertracing/jaeger/thrift-gen/agent/agent.go:157\ngithub.com/jaegertracing/jaeger/thrift-gen/agent.(*AgentProcessor).Process\n\tgithub.com/jaegertracing/jaeger/thrift-gen/agent/agent.go:112\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:122\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}

I don't know why a file base storage need so much memory.

[jpkrohling]

This does sound bad, and I would say that we should be doing some tweaking on our side. That said, I don't think we have anyone working on badger at the moment. Would you be willing to give this a try? Perhaps @burmanm would want to check this on his spare time?

[burmanm]

@jarifibrahim Might remember this, could be something of a bug that was fixed in later 1.x versions (or 2.x?). Sadly the github issues are deprecated in the repo and they're using a forum software for tracking bugs or something as odd so I can't find the info anymore.

[jarifibrahim]

Which version of badger are you using? We fixed a memory leak in skl (memtables) a long time ago https://github.com/dgraph-io/badger/pull/849 which is part of badger 1.6.x and v2.x releases.

https://issues.redhat.com/browse/TRACING-1071

@jpkrohling Badger memory usage is supposed to increase linearly with the data if you're using the default options. Badger has in-memory bloom filters (one per sst file) and an index (one per sst file) kept in-memory. You could set caches to limit the amount of memory the bloom filter and index should take (this is only in badger 2x).

I can help you guys tweak badger for a memory-friendly mode, right now it runs in the performance-friendly mode.

Sadly the github issues are deprecated in the repo and they're using a forum software for tracking bugs or something as odd so I can't find the info anymore.

Sorry to hear that. Old issues are still in github but if you can't find something related to badger, feel free to tag me.

[jpkrohling]

How many spans per second are we talking about here, @lichenglin ?

[lichenglin]

How many spans per second are we talking about here, @lichenglin ?

6000/s Span.

But I think It done's matter.

While using a file base storage I think It should be more memory-friendly. Even at the expense of some data quality and speed.

[jpkrohling]

@lichenglin I ran a local test here with a rate somewhat above yours:

SPAN_STORAGE_TYPE=badger go run ./cmd/all-in-one --badger.ephemeral=false --badger.directory-value=/home/jpkroehling/.badger/jaeger/data --badger.directory-key=/home/jpkroehling/.badger/jaeger/key  --badger.span-store-ttl=1m --badger.consistency --badger.maintenance-interval=1m

$ go run ./cmd/tracegen -pause 50us -duration 1m 

This created 642670 traces in one minute (each with two spans) and consumed, at the peak, around 650MiB of disk space and about 2GiB of memory:

It wasn't clear to me whether the memory usage had peaked in this example, so, I ran a longer test (20m):

I have to agree that the pattern does seem a bit strange. From under 1GiB in the first minutes, to between 1GiB and 2 GiB for the next few minutes, and then between 2GiB and 3GiB for the last part. The peaks of 3GiB, then 4GiB, then 6.5GiB, then 10GiB are also suspicious, although could probably be explained. But given that the total disk usage was not much higher than 4GiB at any given point, 10GiB of memory consumption sounds indeed a bit too much. The most worrying part to me isn't that it's consuming 10GiB at most: the lack of consistency is what makes it hard to plan a deployment: should I assign 6GiB as limit to my deployment? Or 10GiB? Or would 20GiB be better?)

Note that the main use case for using Badger vs. in memory isn't to be easier on the memory consumption: it is to be able to have persistent data between restarts. That said, I would also agree that a lower memory footprint would be highly desirable. As @jarifibrahim mentioned, the memory profile could be improved using certain features from Badger v2. Migrating to v2 has always being in our minds, but we never had a compelling reason to do it. At some point, I did have a PR for it, but I don't think we ran extensive benchmarks to ensure that we were indeed improving. The main contention point was about backwards compatibility with older versions: should we migrate data from v1 to v2? Or should we instruct users to do it by themselves?

Anyway, given that you seem to have the perfect motivation, would you want to invest some time in this and send a PR?

[lichenglin]

@lichenglin I ran a local test here with a rate somewhat above yours:

SPAN_STORAGE_TYPE=badger go run ./cmd/all-in-one --badger.ephemeral=false --badger.directory-value=/home/jpkroehling/.badger/jaeger/data --badger.directory-key=/home/jpkroehling/.badger/jaeger/key  --badger.span-store-ttl=1m --badger.consistency --badger.maintenance-interval=1m

$ go run ./cmd/tracegen -pause 50us -duration 1m 

This created 642670 traces in one minute (each with two spans) and consumed, at the peak, around 650MiB of disk space and about 2GiB of memory:

It wasn't clear to me whether the memory usage had peaked in this example, so, I ran a longer test (20m):

I have to agree that the pattern does seem a bit strange. From under 1GiB in the first minutes, to between 1GiB and 2 GiB for the next few minutes, and then between 2GiB and 3GiB for the last part. The peaks of 3GiB, then 4GiB, then 6.5GiB, then 10GiB are also suspicious, although could probably be explained. But given that the total disk usage was not much higher than 4GiB at any given point, 10GiB of memory consumption sounds indeed a bit too much. The most worrying part to me isn't that it's consuming 10GiB at most: the lack of consistency is what makes it hard to plan a deployment: should I assign 6GiB as limit to my deployment? Or 10GiB? Or would 20GiB be better?)

Note that the main use case for using Badger vs. in memory isn't to be easier on the memory consumption: it is to be able to have persistent data between restarts. That said, I would also agree that a lower memory footprint would be highly desirable. As @jarifibrahim mentioned, the memory profile could be improved using certain features from Badger v2. Migrating to v2 has always being in our minds, but we never had a compelling reason to do it. At some point, I did have a PR for it, but I don't think we ran extensive benchmarks to ensure that we were indeed improving. The main contention point was about backwards compatibility with older versions: should we migrate data from v1 to v2? Or should we instruct users to do it by themselves?

Anyway, given that you seem to have the perfect motivation, would you want to invest some time in this and send a PR?

Since I'm not a go developer, I'm not sure I can handle this.

I have updated badger to version 2.x in my github https://github.com/lichenglin/jaeger.git

But when I rerun the test up,It still the same. What did I miss?

What confusing me is Although I have set --badger.span-store-ttl=1m and why disk space never be clean.

And here is a solution for user to move 1.x's data to 2.x on badger's offsite https://dgraph.io/docs/badger/faq/#i-see-manifest-has-unsupported-version-x-we-support-y-error

[jpkrohling]

Since I'm not a go developer, I'm not sure I can handle this.

As part of the PR that I closed without merging, I built a container image for testing: quay.io/jpkroehling/all-in-one:badger-v2-ubi-minimal. Could you try this out? This is about 6 months old, but I don't think we had new features for badger since then. If you see that the memory profile is similar, then a simple upgrade to v2 isn't sufficient (v2.0.2).

But when I rerun the test up,It still the same. What did I miss?

You just added the new badger, without removing the old one. Also, the Go imports will need to reference the new package.

You can compare your commit with this PR: https://github.com/jaegertracing/jaeger/pull/2131/files .

[lichenglin]

Since I'm not a go developer, I'm not sure I can handle this.

As part of the PR that I closed without merging, I built a container image for testing: quay.io/jpkroehling/all-in-one:badger-v2-ubi-minimal. Could you try this out? This is about 6 months old, but I don't think we had new features for badger since then. If you see that the memory profile is similar, then a simple upgrade to v2 isn't sufficient (v2.0.2).

But when I rerun the test up,It still the same. What did I miss?

You just added the new badger, without removing the old one. Also, the Go imports will need to reference the new package.

You can compare your commit with this PR: https://github.com/jaegertracing/jaeger/pull/2131/files .

docker pull quay.io/jpkroehling/all-in-one:badger-v2-ubi-minima failed I can't find quay.io/jpkroehling/all-in-one:badger-v2-ubi-minimal in docker hup .

[jpkrohling]

You missed the final l in the first command:

$ docker pull quay.io/jpkroehling/all-in-one:badger-v2-ubi-minimal

[jarifibrahim]

Switching from 1x to 2x won't reduce the memory. You'll have to enable the index cache to see memory improvement.

You have to set the options.IndexCache size in badger. Wherever you're opening badger, set the IndexCacheSize in badger options.

[quaff]

We are using v1.19.2 with badger storage, It consume memory very fast and will drop very slow if no incoming requests. If switch to memory storage and limit max traces, memory usage will reach an reasonable peak and keep stable.

[jarifibrahim]

https://github.com/dgraph-io/badger/blob/c5d36c806aa80954a24606a982a475a717d44de2/table/table.go#L61 This is the index for each table which is kept in memory on v1x. This will grow linearly with the number of SST files in badger. On v2x, we support an index cache. So if you set 500 mb of index cache, we'll cache these table indices and it will limit the memory usage.

We're working on badger v3 which will remove the index cache. Badger v3 will use flatbuffers to store the index and this index will be mmapped so it will use 0 mb of RES memory. This is planned for the November release of badger.

[lichenglin]

https://github.com/dgraph-io/badger/blob/c5d36c806aa80954a24606a982a475a717d44de2/table/table.go#L61 This is the index for each table which is kept in memory on v1x. This will grow linearly with the number of SST files in badger. On v2x, we support an index cache. So if you set 500 mb of index cache, we'll cache these table indices and it will limit the memory usage.

We're working on badger v3 which will remove the index cache. Badger v3 will use flatbuffers to store the index and this index will be mmapped so it will use 0 mb of RES memory. This is planned for the November release of badger.

thanks for the reply.

And in v2, "index cache" is set by this option? // WithMaxCacheSize returns a new Options value with MaxCacheSize set to the given value. // This value specifies how much data cache should hold in memory. A small size of cache means lower // memory consumption and lookups/iterations would take longer. Setting size to zero disables the // cache altogether. func (opt Options) WithMaxCacheSize(size int64) Options { opt.MaxCacheSize = size return opt }

[Mario-Hofstaetter]

I believe I am having the same issue at a very low span ingest rate of about 20 spans / s, running jaeger 1.21

Is there anything I can do at the moment? This is a showstopper for us atm.

I am able to reproduce the behavior in a short period of time using a simple ASP .NET Core application using opentelemetry-dotnet. I can provide the source if that is of any help..

It happens on Windows, and in a linux docker container running in WSL2, I believe on native linux docker container too.

With very low span rate nothings happening, then suddenly memory peaks several times (can go beyond 8 GB):

When now more spans are sent, memory decreases slowly.

There are log errors happening and increasing in numbers:

{"level":"error","ts":1605554893.3096995,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: *jaeger.Span field 8 read error: don't know what type: 14","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}
{"level":"error","ts":1605554893.3096995,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: *jaeger.Span field 5 read error: don't know what type: 15","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}
{"level":"error","ts":1605554897.4190276,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: *jaeger.Span field 2 read error: don't know what type: 14","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}
{"level":"error","ts":1605554898.3213987,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: *jaeger.Span field 8 read error: don't know what type: 14","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}
{"level":"error","ts":1605554898.3213987,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: don't know what type: 14","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}
{"level":"error","ts":1605554898.322346,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: *jaeger.Span field 2 read error: don't know what type: 14","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}
{"level":"error","ts":1605554903.3332632,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: *jaeger.Span field -44 read error: don't know what type: 14","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}
{"level":"error","ts":1605554933.3925748,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: Required field TraceIdLow is not set","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}
{"level":"error","ts":1605554953.4234784,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: Required field TraceIdLow is not set","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}
{"level":"error","ts":1605554978.4874256,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: Required field TraceIdLow is not set","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}
{"level":"error","ts":1605555008.5477173,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: *jaeger.Span field 9 read error: don't know what type: 13","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}
{"level":"error","ts":1605555043.6064608,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: *jaeger.Span field 34 read error: don't know what type: 13","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}
{"level":"error","ts":1605555078.666566,"caller":"processors/thrift_processor.go:123","msg":"Processor failed","error":"*jaeger.Batch error reading struct: *jaeger.Span error reading struct: *jaeger.Span field 2 read error: don't know what type: 15","stacktrace":"github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).processBuffer\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:123\ngithub.com/jaegertracing/jaeger/cmd/agent/app/processors.NewThriftProcessor.func2\n\tgithub.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:87"}

Currently I have a dev setup where clients directly push spans to jaeger-all-in-one (runs on localhost).

[jpkrohling]

Related to #2638.

[jpkrohling]

@Mario-Hofstaetter, are you able to test the latest image? If the problem was the same as #2638, your problem should have been fixed already.

[Mario-Hofstaetter]

@jpkrohling Unfortunately I'm too busy atm to test this 😢 , we have switched our dev setup to elasticsearch backend in the meantime. Maybe @lichenglin has time to test it.

Anyway we'll have to keep MaxPayloadSizeInBytes = 65000; in OpenTelemetry exporter as stated in #2638 until a jaeger release is published.

[jpkrohling]

This is probably fixed by #3096. Please, reopen if you still see this happening.