Autoscaler memory usage increases even with total number of ksvcs/revisions kept constant

[skonto]

/area monitoring

What version of Knative?

0.18.2 but should affect any version greater than this one.

Expected Behavior

Creating/deleting a number of ksvcs while keeping the final number constant eg zero should not create any significant difference
in the heap memory allocated before and after the crud ops.

Actual Behavior

Running reproducer reproducer.sh (see attached file reproducer.sh.txt) soak test that repeatedly creates and deletes ksvcs, keeping the total number of ksvcs constant autoscaler gets OOMKilled after 4 hours.

Steps to Reproduce the Problem

Running reproducer.sh (see attached file) for > 4hs.

[root@ocp-dynamic-6653 ~]# go tool pprof --base "knative-serving.autoscaler-699dff8cff-hk27b.heap.2021-01-10_09:24:04-05:00.pb.gz" "knative-serving.autoscaler-699dff8cff-hk27b.heap.2021-01-10_10:47:41-05:00.pb.gz"                        
File: autoscaler
Type: inuse_space
Time: Jan 10, 2021 at 9:24am (EST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 47.90MB, 85.65% of 55.93MB total
Dropped 5 nodes (cum <= 0.28MB)
Showing top 10 nodes out of 130
      flat  flat%   sum%        cum   cum%
   26.89MB 48.08% 48.08%    26.89MB 48.08%  go.opencensus.io/stats/view.NewMeter
       6MB 10.73% 58.81%        6MB 10.73%  go.opencensus.io/stats/view.(*collector).addSample
    3.50MB  6.26% 65.07%        9MB 16.10%  go.opencensus.io/stats/view.(*worker).tryRegisterView
       3MB  5.36% 70.44%        3MB  5.36%  go.opencensus.io/stats/view.viewToMetricDescriptor
    2.50MB  4.47% 74.91%     2.50MB  4.47%  knative.dev/pkg/metrics.copyViews
    1.51MB  2.69% 77.60%     1.51MB  2.69%  k8s.io/apimachinery/pkg/apis/meta/v1.(*FieldsV1).UnmarshalJSON
    1.50MB  2.68% 80.28%     1.50MB  2.68%  go.opencensus.io/stats/view.(*worker).getMeasureRef (inline)
       1MB  1.79% 82.07%        1MB  1.79%  go.opencensus.io/stats/view.(*worker).RegisterExporter
       1MB  1.79% 83.86%        2MB  3.58%  go.opencensus.io/stats/view.(*collector).collectedRows
       1MB  1.79% 85.65%        4MB  7.15%  go.opencensus.io/stats/view.newViewInternal (inline)

autoscaler.heap.zip contains the data for heap comparison.
This seems to happen due to the fact that a NewMeter is called every time we record a metric and we actually never delete any meter from this map. It seems like a bug at the knative.pkg/metrics side.
Note: that this affects other components since we use metrics everywhere. We noticed also an issue with the activator by using a similar test that issues http requests.

Credit goes to @maschmid for discovering this.

[vagababov]

(ノಠ益ಠ)ノ彡┻━┻

metrics again :)

[vagababov]

/cc @evankanderson

[evankanderson]

I'd expect knative/pkg#1741 fixes the problem, let me see if it got pulled in...

[evankanderson]

Yes, it looks like the release-0.18 branch does not have that patch.

Do you want me to try to back-port a cherrypick of that change?

[skonto]

@evankanderson yes that would be great! I have a question though, in that PR there is a 10minute TTL beyond that all exporters are flushed and meters are removed. I am wondering from a semantics perspective if a revision is just inactive (nothing happens), no traffic hits it and no event happens related to scaling etc, so no call to Record(), would that mean that we will remove its metrics so that prometheus for example would show no metrics when it will scrape the metrics endpoint?

[evankanderson]

Yes, that's what will happen. We can probably adjust the TTL, but tying it in with the informer cache is probably a much larger PR.

[skonto]

Ok cool, I guess we could cleanup things when we get a delete event like here and do that per resource informer, would that work in general?
Regarding adjusting the TTL in the PR we could list the resource (hits the cache should be cheap) and if it exists in the cache we should keep the metrics.

[evankanderson]

It would be nice if we could keep the Meter or a set of Counters/Observers alongside the informer in the cache, and then load them into the Context when handling something for that Resource.

[evankanderson]

(Unfortunately, the current code is structured with a sort-of-global singleton for the Metrics, which isn't right for our use case, but I started the migration from the inside rather than the outside.)

[skonto]

@evankanderson have a pointer for the migration? Anyway I can help?

[skonto]

@evankanderson even with the fix were are hitting the same issue, activator and autoscaler are restarting in 12h soak test (here is a dump diff with a 25 minutes time diff):

[root@ocp-dynamic-20 soak]# go tool pprof --base "knative-serving_autoscaler-6d76d9d7f4-ddrvt_heap_2021-01-29T09:34:17-05:00.pb.gz" "knative-serving_autoscaler-6d76d9d7f4-ddrvt_heap_2021-01-29T10:00:30-05:00.pb.gz"
File: autoscaler
Type: inuse_space
Time: Jan 29, 2021 at 9:34am (EST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top20
Showing nodes accounting for 6789.61kB, 38.01% of 17861.85kB total
Dropped 7 nodes (cum <= 89.31kB)
Showing top 20 nodes out of 156
      flat  flat%   sum%        cum   cum%
 2048.56kB 11.47% 11.47%  2048.56kB 11.47%  go.opencensus.io/stats/view.(*collector).addSample
 1552.15kB  8.69% 20.16%  1552.15kB  8.69%  go.opencensus.io/stats/view.NewMeter
 1537.44kB  8.61% 28.77%  3073.53kB 17.21%  go.opencensus.io/stats/view.(*worker).tryRegisterView
 1026.91kB  5.75% 34.52%  1026.91kB  5.75%  k8s.io/apimachinery/pkg/apis/meta/v1.(*FieldsV1).UnmarshalJSON
 1024.08kB  5.73% 40.25%  1024.08kB  5.73%  go.opencensus.io/stats/view.viewToMetricDescriptor
 1024.08kB  5.73% 45.98%  1024.08kB  5.73%  knative.dev/pkg/metrics.copyViews
 -902.59kB  5.05% 40.93%  -902.59kB  5.05%  compress/flate.NewWriter
 -528.17kB  2.96% 37.97%  -528.17kB  2.96%  encoding/json.(*Decoder).refill
  528.17kB  2.96% 40.93%   528.17kB  2.96%  regexp.(*bitState).reset
 -518.65kB  2.90% 38.03%  -518.65kB  2.90%  github.com/json-iterator/go.(*Iterator).stopCapture
    -514kB  2.88% 35.15%     -514kB  2.88%  bufio.NewReaderSize
 -512.28kB  2.87% 32.28%  -512.28kB  2.87%  encoding/json.(*decodeState).objectInterface
 -512.25kB  2.87% 29.41%  -512.25kB  2.87%  reflect.New
  512.14kB  2.87% 32.28%   512.14kB  2.87%  k8s.io/apimachinery/pkg/apis/meta/v1.(*ObjectMeta).DeepCopyInto
 -512.10kB  2.87% 29.41%  -512.10kB  2.87%  go.uber.org/zap.getCallerFrame
  512.05kB  2.87% 32.28%   512.05kB  2.87%  context.(*cancelCtx).Done
  512.05kB  2.87% 35.15%   512.05kB  2.87%  golang.org/x/net/http2.(*ClientConn).newStream
  512.05kB  2.87% 38.01%   512.05kB  2.87%  net/http.(*persistConn).roundTrip
 -512.04kB  2.87% 35.15%  -512.04kB  2.87%  go.opencensus.io/stats/view.(*worker).reportView
  512.03kB  2.87% 38.01%   512.03kB  2.87%  context.WithCancel

I think the reason for this is that we create the views here (also by copying them): https://github.com/knative/pkg/blob/ca02ef752ac658f5a315b619e56ec2f87fafdeff/metrics/resource_view.go#L131 but we never unregister them (so old metrics are still exported). During cleanup there is an exporter flush https://github.com/knative/pkg/blob/ca02ef752ac658f5a315b619e56ec2f87fafdeff/metrics/resource_view.go#L87 but the exporter is always nil. Metrics are not that many per resource thus the slow OOM issue. The increase exists also in the statistics in the ticket description above, so it didnt go away by removing the meters from the array.
So my guess is that we have to unregister the views during cleanup.

[skonto]

I think we can close this as there is a fix merged. We should keep an eye though.