OOM on unrecoverable errors even with memory_limiter configured

[kbrockhoff]

Describe the bug
Kubernetes container running otelcol ends up in CrashLoopBackoff on repeated unrecoverable errors from an exporter. This is with the memory_limiter in place and working without error when data is flowing normally.

Steps to reproduce
Push enough data to AWS X-Ray that is starts returning ThrottlingExceptions.

What did you expect to see?
Span data is dropped and otelcol instance keeps running without issues.

What did you see instead?
Constant restarts of K8s pod.

What version did you use?
Version: Custom build from commit f640b71 of open telemetry-collector-contrib

What config did you use?
Config:

receivers:
  opencensus:
    endpoint: ":55678"
    max_recv_msg_size_mib: 16
    max_concurrent_streams: 16
  otlp:
    endpoint: ":55680"
    max_recv_msg_size_mib: 16
    max_concurrent_streams: 16
  
processors:
  memory_limiter:
    ballast_size_mib: 192
    check_interval: 5s
    limit_mib: 448
    spike_limit_mib: 64
  queued_retry:
    num_workers: 16
    queue_size: 8192
    retry_on_failure: true
  batch:
    send_batch_size: 48
    timeout: 15s

exporters:
  awsxray:
    num_workers: 8
    endpoint: ""
    request_timeout_seconds: 30
    max_retries: 2
    no_verify_ssl: false
    local_mode: false
    resource_arn: "arn:aws:eks:{{ .Values.Region }}:{{ .Values.AWS_ACCOUNT_ID }}:cluster/{{ .Values.CLUSTER_NAME }}"
    role_arn: ""

extensions:
  health_check:
    port: 13133
  zpages:
    endpoint: ":55679"

service:
  extensions: [zpages, health_check]
  pipelines:
    traces:
      receivers: [opencensus, otlp]
      processors: [memory_limiter, batch, queued_retry]
      exporters: [awsxray]

Environment
OS: Amazon Linux/2
Compiler go 14.2

Additional context

2020-06-12T18:30:49.872Z	WARN	queuedprocessor/queued_processor.go:175	Unrecoverable bad data error	{"component_kind": "processor", "component_type": "queued_retry", "component_name": "queued_retry", "#spans": 916, "error": "ThrottlingException: Rate exceeded\n\tstatus code: 400, request id: 56eb8255-dc18-4fd9-8548-4ab086f7565c"}
go.opentelemetry.io/collector/processor/queuedprocessor.(*queuedSpanProcessor).processItemFromQueue
	/go/pkg/mod/go.opentelemetry.io/collector@v0.3.1-0.20200522130256-daf2fc71ac65/processor/queuedprocessor/queued_processor.go:175
go.opentelemetry.io/collector/processor/queuedprocessor.(*queuedSpanProcessor).Start.func1
	/go/pkg/mod/go.opentelemetry.io/collector@v0.3.1-0.20200522130256-daf2fc71ac65/processor/queuedprocessor/queued_processor.go:86
github.com/jaegertracing/jaeger/pkg/queue.(*BoundedQueue).StartConsumers.func1
	/go/pkg/mod/github.com/jaegertracing/jaeger@v1.17.0/pkg/queue/bounded_queue.go:77
2020-06-12T18:30:50.073Z	WARN	queuedprocessor/queued_processor.go:175	Unrecoverable bad data error	{"component_kind": "processor", "component_type": "queued_retry", "component_name": "queued_retry", "#spans": 713, "error": "ThrottlingException: Rate exceeded\n\tstatus code: 400, request id: defbd58d-8b87-4f3c-a2d5-f0a1ff3327a4"}
go.opentelemetry.io/collector/processor/queuedprocessor.(*queuedSpanProcessor).processItemFromQueue
	/go/pkg/mod/go.opentelemetry.io/collector@v0.3.1-0.20200522130256-daf2fc71ac65/processor/queuedprocessor/queued_processor.go:175
go.opentelemetry.io/collector/processor/queuedprocessor.(*queuedSpanProcessor).Start.func1
	/go/pkg/mod/go.opentelemetry.io/collector@v0.3.1-0.20200522130256-daf2fc71ac65/processor/queuedprocessor/queued_processor.go:86
github.com/jaegertracing/jaeger/pkg/queue.(*BoundedQueue).StartConsumers.func1
	/go/pkg/mod/github.com/jaegertracing/jaeger@v1.17.0/pkg/queue/bounded_queue.go:77
2020-06-12T18:30:50.075Z	WARN	queuedprocessor/queued_processor.go:175	Unrecoverable bad data error	{"component_kind": "processor", "component_type": "queued_retry", "component_name": "queued_retry", "#spans": 678, "error": "ThrottlingException: Rate exceeded\n\tstatus code: 400, request id: 27700543-f30f-49c4-bc5d-19c27b225309"}
go.opentelemetry.io/collector/processor/queuedprocessor.(*queuedSpanProcessor).processItemFromQueue
	/go/pkg/mod/go.opentelemetry.io/collector@v0.3.1-0.20200522130256-daf2fc71ac65/processor/queuedprocessor/queued_processor.go:175
go.opentelemetry.io/collector/processor/queuedprocessor.(*queuedSpanProcessor).Start.func1
	/go/pkg/mod/go.opentelemetry.io/collector@v0.3.1-0.20200522130256-daf2fc71ac65/processor/queuedprocessor/queued_processor.go:86
github.com/jaegertracing/jaeger/pkg/queue.(*BoundedQueue).StartConsumers.func1
	/go/pkg/mod/github.com/jaegertracing/jaeger@v1.17.0/pkg/queue/bounded_queue.go:77
2020-06-12T18:30:50.272Z	WARN	queuedprocessor/queued_processor.go:175	Unrecoverable bad data error	{"component_kind": "processor", "component_type": "queued_retry", "component_name": "queued_retry", "#spans": 2005, "error": "ThrottlingException: Rate exceeded\n\tstatus code: 400, request id: 03052edb-a4de-4cb4-813b-b8096ce47f42"}

[jpkrohling]

@kbrockhoff, how do your resources settings for the deployment look like? I'll try to simulate this with another exporter, as I don't have an AWS account for testing this, so, would you be able to get me a series of pprof snapshots? Like, one every minute, if it takes a few minutes to reach this state (or one every hour). This way, I can see what's getting stuck in memory for your problem and compare with what I'm trying to reproduce locally.

[jpkrohling]

I need the information requested in the previous comment to confirm, but I think this can be reproduced with a setup like this:

1. podman run -p 14250:14250 -p 16686:16686 jaegertracing/all-in-one --memory.max-traces=1000
2. go run ./cmd/otelcol --config local/config.memlimit.yaml --mem-ballast-size-mib 192 (on github.com/open-telemetry/opentelemetry-collector)
3. tracegen -duration 5m -otlp-insecure (tracegen from contrib)

And with this config file:

receivers:
  otlp:
    protocols:
      grpc:
        endpoint: ":55680"
        max_recv_msg_size_mib: 16
        max_concurrent_streams: 16

processors:
  memory_limiter:
    ballast_size_mib: 192
    check_interval: 5s
    limit_mib: 448
    spike_limit_mib: 64
  queued_retry:
    num_workers: 16
    queue_size: 8192
    retry_on_failure: true
  batch:
    send_batch_size: 48
    timeout: 15s

exporters:
  jaeger:
    endpoint: localhost:14250
    insecure: true

extensions:
  health_check:
    port: 13133
  zpages:
    endpoint: ":55679"
  pprof:
    endpoint: ":1777"

service:
  extensions: [zpages, health_check, pprof]
  pipelines:
    traces:
      receivers: [otlp]
      processors: [memory_limiter, batch, queued_retry]
      exporters: [jaeger]

This will run with a very low memory profile while Jaeger is up, but stopping the Jaeger container will cause the queued retry to jump to very high levels of memory consumption, depending on the in-flight data. I've seen numbers between ~400Mi and ~1Gi, which certainly would explain your OOMKilled in Kubernetes, depending on your limits configuration.

Note that there are two queued retries: one as a processor (deprecated) and one inside the exporter. Disabling both will cause the memory profile to be at the normal levels even when the exporter is failing:

receivers:
  otlp:
    protocols:
      grpc:
        endpoint: ":55680"
        max_recv_msg_size_mib: 16
        max_concurrent_streams: 16

processors:
  memory_limiter:
    ballast_size_mib: 192
    check_interval: 5s
    limit_mib: 448
    spike_limit_mib: 64
  batch:
    send_batch_size: 48
    timeout: 15s

exporters:
  jaeger:
    endpoint: localhost:14250
    insecure: true
    retry_on_failure:
      enabled: false

extensions:
  health_check:
    port: 13133
  zpages:
    endpoint: ":55679"
  pprof:
    endpoint: ":1777"

service:
  extensions: [zpages, health_check, pprof]
  pipelines:
    traces:
      receivers: [otlp]
      processors: [memory_limiter, batch]
      exporters: [jaeger]

In the example above, note that I disabled the Jaeger queued retry and removed the queued_retry processor entirely. And here's the catch: the memory limiter only works for things entering the pipeline: things that are already in the pipeline aren't evicted, even if they are being retried. In the tests above, I confirmed that the memory limiter did stop new data from being added to the pipeline, sending this back to the client:

2020/11/09 17:29:34 rpc error: code = Unknown desc = data dropped due to high memory usage

That all said, I think this is actually working as designed, but we should definitely talk about improving this design, as it's clearly not enough to prevent OOMs.

[jpkrohling]

@kbrockhoff, did you have a chance to get the requested info?

[jpkrohling]

@tigrannajaryan, @pjanotti: looking at the original PR that introduced this processor (#498), I see that the case where exporters are unavailable is explicitly listed there as a motivation for using this processor. Given that this is exactly the case here, it appears that either the design for this processor should be changed or this processor should be removed, as it's not being very effective. In fact,, it causes a false sense of security at the moment.

[tigrannajaryan]

In the tests above, I confirmed that the memory limiter did stop new data from being added to the pipeline, sending this back to the client:

@jpkrohling If the memory limiter stops the new data from being added why is it not effective at limiting the data? Is new data being created elsewhere?

things that are already in the pipeline aren't evicted, even if they are being retried.

They should be eventually evicted after the maximum number of retries is reached. It may take a while. In the meantime no new data should be added so I don't understand why the limiter is not effective.

That all said, I think this is actually working as designed, but we should definitely talk about improving this design, as it's clearly not enough to prevent OOMs.
In fact,, it causes a false sense of security at the moment.

We definitely need to fix it. For now I don't understand what is the design flaw.

[jpkrohling]

why is it not effective at limiting the data?

It does stop, but only after the process has exploded in memory usage way above the limit set in the memory limiter. People using the memory-limiter setting the limit to, say, 1GiB would assume the process won't ever go over ~1GiB, but it can actually go over double of that very easily, causing their watchdog processes (like Kubernetes requests/limits) to kill the process.

[kbrockhoff]

I do not have access to the k8s pod config used at that time any more. Knowing how I usually set this, I am fairly confident the pod memory limit was set to 512m

[tigrannajaryan]

but it can actually go over double of that very easily

Why does this happen? Limiter kicks in too late?

[jpkrohling]

Why does this happen? Limiter kicks in too late?

Yes, I believe so. In the example I was testing, the check happens every 5s, which is already too long for high-traffic scenarios. And I'm not sure we'd want more frequent checks than that, especially for high-throughput collectors. I would love to come up with a proposal, but I can't think of one that would be satisfactory for the case that was tested here.

[tigrannajaryan]

Closing for now, should be fixed or at least mitigated by #2250
Can reopen if more work is needed.