keda Timeout or abort while handling GET external metrics with 1500 scaledobjects

Timeout or abort while handling GET external metrics with 1500 scaledobjects

Open kevinteng525 opened this issue 1 year ago • 3 comments

Report

Greetings,

We are running some lnp test with KEDA scaledobjects, we created 1500 namespaces with deployments and scaledobjects, each scaledobjects includes 4 prometheus triggers + 1 cron trigger, so totally there will be 1500 x 5 = 7500 external metrics, the polling interval is set as 300.

And we found following errors from keda-metrics-apiserver logs, although most metrics will return successfully.

E0915 05:55:16.374102 1 wrap.go:54] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="9b262919-7c2d-4b35-b4cc-58d0101d3f42" E0915 05:55:16.374236 1 wrap.go:54] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="5c2dbfe7-0768-4c89-8dd0-071ec0fc0436" E0915 05:55:16.374284 1 timeout.go:141] post-timeout activity - time-elapsed: 132.995µs, GET "/apis/external.metrics.k8s.io/v1beta1" result: E0915 05:55:16.374332 1 writers.go:111] apiserver was unable to close cleanly the response writer: http2: stream closed E0915 05:55:16.374661 1 wrap.go:54] timeout or abort while handling: method=GET

I also tried retrieving those metrics manually and were able to return successfully, e.g. kubectl get --raw "/apis/external.metrics.k8s.io/v1beta1/namespaces/sample-app-2900/s2-prometheus-gcovhdx10" | jq

So I thought those timeout errors might happen when too many requests sent at once. I tried increasing KEDA_HTTP_DEFAULT_TIMEOUT, and CPU/memory, but doesn't help.

Have you met such issue in your environments? And do you have any suggestion how to eliminate it?

Thanks, Kevin

Expected Behavior

No timeout errors

Actual Behavior

Seeing timeout errors from keda-metrics-apiserver logs

Steps to Reproduce the Problem

created 1500 namespaces with deployments and scaledobjects
each scaledobjects includes 4 prometheus triggers + 1 cron trigger
pollingInterval = 300

Logs from KEDA operator

E0915 05:55:16.374102       1 wrap.go:54] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="9b262919-7c2d-4b35-b4cc-58d0101d3f42"
E0915 05:55:16.374236       1 wrap.go:54] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="5c2dbfe7-0768-4c89-8dd0-071ec0fc0436"
E0915 05:55:16.374284       1 timeout.go:141] post-timeout activity - time-elapsed: 132.995µs, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>
E0915 05:55:16.374332       1 writers.go:111] apiserver was unable to close cleanly the response writer: http2: stream closed
E0915 05:55:16.374661       1 wrap.go:54] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="7b09ac4f-a579-4efb-a65c-31223ee09525"
E0915 05:55:16.374663       1 wrap.go:54] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="2d47c189-0a1c-4bbb-a281-6a20938a636d"
E0915 05:55:16.374682       1 timeout.go:141] post-timeout activity - time-elapsed: 1.994µs, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>
E0915 05:55:16.374690       1 timeout.go:141] post-timeout activity - time-elapsed: 3.367µs, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>
E0915 05:55:16.374915       1 wrap.go:54] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="744e9c6e-73df-4d9a-bee7-6fcd42aab3cf"
E0915 05:55:16.374965       1 timeout.go:141] post-timeout activity - time-elapsed: 31.847µs, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>
E0915 05:55:16.378196       1 timeout.go:141] post-timeout activity - time-elapsed: 3.938072ms, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>
I0915 05:55:26.373519       1 trace.go:205] Trace[979874152]: "List" url:/apis/external.metrics.k8s.io/v1beta1/namespaces/sample-app-2774/s0-prometheus-cpu,user-agent:kube-controller-manager/v1.18.8 (linux/amd64) kubernetes/00549f3/system:serviceaccount:kube-system:horizontal-pod-autoscaler,audit-id:fac6c61f-b7e0-455e-a717-167f1bf59a10,client:10.153.229.14,accept:application/vnd.kubernetes.protobuf, */*,protocol:HTTP/2.0 (15-Sep-2022 05:55:25.744) (total time: 628ms):
Trace[979874152]: ---"Listing from storage done" 628ms (05:55:26.373)
Trace[979874152]: [628.761119ms] [628.761119ms] END
I0915 05:55:27.806344       1 trace.go:205] Trace[1865276521]: "List" url:/apis/external.metrics.k8s.io/v1beta1/namespaces/sample-app-2774/s1-prometheus-appthread,user-agent:kube-controller-manager/v1.18.8 (linux/amd64) kubernetes/00549f3/system:serviceaccount:kube-system:horizontal-pod-autoscaler,audit-id:282aefef-685b-402e-ae53-54ba0ea17d5f,client:10.153.229.14,accept:application/vnd.kubernetes.protobuf, */*,protocol:HTTP/2.0 (15-Sep-2022 05:55:26.377) (total time: 1429ms):
Trace[1865276521]: ---"Listing from storage done" 1429ms (05:55:27.806)
Trace[1865276521]: [1.429245175s] [1.429245175s] END
I0915 05:55:30.936054       1 trace.go:205] Trace[2080867570]: "List" url:/apis/external.metrics.k8s.io/v1beta1/namespaces/sample-app-711/s3-prometheus-tps,user-agent:kube-controller-manager/v1.18.8 (linux/amd64) kubernetes/00549f3/system:serviceaccount:kube-system:horizontal-pod-autoscaler,audit-id:d73b22a6-1403-4e7c-95fa-9c3ec1d377d2,client:10.153.229.14,accept:application/vnd.kubernetes.protobuf, */*,protocol:HTTP/2.0 (15-Sep-2022 05:55:30.169) (total time: 766ms):
Trace[2080867570]: ---"Listing from storage done" 766ms (05:55:30.935)
Trace[2080867570]: [766.150331ms] [766.150331ms] END

KEDA Version

2.7.1

Kubernetes Version

< 1.23

Platform

No response

Scaler Details

Prometheus

Anything else?

No response

Sep 15 '22 06:09 kevinteng525

Hey, We are working to redesign KEDA to improve the mechanics with an internal cache but I can't provide any ETA atm, sorry :( I expect to have it aiming to v2.10, but we are discussing how to proceed yet

Sep 19 '22 18:09 JorTurFer

Oh, great! BTW, What will be cached in the internal cache?

Sep 26 '22 10:09 kevinteng525

KEDA already has cache now, but only for the scalers itself, not the values. When the HPA Controller ask the value, KEDA needs to go directly to the upstream, and that requires some time, that's why in huge clusters with a lot of ScaledObjects, there are problems like yours.

The "draw" of the idea is basically to querying the values constantly in the operator (every X seconds) and send that values to the metrics-server, so the metrics server only needs to check the value from its own memory instead of going to the upstream. This can improve a lot the performance because the HPA Controller is single thread and requires responding fastest as possible but our operator is multithread, so we could have multiple thread preloading the metrics in the metrics server and when the HPA Controller request a metrics, KEDA only needs a few ms to respond instead of 50-200ms.

This idea is still on design, so I can't give any ETA, but basically we will cache/store every scaler value and we will refresh it every X seconds

Sep 26 '22 11:09 JorTurFer

@JorTurFer It also happen when I only use 60 scaledobject

KEDA Version 2.8.1

Kubernetes Version 1.20.11

Platform ack

Scaler Details Prometheus


E0930 08:31:32.883497 1 wrap.go:53] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="81d48256-b8da-4296-a4c8-18ad28a366fe"
--
Fri, Sep 30 2022 4:31:32 pm | E0930 08:31:32.883560 1 timeout.go:141] post-timeout activity - time-elapsed: 31.278µs, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>
Fri, Sep 30 2022 4:33:32 pm | E0930 08:33:32.883236 1 wrap.go:53] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="869fb11d-6feb-4ad3-9d63-4e4ac1ef7854"
Fri, Sep 30 2022 4:33:32 pm | E0930 08:33:32.883320 1 wrap.go:53] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="a7f08d81-a31a-400d-b32c-58eac9448214"
Fri, Sep 30 2022 4:33:32 pm | E0930 08:33:32.883341 1 writers.go:118] apiserver was unable to write a JSON response: http2: stream closed
Fri, Sep 30 2022 4:33:32 pm | E0930 08:33:32.883376 1 timeout.go:141] post-timeout activity - time-elapsed: 37.952µs, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>
Fri, Sep 30 2022 4:33:32 pm | E0930 08:33:32.886032 1 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"http2: stream closed"}: http2: stream closed
Fri, Sep 30 2022 4:33:32 pm | E0930 08:33:32.887286 1 writers.go:131] apiserver was unable to write a fallback JSON response: http: Handler timeout
Fri, Sep 30 2022 4:33:32 pm | E0930 08:33:32.889294 1 timeout.go:141] post-timeout activity - time-elapsed: 6.019707ms, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>
Fri, Sep 30 2022 4:49:02 pm | E0930 08:49:02.886873 1 wrap.go:53] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="5eb0cb40-8c4a-4ff7-a186-646671acd1ff"
Fri, Sep 30 2022 4:49:02 pm | E0930 08:49:02.886937 1 timeout.go:141] post-timeout activity - time-elapsed: 2.186µs, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>
Fri, Sep 30 2022 4:49:02 pm | E0930 08:49:02.886956 1 wrap.go:53] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="dcb53acc-ba44-4139-8d77-a53a22d067ac"
Fri, Sep 30 2022 4:49:02 pm | E0930 08:49:02.886988 1 timeout.go:141] post-timeout activity - time-elapsed: 1.166µs, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>

apiVersion: keda.sh/v1alpha1
kind: ScaledObject
metadata:
  finalizers:
    - finalizer.keda.sh
  labels:
    app.kubernetes.io/name: bservice29
    devops.zego.im/center-name: smalpha
    devops.zego.im/cluster-name: smalpha
    devops.zego.im/env: alpha
    devops.zego.im/group: media
    devops.zego.im/operator-version: v1.3.0
    devops.zego.im/system-name: rtc
    scaledobject.keda.sh/name: so-bservice29
  name: so-bservice29
  namespace: test-infra
spec:
  advanced:
    horizontalPodAutoscalerConfig:
      behavior:
        scaleDown:
          policies:
            - periodSeconds: 600
              type: Percent
              value: 5
            - periodSeconds: 300
              type: Pods
              value: 1
          selectPolicy: Min
          stabilizationWindowSeconds: 1800
        scaleUp:
          policies:
            - periodSeconds: 15
              type: Pods
              value: 8
            - periodSeconds: 15
              type: Percent
              value: 100
          selectPolicy: Max
          stabilizationWindowSeconds: 0
  maxReplicaCount: 1
  minReplicaCount: 1
  scaleTargetRef:
    apiVersion: apps.zego.im/v1alpha3
    kind: AppGroup
    name: bservice29
  triggers:
    - metadata:
        metricName: istio-proxy-prometheus-0
        query: >-
          max(rate(container_cpu_usage_seconds_total{namespace="test-infra",container="bservice290"}[2m]))
        serverAddress: 'http://prometheus-operated.monitoring:9090'
        threshold: '65'
      metricType: Value
      type: prometheus
    - metadata:
        metricName: service-bservice29-0
        query: >-
          max(rate(container_cpu_usage_seconds_total{namespace="test-infra",container="bservice290"}[2m]))
        serverAddress: 'http://prometheus-operated.monitoring:9090'
        threshold: '65'
      metricType: Value
      type: prometheus
    - metadata:
        desiredReplicas: '600'
        end: 55 23 * * *
        start: 0 0 * * *
        timezone: Asia/Shanghai
      type: cron

Sep 30 '22 08:09 penghuazhou

@penghuazhou Could you prometheus server have slow responses too? I mean, the HPA Controller requests the metric to KEDA and KEDA requests it to prometheus server, if prometheus server has slow responses, KEDA could fail. Do you have any monitoring on that? Could you share operator logs too? they are clearer in some places

Sep 30 '22 15:09 JorTurFer

@JorTurFer, prometheus server response 35ms，kubernetes version 1.20.11.

operator logs is below. there be no errors.

2022-10-07T10:09:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice21","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice21", "reconcileID": "ef3ba788-6f45-46b1-9b9b-285ca9ab8785"}
2022-10-07T10:09:36Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice21","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice21", "reconcileID": "ef3ba788-6f45-46b1-9b9b-285ca9ab8785"}
2022-10-07T10:09:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice22","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice22", "reconcileID": "b75c369a-e1ab-43d6-81de-96a29efd6029"}
2022-10-07T10:09:36Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice22","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice22", "reconcileID": "b75c369a-e1ab-43d6-81de-96a29efd6029"}
2022-10-07T10:09:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice23","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice23", "reconcileID": "e67a4d86-1d0a-4304-bb65-cffc0b695b4a"}
2022-10-07T10:09:36Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice23","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice23", "reconcileID": "e67a4d86-1d0a-4304-bb65-cffc0b695b4a"}
2022-10-07T10:09:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice24","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice24", "reconcileID": "ac848a88-3ec4-4d4f-82f8-a1d58b348166"}
2022-10-07T10:09:36Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice24","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice24", "reconcileID": "ac848a88-3ec4-4d4f-82f8-a1d58b348166"}
2022-10-07T10:09:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice25","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice25", "reconcileID": "f51c9819-3aaf-4ec5-b14a-99df8f1e6954"}
2022-10-07T10:09:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice26","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice26", "reconcileID": "e7fc0f6e-803b-430d-bcd0-af457a2af3c0"}
2022-10-07T10:09:37Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice25","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice25", "reconcileID": "f51c9819-3aaf-4ec5-b14a-99df8f1e6954"}
2022-10-07T10:09:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice27","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice27", "reconcileID": "b8e086bc-5316-45b2-972f-23f5120ab0e0"}
2022-10-07T10:09:37Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice26","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice26", "reconcileID": "e7fc0f6e-803b-430d-bcd0-af457a2af3c0"}
2022-10-07T10:09:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice28","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice28", "reconcileID": "e190e242-94a0-46ec-a29e-48cbcd2fe083"}
2022-10-07T10:09:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice29","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice29", "reconcileID": "2d233631-afc5-414e-bef9-2e86ceb1883f"}
2022-10-07T10:09:37Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice27","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice27", "reconcileID": "b8e086bc-5316-45b2-972f-23f5120ab0e0"}
2022-10-07T10:09:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice3","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice3", "reconcileID": "09a2786d-02b5-4758-8195-876d39caeb4d"}
2022-10-07T10:09:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice4","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice4", "reconcileID": "ab1fa27f-9568-44b5-a7c8-98977db2e34b"}
2022-10-07T10:09:37Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice28","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice28", "reconcileID": "e190e242-94a0-46ec-a29e-48cbcd2fe083"}
2022-10-07T10:09:37Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice29","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice29", "reconcileID": "2d233631-afc5-414e-bef9-2e86ceb1883f"}
2022-10-07T10:09:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice5","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice5", "reconcileID": "70fccd94-1018-4685-bab6-0a88f611f5ad"}
2022-10-07T10:09:37Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice3","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice3", "reconcileID": "09a2786d-02b5-4758-8195-876d39caeb4d"}
2022-10-07T10:09:37Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice4","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice4", "reconcileID": "ab1fa27f-9568-44b5-a7c8-98977db2e34b"}
2022-10-07T10:09:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice6","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice6", "reconcileID": "9026aaa0-6db0-44ba-8f84-78cd0d0979b1"}
2022-10-07T10:09:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice7","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice7", "reconcileID": "f4b0052b-90a5-451d-ab3b-20053869844b"}
2022-10-07T10:09:37Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice5","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice5", "reconcileID": "70fccd94-1018-4685-bab6-0a88f611f5ad"}
2022-10-07T10:09:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice8","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice8", "reconcileID": "0ad6a4b9-3f02-408b-85b4-9d813ce586ac"}
2022-10-07T10:09:38Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice9","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice9", "reconcileID": "d66514bb-87e9-47db-912e-07c2f3022fd9"}
2022-10-07T10:09:38Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice6","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice6", "reconcileID": "9026aaa0-6db0-44ba-8f84-78cd0d0979b1"}
2022-10-07T10:09:38Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice7","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice7", "reconcileID": "f4b0052b-90a5-451d-ab3b-20053869844b"}
2022-10-07T10:09:38Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice8","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice8", "reconcileID": "0ad6a4b9-3f02-408b-85b4-9d813ce586ac"}
2022-10-07T10:09:38Z	INFO	Initializing Scaling logic according to ScaledObject Specification	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"so-bservice9","namespace":"test-infra"}, "namespace": "test-infra", "name": "so-bservice9", "reconcileID": "d66514bb-87e9-47db-912e-07c2f3022fd9"}
2022-10-07T10:09:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "13a53171-a0a5-4d01-86b4-b608cafd485f"}
2022-10-07T10:10:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "2dd3ef64-fd86-4d8a-8441-93a7d429b944"}
2022-10-07T10:10:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "b5959006-2f7c-4f7a-8aae-aa0963badbab"}
2022-10-07T10:10:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "de7f4d26-fb7d-43cc-9849-f9f4e8367390"}
2022-10-07T10:10:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "d8bcc0ec-9a9f-4793-8596-bd5e2f8b6e90"}
2022-10-07T10:11:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "7a04128c-0831-40dd-9b2a-b7416dd4ebdf"}
2022-10-07T10:11:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "95bae500-83eb-408c-bb14-e81c6ba8ac06"}
2022-10-07T10:11:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "27bf50b1-60cf-4dad-808e-31fe8cb86147"}
2022-10-07T10:11:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "9f438de2-6e6b-420a-b59c-eb13f4f301ca"}
2022-10-07T10:12:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "0a79e0ac-6842-4df7-b235-34a562ba10ba"}
2022-10-07T10:12:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "3936e410-e778-428b-946c-7fed07c9b6cf"}
2022-10-07T10:12:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "8afa054d-3688-47fd-b62d-b81884fbdb11"}
2022-10-07T10:12:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "3edee7cb-36fa-476c-a96a-360603dcfa4c"}
2022-10-07T10:13:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "7247133e-4c75-439a-a2cf-f507aa55f46f"}
2022-10-07T10:13:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "cfe510bf-bd36-497c-98e0-51023e2665b2"}
2022-10-07T10:13:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "ef106647-97b0-4d19-9c03-bc9e16c535c7"}
2022-10-07T10:13:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "9f49f60b-fee1-4cf1-9f0e-bbdb49839008"}
2022-10-07T10:14:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "feb6af60-bcf2-4f86-a73e-04bd602d1783"}
2022-10-07T10:14:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "ca389750-1bd1-4f0d-82ca-a276289761d1"}
2022-10-07T10:14:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "6bb40aa9-d9b9-4866-8a32-12e3491e8d24"}
2022-10-07T10:14:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "aee3608e-a3b9-4a7a-8e62-59eb4455f298"}
2022-10-07T10:15:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "b8cdc4a7-74f8-46a0-8831-b9188b411ed0"}
2022-10-07T10:15:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "bfdb1205-1acf-44e1-aac7-0f3d703c719a"}
2022-10-07T10:15:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "a74dc222-1c92-4805-9d66-fa3d76dcfb9b"}
2022-10-07T10:15:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "b28353f9-743d-4efe-b231-567de860e4af"}
2022-10-07T10:16:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "7ab4143c-905f-4388-b59e-0e00341fa0d8"}
2022-10-07T10:16:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "631c8bb5-3225-4e56-84c5-aea2c9bcb77f"}
2022-10-07T10:16:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "134777c8-81ad-4990-a412-cbf0a6aa8d37"}
2022-10-07T10:16:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "1f6344d5-03fd-4177-9592-b556b4160192"}
2022-10-07T10:17:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "3cfb8149-6ead-4c23-ac8d-d9b194b8fd3a"}
2022-10-07T10:17:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "8c709442-711c-4d71-8798-641403fec586"}
2022-10-07T10:17:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "5f58b4ef-6d66-48ad-9f0a-112e8ba27ead"}
2022-10-07T10:17:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "8643a3a5-8e9c-4a0b-89da-80445bac3897"}
2022-10-07T10:18:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "cca2e6f6-183c-475a-a743-1e2a0f33ba43"}
2022-10-07T10:18:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "aee537ac-c2b2-4887-8dbc-940910dc55a8"}
2022-10-07T10:18:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "b67a9a89-356e-43c8-9e3d-a16417fb6f3d"}
2022-10-07T10:18:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "457c692b-b5e1-43c9-a873-5c7d5d5aa497"}
2022-10-07T10:19:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "60714674-ffa7-4751-ba6b-3ab0e1f3b924"}
2022-10-07T10:19:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "0e4f8b70-a504-4dad-ae18-d67417aaf4e4"}
2022-10-07T10:19:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "bf9ac213-ec73-4c9c-81f1-678db111cc0f"}
2022-10-07T10:19:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "a9692b8e-b48c-4392-8020-d6cfdefa1c5e"}
2022-10-07T10:20:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "85b79fe7-2219-41c3-8b06-e192fdf6fbf6"}
2022-10-07T10:20:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "808632d9-d48a-47c8-962b-feded2a85a20"}
2022-10-07T10:20:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "015acea4-74c5-4aae-925e-205e5c5bfeb2"}
2022-10-07T10:20:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "8f3ea1b2-bc67-490d-9f76-4b9645d32e61"}
2022-10-07T10:21:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "b18b0b7c-f44b-4411-9b2e-b957e33f45b1"}
2022-10-07T10:21:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "37eb06cc-f837-42ac-9c24-a9afb4564829"}
2022-10-07T10:21:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "afd411ed-d648-460f-aa94-f255f88d3354"}
2022-10-07T10:21:51Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "fd3513ab-e82f-43d8-af4e-6ac54af36003"}
2022-10-07T10:22:06Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "fe03765d-70c5-42bf-9bcd-dfb7259b0dc4"}
2022-10-07T10:22:21Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "415a3bc6-f41c-40d7-b8cf-f52ab79a317d"}
2022-10-07T10:22:36Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "27135f87-f5a3-441d-9db1-ef8594579707"}
2022-10-07T10:22:52Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "84bd9820-ce17-4e27-8e70-c9cd742ffa59"}
2022-10-07T10:23:07Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "514c1b29-a385-4bca-9d40-554011899fd5"}
2022-10-07T10:23:22Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "4f59a75d-5e0e-435d-8a47-fc9c4576947b"}
2022-10-07T10:23:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "9680a86a-e301-419d-b9f7-c73b05543f2d"}
2022-10-07T10:23:52Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "d30d7e5d-a284-4f69-b44c-407c00c39563"}
2022-10-07T10:24:07Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "2aa7d636-3a2f-4d9b-8604-a159cb202041"}
2022-10-07T10:24:22Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "b6cadcd3-d92b-4442-85f1-046f6bc4ee74"}
2022-10-07T10:24:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "791b3f63-f4ac-423e-b114-c046810f73b9"}
2022-10-07T10:24:52Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "ebea280c-9db5-49a1-8e8e-16484e07afca"}
2022-10-07T10:25:07Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "4460206c-aeec-420e-b26b-2c82cf290901"}
2022-10-07T10:25:22Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "8bea2a73-a223-4419-89d5-71038745325f"}
2022-10-07T10:25:37Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "f4bb8828-f842-495e-9b48-ed53984fae13"}
2022-10-07T10:25:52Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "aac574b6-baa1-4fcc-b8c8-ad22515daf19"}
2022-10-07T10:26:07Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "5c9ac446-e772-485d-afeb-2b01382d843b"}
2022-10-07T10:26:23Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "91bc2829-86e4-4902-8880-080f866cc6cf"}
2022-10-07T10:26:38Z	INFO	Reconciling ScaledObject	{"controller": "scaledobject", "controllerGroup": "keda.sh", "controllerKind": "ScaledObject", "scaledObject": {"name":"bservice","namespace":"istio-ryanzhou"}, "namespace": "istio-ryanzhou", "name": "bservice", "reconcileID": "55135801-7fe6-45d5-b03c-2a783ea23640"}

press test prometheus data below.

zego@zegodeMacBook-Pro-38 .kube % kubectl -n test-infra exec -it deploy/fortio -c fortio -- fortio load -c 300 -qps 300 -t 30s -payload '{"datar":"eXcioSmtd1RCk0tlLBAhVAzZeIY96I3CbB5ERaFTT3lGO0iU55LkhXfYXUhQ7d8Z83N2PWN1ZOwAYDh0qc2HxsFnZ1spDDYl24v9wEUosZOrkYCFNfiXuLw6qORwkdSNxpKsjTndVkiFDXdxtRVT9Rl2i2O95ZZWwM6O3XRxiItWpmDQthvBzQi8uH6vrecr4BvTKCvbDs4WlPHiGrSYRmvLx9lejKLWyCQtNQIyDMuln6fQN1KANSvEZW8sQlupmB3UV9POwY5Vkl5nfRvf9FhZU21mHxJfNEkLMEI7z5PCvCLijxIhB9tQ6IqKFPrY20LEfKOglz1IOQ6aJVmfLdlEgu6nKKOLefnerWxuH1BAHHIHljUUh2AXZvoclNmaNuXHY4qu2JbxApg9RFipE76MLN2gR37MkK0UO97BzZSo6zzKHFyHJSr8DJzNu1UxhwbkXnMPPDEgvui3EmivcYaeF6p7ueochY8LC0Ic0eqncWadgU1Zfvuc90JC3P4iaZ5iabQyidoZoo0NOx7mnsY0Bi29pxxTErFqfgMBdRY2klQQheMVYGwuk6zlypRXhMOCSqfKqqwFh0cVD4HnNLn3xulGEXgJP7WxumdXkBivy328p1cNNBmK2UdpZnUTCZ3NvYs70zEdKeBbJTHIcs8MQ1bkSzqqQBb4Pqu4xtDvhlCwoZ8YO3eQylXZ9cUcaSDWsTYaWOgzwGDm6keZOu4Wdz1tDJshSlJ1YgJqb2MQr4orX7EiYkQKZqXed7DxQrbLViAvNnSWa8C15fG0Wo8ni7NnaHwJhdsjEKS9KuE0Nao1KVHyQEuHf8cIePKbLMENnS9eGIF0f6WiHXJCuNkBAU3IrSWr1rPoJlOD3qoSebiGdCSPV8MJEHwdsTlWsmYtAdyVqlLNWnhOyiklOBQpHkXZze8ni2hGbK71o2xECN8xsODIttZHDIIHlzTGmtJUuxVoZvqRKtuSxPt4m4mMDH8PgR9wNDG"}' "http://prometheus-operated.monitoring:9090/api/v1/query?query=max%28rate%28container_cpu_usage_seconds_total%7Bnamespace%3D%22test-infra%22%2Ccontainer%3D%22bservice40%22%7D%5B2m%5D%29%29&time=2022-10-08T09:39:38Z"
Fortio 1.35.0 running at 300 queries per second, 8->8 procs, for 30s: http://prometheus-operated.monitoring:9090/api/v1/query?query=max%28rate%28container_cpu_usage_seconds_total%7Bnamespace%3D%22test-infra%22%2Ccontainer%3D%22bservice40%22%7D%5B2m%5D%29%29&time=2022-10-08T09:39:38Z
11:00:44 I httprunner.go:100> Starting http test for http://prometheus-operated.monitoring:9090/api/v1/query?query=max%28rate%28container_cpu_usage_seconds_total%7Bnamespace%3D%22test-infra%22%2Ccontainer%3D%22bservice40%22%7D%5B2m%5D%29%29&time=2022-10-08T09:39:38Z with 300 threads at 300.0 qps and parallel warmup
Starting at 300 qps with 300 thread(s) [gomax 8] for 30s : 30 calls each (total 9000)
11:01:15 I periodic.go:806> T008 ended after 30.011886178s : 30 calls. qps=0.9996039509836369
11:01:15 I periodic.go:806> T076 ended after 30.015582593s : 30 calls. qps=0.9994808498901622
11:01:15 I periodic.go:806> T164 ended after 30.015652423s : 30 calls. qps=0.9994785246450947
11:01:15 I periodic.go:806> T142 ended after 30.017232873s : 30 calls. qps=0.999425900679356
11:01:15 I periodic.go:806> T230 ended after 30.01738753s : 30 calls. qps=0.999420751390086
11:01:15 I periodic.go:806> T233 ended after 30.018203103s : 30 calls. qps=0.9993935978466951
11:01:15 I periodic.go:806> T084 ended after 30.018303924s : 30 calls. qps=0.9993902412326046
11:01:15 I periodic.go:806> T269 ended after 30.018378067s : 30 calls. qps=0.9993877728184054
11:01:15 I periodic.go:806> T234 ended after 30.01839685s : 30 calls. qps=0.999387147485193
11:01:15 I periodic.go:806> T066 ended after 30.019069263s : 30 calls. qps=0.9993647616842171
11:01:15 I periodic.go:806> T238 ended after 30.019117429s : 30 calls. qps=0.9993631581926012
11:01:15 I periodic.go:806> T096 ended after 30.019211322s : 30 calls. qps=0.9993600324207744
11:01:15 I periodic.go:806> T224 ended after 30.019371814s : 30 calls. qps=0.9993546895611265
11:01:15 I periodic.go:806> T194 ended after 30.019894516s : 30 calls. qps=0.999337288943857
11:01:15 I periodic.go:806> T190 ended after 30.01997894s : 30 calls. qps=0.9993344785471058
11:01:15 I periodic.go:806> T176 ended after 30.019995705s : 30 calls. qps=0.9993339204576679
11:01:15 I periodic.go:806> T151 ended after 30.020100809s : 30 calls. qps=0.9993304216688715
11:01:15 I periodic.go:806> T138 ended after 30.020119737s : 30 calls. qps=0.9993297915805711
11:01:15 I periodic.go:806> T209 ended after 30.020617678s : 30 calls. qps=0.9993132160630023
11:01:15 I periodic.go:806> T143 ended after 30.020749627s : 30 calls. qps=0.9993088238215965
11:01:15 I periodic.go:806> T225 ended after 30.022146459s : 30 calls. qps=0.9992623292598268
11:01:15 I periodic.go:806> T265 ended after 30.022490416s : 30 calls. qps=0.9992508810665482
11:01:15 I periodic.go:806> T064 ended after 30.022538214s : 30 calls. qps=0.9992492901886126
11:01:15 I periodic.go:806> T121 ended after 30.02256169s : 30 calls. qps=0.9992485088303602
11:01:15 I periodic.go:806> T094 ended after 30.022578516s : 30 calls. qps=0.9992479488066635
11:01:15 I periodic.go:806> T072 ended after 30.022597116s : 30 calls. qps=0.9992473297392397
11:01:15 I periodic.go:806> T289 ended after 30.022607499s : 30 calls. qps=0.9992469841601616
11:01:15 I periodic.go:806> T093 ended after 30.022843183s : 30 calls. qps=0.9992391399155383
11:01:15 I periodic.go:806> T199 ended after 30.023163467s : 30 calls. qps=0.9992284801358304
11:01:15 I periodic.go:806> T221 ended after 30.023320171s : 30 calls. qps=0.9992232647532925
11:01:15 I periodic.go:806> T279 ended after 30.023346743s : 30 calls. qps=0.9992223803961681
11:01:15 I periodic.go:806> T155 ended after 30.023355425s : 30 calls. qps=0.9992220914461629
11:01:15 I periodic.go:806> T077 ended after 30.023485078s : 30 calls. qps=0.9992177764193935
11:01:15 I periodic.go:806> T014 ended after 30.023743071s : 30 calls. qps=0.9992091901751273
11:01:15 I periodic.go:806> T293 ended after 30.023917116s : 30 calls. qps=0.999203397880843
11:01:15 I periodic.go:806> T216 ended after 30.024837722s : 30 calls. qps=0.9991727608245555
11:01:15 I periodic.go:806> T172 ended after 30.025357113s : 30 calls. qps=0.9991554767224061
11:01:15 I periodic.go:806> T150 ended after 30.025386504s : 30 calls. qps=0.9991544986774236
11:01:15 I periodic.go:806> T053 ended after 30.025568324s : 30 calls. qps=0.9991484482916659
11:01:15 I periodic.go:806> T272 ended after 30.025980007s : 30 calls. qps=0.9991347490741703
11:01:15 I periodic.go:806> T052 ended after 30.026166684s : 30 calls. qps=0.9991285373096279
11:01:15 I periodic.go:806> T244 ended after 30.02650793s : 30 calls. qps=0.9991171823889146
11:01:15 I periodic.go:806> T299 ended after 30.026708845s : 30 calls. qps=0.9991104970865147
11:01:15 I periodic.go:806> T087 ended after 30.027303153s : 30 calls. qps=0.9990907224381465
11:01:15 I periodic.go:806> T267 ended after 30.027906684s : 30 calls. qps=0.9990706417102704
11:01:15 I periodic.go:806> T137 ended after 30.028516303s : 30 calls. qps=0.9990503592414537
11:01:15 I periodic.go:806> T055 ended after 30.028553296s : 30 calls. qps=0.999049128483862
11:01:15 I periodic.go:806> T103 ended after 30.028556164s : 30 calls. qps=0.9990490330655912
11:01:15 I periodic.go:806> T100 ended after 30.028561123s : 30 calls. qps=0.9990488680798587
11:01:15 I periodic.go:806> T231 ended after 30.028568803s : 30 calls. qps=0.999048612566672
11:01:15 I periodic.go:806> T101 ended after 30.030424953s : 30 calls. qps=0.9989868623888067
11:01:15 I periodic.go:806> T003 ended after 30.030507166s : 30 calls. qps=0.9989841275130199
11:01:15 I periodic.go:806> T037 ended after 30.030696875s : 30 calls. qps=0.9989778167610371
11:01:15 I periodic.go:806> T271 ended after 30.031049701s : 30 calls. qps=0.9989660800634962
11:01:15 I periodic.go:806> T105 ended after 30.031203259s : 30 calls. qps=0.9989609720685884
11:01:15 I periodic.go:806> T158 ended after 30.031221414s : 30 calls. qps=0.9989603681592036
11:01:15 I periodic.go:806> T005 ended after 30.032423463s : 30 calls. qps=0.9989203847288599
11:01:15 I periodic.go:806> T258 ended after 30.033077503s : 30 calls. qps=0.9988986309179705
11:01:15 I periodic.go:806> T070 ended after 30.03326899s : 30 calls. qps=0.998892262110692
11:01:15 I periodic.go:806> T246 ended after 30.033804082s : 30 calls. qps=0.998874465521993
11:01:15 I periodic.go:806> T028 ended after 30.033914531s : 30 calls. qps=0.9988707921851148
11:01:15 I periodic.go:806> T104 ended after 30.03392987s : 30 calls. qps=0.9988702820394513
11:01:15 I periodic.go:806> T062 ended after 30.033941493s : 30 calls. qps=0.9988698954811538
11:01:15 I periodic.go:806> T275 ended after 30.033959599s : 30 calls. qps=0.9988692933115243
11:01:15 I periodic.go:806> T223 ended after 30.033974022s : 30 calls. qps=0.9988688136316854
11:01:15 I periodic.go:806> T108 ended after 30.034398446s : 30 calls. qps=0.9988546983532283
11:01:15 I periodic.go:806> T148 ended after 30.03441977s : 30 calls. qps=0.9988539891809604
11:01:15 I periodic.go:806> T213 ended after 30.034429091s : 30 calls. qps=0.9988536791927796
11:01:15 I periodic.go:806> T135 ended after 30.034441304s : 30 calls. qps=0.9988532730257441
11:01:15 I periodic.go:806> T001 ended after 30.034438958s : 30 calls. qps=0.9988533510465051
11:01:15 I periodic.go:806> T073 ended after 30.034471424s : 30 calls. qps=0.9988522713280563
11:01:15 I periodic.go:806> T207 ended after 30.034455427s : 30 calls. qps=0.9988528033383609
11:01:15 I periodic.go:806> T002 ended after 30.03448592s : 30 calls. qps=0.9988517892368174
11:01:15 I periodic.go:806> T263 ended after 30.034490708s : 30 calls. qps=0.9988516300031413
11:01:15 I periodic.go:806> T168 ended after 30.034513205s : 30 calls. qps=0.9988508818250381
11:01:15 I periodic.go:806> T097 ended after 30.034535178s : 30 calls. qps=0.9988501510745771
11:01:15 I periodic.go:806> T297 ended after 30.034542222s : 30 calls. qps=0.9988499168142907
11:01:15 I periodic.go:806> T128 ended after 30.034558785s : 30 calls. qps=0.9988493659837859
11:01:15 I periodic.go:806> T210 ended after 30.034587562s : 30 calls. qps=0.9988484089575527
11:01:15 I periodic.go:806> T227 ended after 30.03461731s : 30 calls. qps=0.9988474196410528
11:01:15 I periodic.go:806> T110 ended after 30.034624131s : 30 calls. qps=0.9988471927982523
11:01:15 I periodic.go:806> T024 ended after 30.034636731s : 30 calls. qps=0.9988467737662281
11:01:15 I periodic.go:806> T140 ended after 30.034640765s : 30 calls. qps=0.9988466396095416
11:01:15 I periodic.go:806> T222 ended after 30.034656296s : 30 calls. qps=0.9988461231033092
11:01:15 I periodic.go:806> T082 ended after 30.034660058s : 30 calls. qps=0.9988459979925504
11:01:15 I periodic.go:806> T117 ended after 30.034671734s : 30 calls. qps=0.9988456096904582
11:01:15 I periodic.go:806> T033 ended after 30.034687203s : 30 calls. qps=0.9988450952471869
11:01:15 I periodic.go:806> T115 ended after 30.034703709s : 30 calls. qps=0.9988445463176119
11:01:15 I periodic.go:806> T249 ended after 30.03473202s : 30 calls. qps=0.9988436047980428
11:01:15 I periodic.go:806> T248 ended after 30.034740418s : 30 calls. qps=0.9988433255118403
11:01:15 I periodic.go:806> T212 ended after 30.034751735s : 30 calls. qps=0.9988429491508164
11:01:15 I periodic.go:806> T235 ended after 30.034760278s : 30 calls. qps=0.9988426650428284
11:01:15 I periodic.go:806> T149 ended after 30.034767677s : 30 calls. qps=0.9988424189801
11:01:15 I periodic.go:806> T274 ended after 30.034754554s : 30 calls. qps=0.9988428554014812
11:01:15 I periodic.go:806> T044 ended after 30.03478078s : 30 calls. qps=0.9988419832242239
11:01:15 I periodic.go:806> T253 ended after 30.034800553s : 30 calls. qps=0.9988413256502706
11:01:15 I periodic.go:806> T197 ended after 30.034803707s : 30 calls. qps=0.9988412207604378
11:01:15 I periodic.go:806> T180 ended after 30.034818938s : 30 calls. qps=0.9988407142366372
11:01:15 I periodic.go:806> T171 ended after 30.034843769s : 30 calls. qps=0.9988398884552894
11:01:15 I periodic.go:806> T032 ended after 30.034862066s : 30 calls. qps=0.9988392799699433
11:01:15 I periodic.go:806> T063 ended after 30.03488322s : 30 calls. qps=0.99883857647308
11:01:15 I periodic.go:806> T074 ended after 30.034888606s : 30 calls. qps=0.9988383973565652
11:01:15 I periodic.go:806> T201 ended after 30.034897843s : 30 calls. qps=0.9988380901715591
11:01:15 I periodic.go:806> T027 ended after 30.034905307s : 30 calls. qps=0.9988378419494512
11:01:15 I periodic.go:806> T296 ended after 30.034913708s : 30 calls. qps=0.9988375625667038
11:01:15 I periodic.go:806> T065 ended after 30.034926735s : 30 calls. qps=0.9988371293425098
11:01:15 I periodic.go:806> T061 ended after 30.034945115s : 30 calls. qps=0.9988365181002928
11:01:15 I periodic.go:806> T026 ended after 30.034959402s : 30 calls. qps=0.9988360429747186
11:01:15 I periodic.go:806> T229 ended after 30.034974342s : 30 calls. qps=0.9988355461335922
11:01:15 I periodic.go:806> T292 ended after 30.034986013s : 30 calls. qps=0.9988351580059049
11:01:15 I periodic.go:806> T215 ended after 30.035002738s : 30 calls. qps=0.9988346018042571
11:01:15 I periodic.go:806> T040 ended after 30.035018462s : 30 calls. qps=0.9988340788921337
11:01:15 I periodic.go:806> T131 ended after 30.035040876s : 30 calls. qps=0.998833333500538
11:01:15 I periodic.go:806> T266 ended after 30.035064089s : 30 calls. qps=0.9988325615388701
11:01:15 I periodic.go:806> T277 ended after 30.035068963s : 30 calls. qps=0.9988323994513479
11:01:15 I periodic.go:806> T206 ended after 30.035083795s : 30 calls. qps=0.998831906205441
11:01:15 I periodic.go:806> T255 ended after 30.035084568s : 30 calls. qps=0.9988318804989357
11:01:15 I periodic.go:806> T257 ended after 30.035097693s : 30 calls. qps=0.9988314440206338
11:01:15 I periodic.go:806> T086 ended after 30.035098023s : 30 calls. qps=0.9988314330463273
11:01:15 I periodic.go:806> T185 ended after 30.035117143s : 30 calls. qps=0.9988307972020617
11:01:15 I periodic.go:806> T141 ended after 30.035134456s : 30 calls. qps=0.9988302214510985
11:01:15 I periodic.go:806> T184 ended after 30.035146063s : 30 calls. qps=0.998829835455893
11:01:15 I periodic.go:806> T287 ended after 30.035156772s : 30 calls. qps=0.9988294793242839
11:01:15 I periodic.go:806> T291 ended after 30.035167886s : 30 calls. qps=0.9988291097245242
11:01:15 I periodic.go:806> T189 ended after 30.0351821s : 30 calls. qps=0.998828637033634
11:01:15 I periodic.go:806> T089 ended after 30.03519208s : 30 calls. qps=0.9988283051459679
11:01:15 I periodic.go:806> T282 ended after 30.03551724s : 30 calls. qps=0.9988174919807041
11:01:15 I periodic.go:806> T182 ended after 30.035542331s : 30 calls. qps=0.9988166575915856
11:01:15 I periodic.go:806> T187 ended after 30.035553501s : 30 calls. qps=0.9988162861390647
11:01:15 I periodic.go:806> T195 ended after 30.035568071s : 30 calls. qps=0.9988158016217332
11:01:15 I periodic.go:806> T200 ended after 30.035564411s : 30 calls. qps=0.9988159233329748
11:01:15 I periodic.go:806> T219 ended after 30.035581611s : 30 calls. qps=0.9988153513569062
11:01:15 I periodic.go:806> T157 ended after 30.03561123s : 30 calls. qps=0.9988143663956993
11:01:15 I periodic.go:806> T018 ended after 30.035643271s : 30 calls. qps=0.9988133008945936
11:01:15 I periodic.go:806> T134 ended after 30.035638422s : 30 calls. qps=0.9988134621445603
11:01:15 I periodic.go:806> T007 ended after 30.035659522s : 30 calls. qps=0.9988127604797931
11:01:15 I periodic.go:806> T276 ended after 30.035659429s : 30 calls. qps=0.9988127635724365
11:01:15 I periodic.go:806> T031 ended after 30.035670795s : 30 calls. qps=0.9988123856049874
11:01:15 I periodic.go:806> T092 ended after 30.035728205s : 30 calls. qps=0.9988104764846669
11:01:15 I periodic.go:806> T013 ended after 30.035743352s : 30 calls. qps=0.9988099727853873
11:01:15 I periodic.go:806> T051 ended after 30.035754017s : 30 calls. qps=0.9988096181311192
11:01:15 I periodic.go:806> T245 ended after 30.035764623s : 30 calls. qps=0.9988092654390889
11:01:15 I periodic.go:806> T204 ended after 30.035774697s : 30 calls. qps=0.9988089304384223
11:01:15 I periodic.go:806> T214 ended after 30.035793754s : 30 calls. qps=0.9988082967178041
11:01:15 I periodic.go:806> T083 ended after 30.035814863s : 30 calls. qps=0.9988075947610092
11:01:15 I periodic.go:806> T162 ended after 30.03582563s : 30 calls. qps=0.9988072367165356
11:01:15 I periodic.go:806> T095 ended after 30.03582137s : 30 calls. qps=0.998807378378013
11:01:15 I periodic.go:806> T256 ended after 30.03583591s : 30 calls. qps=0.998806894866939
11:01:15 I periodic.go:806> T181 ended after 30.035842429s : 30 calls. qps=0.9988066780852002
11:01:15 I periodic.go:806> T127 ended after 30.035861081s : 30 calls. qps=0.9988060578352227
11:01:15 I periodic.go:806> T211 ended after 30.035880816s : 30 calls. qps=0.9988054015722128
11:01:15 I periodic.go:806> T262 ended after 30.035890307s : 30 calls. qps=0.9988050859610565
11:01:15 I periodic.go:806> T046 ended after 30.035888204s : 30 calls. qps=0.9988051558936346
11:01:15 I periodic.go:806> T123 ended after 30.035912358s : 30 calls. qps=0.9988043526838153
11:01:15 I periodic.go:806> T050 ended after 30.035925899s : 30 calls. qps=0.9988039023960572
11:01:15 I periodic.go:806> T192 ended after 30.03593742s : 30 calls. qps=0.998803519281004
11:01:15 I periodic.go:806> T243 ended after 30.035947243s : 30 calls. qps=0.9988031926308442
11:01:15 I periodic.go:806> T159 ended after 30.035956422s : 30 calls. qps=0.9988028873961987
11:01:15 I periodic.go:806> T281 ended after 30.03596775s : 30 calls. qps=0.9988025106998591
11:01:15 I periodic.go:806> T251 ended after 30.035978284s : 30 calls. qps=0.998802160407102
11:01:15 I periodic.go:806> T054 ended after 30.036002469s : 30 calls. qps=0.9988013561712429
11:01:15 I periodic.go:806> T022 ended after 30.036022097s : 30 calls. qps=0.9988007034725281
11:01:15 I periodic.go:806> T290 ended after 30.036041178s : 30 calls. qps=0.9988000689642682
11:01:15 I periodic.go:806> T196 ended after 30.036060045s : 30 calls. qps=0.9987994415730301
11:01:15 I periodic.go:806> T156 ended after 30.03607247s : 30 calls. qps=0.9987990284003999
11:01:15 I periodic.go:806> T165 ended after 30.036078674s : 30 calls. qps=0.9987988220968661
11:01:15 I periodic.go:806> T136 ended after 30.036091951s : 30 calls. qps=0.9987983805929587
11:01:15 I periodic.go:806> T111 ended after 30.03610795s : 30 calls. qps=0.9987978485741192
11:01:15 I periodic.go:806> T160 ended after 30.036110821s : 30 calls. qps=0.9987977531040818
11:01:15 I periodic.go:806> T173 ended after 30.036119067s : 30 calls. qps=0.9987974788980083
11:01:15 I periodic.go:806> T049 ended after 30.036719579s : 30 calls. qps=0.9987775103435172
11:01:15 I periodic.go:806> T116 ended after 30.037201358s : 30 calls. qps=0.9987614905411255
11:01:15 I periodic.go:806> T017 ended after 30.037232422s : 30 calls. qps=0.9987604576388093
11:01:15 I periodic.go:806> T118 ended after 30.037237471s : 30 calls. qps=0.9987602897558089
11:01:15 I periodic.go:806> T120 ended after 30.037252585s : 30 calls. qps=0.9987597872044195
11:01:15 I periodic.go:806> T242 ended after 30.037246975s : 30 calls. qps=0.9987599737409024
11:01:15 I periodic.go:806> T069 ended after 30.037274005s : 30 calls. qps=0.9987590749748531
11:01:15 I periodic.go:806> T019 ended after 30.037288559s : 30 calls. qps=0.9987585910450353
11:01:15 I periodic.go:806> T119 ended after 30.037301786s : 30 calls. qps=0.998758151239224
11:01:15 I periodic.go:806> T247 ended after 30.037311448s : 30 calls. qps=0.9987578299720801
11:01:15 I periodic.go:806> T047 ended after 30.037322808s : 30 calls. qps=0.9987574522457089
11:01:15 I periodic.go:806> T030 ended after 30.037333931s : 30 calls. qps=0.9987570823999973
11:01:15 I periodic.go:806> T273 ended after 30.037344825s : 30 calls. qps=0.9987567201689239
11:01:15 I periodic.go:806> T080 ended after 30.037381639s : 30 calls. qps=0.9987554960865342
11:01:15 I periodic.go:806> T125 ended after 30.037428705s : 30 calls. qps=0.9987539311248113
11:01:15 I periodic.go:806> T035 ended after 30.037429526s : 30 calls. qps=0.9987539038263044
11:01:15 I periodic.go:806> T016 ended after 30.037432959s : 30 calls. qps=0.9987537896779963
11:01:15 I periodic.go:806> T071 ended after 30.037447293s : 30 calls. qps=0.9987533130683602
11:01:15 I periodic.go:806> T068 ended after 30.037452736s : 30 calls. qps=0.9987531320871589
11:01:15 I periodic.go:806> T020 ended after 30.037450689s : 30 calls. qps=0.998753200150447
11:01:15 I periodic.go:806> T015 ended after 30.037433076s : 30 calls. qps=0.9987537857877107
11:01:15 I periodic.go:806> T203 ended after 30.0374733s : 30 calls. qps=0.9987524483292675
11:01:15 I periodic.go:806> T166 ended after 30.037491886s : 30 calls. qps=0.9987518303411519
11:01:15 I periodic.go:806> T270 ended after 30.037506529s : 30 calls. qps=0.998751343459092
11:01:15 I periodic.go:806> T114 ended after 30.037517817s : 30 calls. qps=0.9987509681316354
11:01:15 I periodic.go:806> T023 ended after 30.037525817s : 30 calls. qps=0.998750702130774
11:01:15 I periodic.go:806> T126 ended after 30.037534063s : 30 calls. qps=0.9987504279505343
11:01:15 I periodic.go:806> T205 ended after 30.037547692s : 30 calls. qps=0.9987499747853916
11:01:15 I periodic.go:806> T060 ended after 30.037571222s : 30 calls. qps=0.9987491924123185
11:01:15 I periodic.go:806> T091 ended after 30.03758583s : 30 calls. qps=0.9987487066965793
11:01:15 I periodic.go:806> T081 ended after 30.03761056s : 30 calls. qps=0.9987478844255979
11:01:15 I periodic.go:806> T250 ended after 30.037618731s : 30 calls. qps=0.9987476127406473
11:01:15 I periodic.go:806> T217 ended after 30.037627929s : 30 calls. qps=0.9987473069082239
11:01:15 I periodic.go:806> T208 ended after 30.037634484s : 30 calls. qps=0.9987470889553554
11:01:15 I periodic.go:806> T186 ended after 30.037644806s : 30 calls. qps=0.9987467457504364
11:01:15 I periodic.go:806> T288 ended after 30.037662138s : 30 calls. qps=0.9987461694646217
11:01:15 I periodic.go:806> T057 ended after 30.037674085s : 30 calls. qps=0.9987457722294546
11:01:15 I periodic.go:806> T283 ended after 30.037683983s : 30 calls. qps=0.9987454431233337
11:01:15 I periodic.go:806> T112 ended after 30.037694415s : 30 calls. qps=0.9987450962620761
11:01:15 I periodic.go:806> T000 ended after 30.037704935s : 30 calls. qps=0.9987447464750855
11:01:15 I periodic.go:806> T154 ended after 30.037718967s : 30 calls. qps=0.998744279915481
11:01:15 I periodic.go:806> T038 ended after 30.037731965s : 30 calls. qps=0.9987438477364414
11:01:15 I periodic.go:806> T177 ended after 30.037742542s : 30 calls. qps=0.9987434960550972
11:01:15 I periodic.go:806> T240 ended after 30.037752619s : 30 calls. qps=0.9987431609987986
11:01:15 I periodic.go:806> T239 ended after 30.037762047s : 30 calls. qps=0.9987428475216991
11:01:15 I periodic.go:806> T130 ended after 30.037783446s : 30 calls. qps=0.9987421360145324
11:01:15 I periodic.go:806> T241 ended after 30.03779613s : 30 calls. qps=0.9987417142776912
11:01:15 I periodic.go:806> T188 ended after 30.037806066s : 30 calls. qps=0.9987413839107645
11:01:15 I periodic.go:806> T011 ended after 30.037819516s : 30 calls. qps=0.9987409367054805
11:01:15 I periodic.go:806> T106 ended after 30.03782968s : 30 calls. qps=0.9987405987581989
11:01:15 I periodic.go:806> T029 ended after 30.037852414s : 30 calls. qps=0.9987398428663177
11:01:15 I periodic.go:806> T098 ended after 30.037856945s : 30 calls. qps=0.9987396922134186
11:01:15 I periodic.go:806> T056 ended after 30.037866467s : 30 calls. qps=0.9987393756130583
11:01:15 I periodic.go:806> T088 ended after 30.03787302s : 30 calls. qps=0.9987391577301501
11:01:15 I periodic.go:806> T294 ended after 30.037895895s : 30 calls. qps=0.9987383971523016
11:01:15 I periodic.go:806> T025 ended after 30.03791947s : 30 calls. qps=0.9987376133011518
11:01:15 I periodic.go:806> T147 ended after 30.03792352s : 30 calls. qps=0.9987374786417993
11:01:15 I periodic.go:806> T163 ended after 30.037932037s : 30 calls. qps=0.9987371954582867
11:01:15 I periodic.go:806> T145 ended after 30.037934468s : 30 calls. qps=0.9987371146294892
11:01:15 I periodic.go:806> T041 ended after 30.03794291s : 30 calls. qps=0.9987368339398711
11:01:15 I periodic.go:806> T254 ended after 30.037968981s : 30 calls. qps=0.9987359671013705
11:01:15 I periodic.go:806> T059 ended after 30.037988721s : 30 calls. qps=0.9987353107642176
11:01:15 I periodic.go:806> T198 ended after 30.038000976s : 30 calls. qps=0.9987349032969817
11:01:15 I periodic.go:806> T259 ended after 30.038008046s : 30 calls. qps=0.9987346682262753
11:01:15 I periodic.go:806> T132 ended after 30.038015397s : 30 calls. qps=0.9987344238127065
11:01:15 I periodic.go:806> T004 ended after 30.038014017s : 30 calls. qps=0.9987344696963493
11:01:15 I periodic.go:806> T286 ended after 30.038025844s : 30 calls. qps=0.9987340764603678
11:01:15 I periodic.go:806> T039 ended after 30.038056984s : 30 calls. qps=0.9987330410878349
11:01:15 I periodic.go:806> T153 ended after 30.038071474s : 30 calls. qps=0.9987325593111744
11:01:15 I periodic.go:806> T226 ended after 30.038087802s : 30 calls. qps=0.9987320164235799
11:01:15 I periodic.go:806> T175 ended after 30.038098108s : 30 calls. qps=0.9987316737610011
11:01:15 I periodic.go:806> T218 ended after 30.038117277s : 30 calls. qps=0.9987310364145496
11:01:15 I periodic.go:806> T191 ended after 30.038129283s : 30 calls. qps=0.9987306372297432
11:01:15 I periodic.go:806> T228 ended after 30.038128859s : 30 calls. qps=0.9987306513272188
11:01:15 I periodic.go:806> T036 ended after 30.03813864s : 30 calls. qps=0.9987303261211661
11:01:15 I periodic.go:806> T285 ended after 30.038146517s : 30 calls. qps=0.9987300642208928
11:01:15 I periodic.go:806> T042 ended after 30.038167559s : 30 calls. qps=0.9987293646017177
11:01:15 I periodic.go:806> T252 ended after 30.0381827s : 30 calls. qps=0.9987288611837359
11:01:15 I periodic.go:806> T010 ended after 30.038195521s : 30 calls. qps=0.9987284349030455
11:01:15 I periodic.go:806> T021 ended after 30.038207438s : 30 calls. qps=0.9987280386794432
11:01:15 I periodic.go:806> T048 ended after 30.038217722s : 30 calls. qps=0.9987276967510623
11:01:15 I periodic.go:806> T174 ended after 30.038235239s : 30 calls. qps=0.9987271143362525
11:01:15 I periodic.go:806> T122 ended after 30.03823929s : 30 calls. qps=0.9987269796464825
11:01:15 I periodic.go:806> T144 ended after 30.038248046s : 30 calls. qps=0.9987266885225321
11:01:15 I periodic.go:806> T058 ended after 30.038252848s : 30 calls. qps=0.9987265288632609
11:01:15 I periodic.go:806> T161 ended after 30.03827617s : 30 calls. qps=0.9987257534425951
11:01:15 I periodic.go:806> T012 ended after 30.038301088s : 30 calls. qps=0.9987249249587121
11:01:15 I periodic.go:806> T078 ended after 30.038301521s : 30 calls. qps=0.9987249105621626
11:01:15 I periodic.go:806> T220 ended after 30.038313336s : 30 calls. qps=0.9987245177326889
11:01:15 I periodic.go:806> T085 ended after 30.038318902s : 30 calls. qps=0.998724332672377
11:01:15 I periodic.go:806> T178 ended after 30.038333861s : 30 calls. qps=0.9987238353106604
11:01:15 I periodic.go:806> T260 ended after 30.038345442s : 30 calls. qps=0.998723450262131
11:01:15 I periodic.go:806> T124 ended after 30.0385871s : 30 calls. qps=0.9987154156128735
11:01:15 I periodic.go:806> T179 ended after 30.038605829s : 30 calls. qps=0.9987147929161636
11:01:15 I periodic.go:806> T045 ended after 30.038616227s : 30 calls. qps=0.9987144472066164
11:01:15 I periodic.go:806> T232 ended after 30.038627808s : 30 calls. qps=0.9987140621653259
11:01:15 I periodic.go:806> T152 ended after 30.038638647s : 30 calls. qps=0.9987137017940773
11:01:15 I periodic.go:806> T109 ended after 30.038647874s : 30 calls. qps=0.9987133950182409
11:01:15 I periodic.go:806> T009 ended after 30.038659531s : 30 calls. qps=0.9987130074509449
11:01:15 I periodic.go:806> T278 ended after 30.038675453s : 30 calls. qps=0.9987124780831128
11:01:15 I periodic.go:806> T079 ended after 30.038686189s : 30 calls. qps=0.9987121211375027
11:01:15 I periodic.go:806> T043 ended after 30.038695784s : 30 calls. qps=0.998711802127554
11:01:15 I periodic.go:806> T067 ended after 30.038706088s : 30 calls. qps=0.9987114595453409
11:01:15 I periodic.go:806> T146 ended after 30.038735207s : 30 calls. qps=0.9987104914127353
11:01:15 I periodic.go:806> T107 ended after 30.038742401s : 30 calls. qps=0.9987102522308421
11:01:15 I periodic.go:806> T237 ended after 30.038750307s : 30 calls. qps=0.9987099893769226
11:01:15 I periodic.go:806> T280 ended after 30.038757588s : 30 calls. qps=0.9987097473027485
11:01:15 I periodic.go:806> T139 ended after 30.038774175s : 30 calls. qps=0.9987091958288941
11:01:15 I periodic.go:806> T284 ended after 30.038778758s : 30 calls. qps=0.9987090434563798
11:01:15 I periodic.go:806> T236 ended after 30.038792975s : 30 calls. qps=0.9987085707793824
11:01:15 I periodic.go:806> T133 ended after 30.038807174s : 30 calls. qps=0.9987080987012831
11:01:15 I periodic.go:806> T075 ended after 30.038824771s : 30 calls. qps=0.9987075136495525
11:01:15 I periodic.go:806> T193 ended after 30.038839571s : 30 calls. qps=0.9987070215908908
11:01:15 I periodic.go:806> T170 ended after 30.038859216s : 30 calls. qps=0.9987063684502606
11:01:15 I periodic.go:806> T261 ended after 30.03886332s : 30 calls. qps=0.9987062320039878
11:01:15 I periodic.go:806> T167 ended after 30.038874746s : 30 calls. qps=0.9987058521223343
11:01:15 I periodic.go:806> T006 ended after 30.038876868s : 30 calls. qps=0.9987057815719663
11:01:15 I periodic.go:806> T295 ended after 30.038886613s : 30 calls. qps=0.9987054575790046
11:01:15 I periodic.go:806> T034 ended after 30.038895865s : 30 calls. qps=0.9987051499770563
11:01:15 I periodic.go:806> T090 ended after 30.038922251s : 30 calls. qps=0.9987042727207464
11:01:15 I periodic.go:806> T113 ended after 30.038940383s : 30 calls. qps=0.9987036698863706
11:01:15 I periodic.go:806> T169 ended after 30.038945506s : 30 calls. qps=0.998703499562186
11:01:15 I periodic.go:806> T298 ended after 30.038950237s : 30 calls. qps=0.9987033422708619
11:01:15 I periodic.go:806> T129 ended after 30.038959957s : 30 calls. qps=0.998703019110656
11:01:15 I periodic.go:806> T264 ended after 30.038979512s : 30 calls. qps=0.9987023689674801
11:01:15 I periodic.go:806> T202 ended after 30.038994606s : 30 calls. qps=0.9987018671393146
11:01:15 I periodic.go:806> T099 ended after 30.039005886s : 30 calls. qps=0.9987014921150177
11:01:15 I periodic.go:806> T102 ended after 30.039022765s : 30 calls. qps=0.9987009309422187
11:01:15 I periodic.go:806> T268 ended after 30.039046298s : 30 calls. qps=0.9987001485462407
11:01:15 I periodic.go:806> T183 ended after 30.039028278s : 30 calls. qps=0.9987007476527268
Ended after 30.03913575s : 9000 calls. qps=299.61
Sleep times : count 8700 avg 1.0002191 +/- 0.009193 min 0.979398755 max 1.023287054 sum 8701.90651
Aggregated Function Time : count 9000 avg 0.03293221 +/- 0.009036 min 0.01070619 max 0.054699654 sum 296.389894
# range, mid point, percentile, count
>= 0.0107062 <= 0.011 , 0.0108531 , 0.02, 2
> 0.011 <= 0.012 , 0.0115 , 0.54, 47
> 0.012 <= 0.014 , 0.013 , 3.23, 242
> 0.014 <= 0.016 , 0.015 , 6.60, 303
> 0.016 <= 0.018 , 0.017 , 10.02, 308
> 0.018 <= 0.02 , 0.019 , 12.91, 260
> 0.02 <= 0.025 , 0.0225 , 19.83, 623
> 0.025 <= 0.03 , 0.0275 , 26.21, 574
> 0.03 <= 0.035 , 0.0325 , 56.77, 2750
> 0.035 <= 0.04 , 0.0375 , 83.70, 2424
> 0.04 <= 0.045 , 0.0425 , 88.97, 474
> 0.045 <= 0.05 , 0.0475 , 99.14, 916
> 0.05 <= 0.0546997 , 0.0523498 , 100.00, 77
# target 50% 0.0338927
# target 75% 0.0383849
# target 90% 0.0455076
# target 99% 0.049929
# target 99.9% 0.0541503
Error cases : no data
# Socket and IP used for each connection:
[0]   1 socket used, resolved to [172.22.128.229:9090]
[1]   1 socket used, resolved to [172.22.128.229:9090]
[2]   1 socket used, resolved to [172.22.128.229:9090]
[3]   1 socket used, resolved to [172.22.128.229:9090]
[4]   1 socket used, resolved to [172.22.128.229:9090]
[5]   1 socket used, resolved to [172.22.128.229:9090]
[6]   1 socket used, resolved to [172.22.128.229:9090]
[7]   1 socket used, resolved to [172.22.128.229:9090]
[8]   1 socket used, resolved to [172.22.128.229:9090]
[9]   1 socket used, resolved to [172.22.128.229:9090]
[10]   1 socket used, resolved to [172.22.128.229:9090]
[11]   1 socket used, resolved to [172.22.128.229:9090]
[12]   1 socket used, resolved to [172.22.128.229:9090]
[13]   1 socket used, resolved to [172.22.128.229:9090]
[14]   1 socket used, resolved to [172.22.128.229:9090]
[15]   1 socket used, resolved to [172.22.128.229:9090]
[16]   1 socket used, resolved to [172.22.128.229:9090]
[17]   1 socket used, resolved to [172.22.128.229:9090]
[18]   1 socket used, resolved to [172.22.128.229:9090]
[19]   1 socket used, resolved to [172.22.128.229:9090]
[20]   1 socket used, resolved to [172.22.128.229:9090]
[21]   1 socket used, resolved to [172.22.128.229:9090]
[22]   1 socket used, resolved to [172.22.128.229:9090]
[23]   1 socket used, resolved to [172.22.128.229:9090]
[24]   1 socket used, resolved to [172.22.128.229:9090]
[25]   1 socket used, resolved to [172.22.128.229:9090]
[26]   1 socket used, resolved to [172.22.128.229:9090]
[27]   1 socket used, resolved to [172.22.128.229:9090]
[28]   1 socket used, resolved to [172.22.128.229:9090]
[29]   1 socket used, resolved to [172.22.128.229:9090]
[30]   1 socket used, resolved to [172.22.128.229:9090]
[31]   1 socket used, resolved to [172.22.128.229:9090]
[32]   1 socket used, resolved to [172.22.128.229:9090]
[33]   1 socket used, resolved to [172.22.128.229:9090]
[34]   1 socket used, resolved to [172.22.128.229:9090]
[35]   1 socket used, resolved to [172.22.128.229:9090]
[36]   1 socket used, resolved to [172.22.128.229:9090]
[37]   1 socket used, resolved to [172.22.128.229:9090]
[38]   1 socket used, resolved to [172.22.128.229:9090]
[39]   1 socket used, resolved to [172.22.128.229:9090]
[40]   1 socket used, resolved to [172.22.128.229:9090]
[41]   1 socket used, resolved to [172.22.128.229:9090]
[42]   1 socket used, resolved to [172.22.128.229:9090]
[43]   1 socket used, resolved to [172.22.128.229:9090]
[44]   1 socket used, resolved to [172.22.128.229:9090]
[45]   1 socket used, resolved to [172.22.128.229:9090]
[46]   1 socket used, resolved to [172.22.128.229:9090]
[47]   1 socket used, resolved to [172.22.128.229:9090]
[48]   1 socket used, resolved to [172.22.128.229:9090]
[49]   1 socket used, resolved to [172.22.128.229:9090]
[50]   1 socket used, resolved to [172.22.128.229:9090]
[51]   1 socket used, resolved to [172.22.128.229:9090]
[52]   1 socket used, resolved to [172.22.128.229:9090]
[53]   1 socket used, resolved to [172.22.128.229:9090]
[54]   1 socket used, resolved to [172.22.128.229:9090]
[55]   1 socket used, resolved to [172.22.128.229:9090]
[56]   1 socket used, resolved to [172.22.128.229:9090]
[57]   1 socket used, resolved to [172.22.128.229:9090]
[58]   1 socket used, resolved to [172.22.128.229:9090]
[59]   1 socket used, resolved to [172.22.128.229:9090]
[60]   1 socket used, resolved to [172.22.128.229:9090]
[61]   1 socket used, resolved to [172.22.128.229:9090]
[62]   1 socket used, resolved to [172.22.128.229:9090]
[63]   1 socket used, resolved to [172.22.128.229:9090]
[64]   1 socket used, resolved to [172.22.128.229:9090]
[65]   1 socket used, resolved to [172.22.128.229:9090]
[66]   1 socket used, resolved to [172.22.128.229:9090]
[67]   1 socket used, resolved to [172.22.128.229:9090]
[68]   1 socket used, resolved to [172.22.128.229:9090]
[69]   1 socket used, resolved to [172.22.128.229:9090]
[70]   1 socket used, resolved to [172.22.128.229:9090]
[71]   1 socket used, resolved to [172.22.128.229:9090]
[72]   1 socket used, resolved to [172.22.128.229:9090]
[73]   1 socket used, resolved to [172.22.128.229:9090]
[74]   1 socket used, resolved to [172.22.128.229:9090]
[75]   1 socket used, resolved to [172.22.128.229:9090]
[76]   1 socket used, resolved to [172.22.128.229:9090]
[77]   1 socket used, resolved to [172.22.128.229:9090]
[78]   1 socket used, resolved to [172.22.128.229:9090]
[79]   1 socket used, resolved to [172.22.128.229:9090]
[80]   1 socket used, resolved to [172.22.128.229:9090]
[81]   1 socket used, resolved to [172.22.128.229:9090]
[82]   1 socket used, resolved to [172.22.128.229:9090]
[83]   1 socket used, resolved to [172.22.128.229:9090]
[84]   1 socket used, resolved to [172.22.128.229:9090]
[85]   1 socket used, resolved to [172.22.128.229:9090]
[86]   1 socket used, resolved to [172.22.128.229:9090]
[87]   1 socket used, resolved to [172.22.128.229:9090]
[88]   1 socket used, resolved to [172.22.128.229:9090]
[89]   1 socket used, resolved to [172.22.128.229:9090]
[90]   1 socket used, resolved to [172.22.128.229:9090]
[91]   1 socket used, resolved to [172.22.128.229:9090]
[92]   1 socket used, resolved to [172.22.128.229:9090]
[93]   1 socket used, resolved to [172.22.128.229:9090]
[94]   1 socket used, resolved to [172.22.128.229:9090]
[95]   1 socket used, resolved to [172.22.128.229:9090]
[96]   1 socket used, resolved to [172.22.128.229:9090]
[97]   1 socket used, resolved to [172.22.128.229:9090]
[98]   1 socket used, resolved to [172.22.128.229:9090]
[99]   1 socket used, resolved to [172.22.128.229:9090]
[100]   1 socket used, resolved to [172.22.128.229:9090]
[101]   1 socket used, resolved to [172.22.128.229:9090]
[102]   1 socket used, resolved to [172.22.128.229:9090]
[103]   1 socket used, resolved to [172.22.128.229:9090]
[104]   1 socket used, resolved to [172.22.128.229:9090]
[105]   1 socket used, resolved to [172.22.128.229:9090]
[106]   1 socket used, resolved to [172.22.128.229:9090]
[107]   1 socket used, resolved to [172.22.128.229:9090]
[108]   1 socket used, resolved to [172.22.128.229:9090]
[109]   1 socket used, resolved to [172.22.128.229:9090]
[110]   1 socket used, resolved to [172.22.128.229:9090]
[111]   1 socket used, resolved to [172.22.128.229:9090]
[112]   1 socket used, resolved to [172.22.128.229:9090]
[113]   1 socket used, resolved to [172.22.128.229:9090]
[114]   1 socket used, resolved to [172.22.128.229:9090]
[115]   1 socket used, resolved to [172.22.128.229:9090]
[116]   1 socket used, resolved to [172.22.128.229:9090]
[117]   1 socket used, resolved to [172.22.128.229:9090]
[118]   1 socket used, resolved to [172.22.128.229:9090]
[119]   1 socket used, resolved to [172.22.128.229:9090]
[120]   1 socket used, resolved to [172.22.128.229:9090]
[121]   1 socket used, resolved to [172.22.128.229:9090]
[122]   1 socket used, resolved to [172.22.128.229:9090]
[123]   1 socket used, resolved to [172.22.128.229:9090]
[124]   1 socket used, resolved to [172.22.128.229:9090]
[125]   1 socket used, resolved to [172.22.128.229:9090]
[126]   1 socket used, resolved to [172.22.128.229:9090]
[127]   1 socket used, resolved to [172.22.128.229:9090]
[128]   1 socket used, resolved to [172.22.128.229:9090]
[129]   1 socket used, resolved to [172.22.128.229:9090]
[130]   1 socket used, resolved to [172.22.128.229:9090]
[131]   1 socket used, resolved to [172.22.128.229:9090]
[132]   1 socket used, resolved to [172.22.128.229:9090]
[133]   1 socket used, resolved to [172.22.128.229:9090]
[134]   1 socket used, resolved to [172.22.128.229:9090]
[135]   1 socket used, resolved to [172.22.128.229:9090]
[136]   1 socket used, resolved to [172.22.128.229:9090]
[137]   1 socket used, resolved to [172.22.128.229:9090]
[138]   1 socket used, resolved to [172.22.128.229:9090]
[139]   1 socket used, resolved to [172.22.128.229:9090]
[140]   1 socket used, resolved to [172.22.128.229:9090]
[141]   1 socket used, resolved to [172.22.128.229:9090]
[142]   1 socket used, resolved to [172.22.128.229:9090]
[143]   1 socket used, resolved to [172.22.128.229:9090]
[144]   1 socket used, resolved to [172.22.128.229:9090]
[145]   1 socket used, resolved to [172.22.128.229:9090]
[146]   1 socket used, resolved to [172.22.128.229:9090]
[147]   1 socket used, resolved to [172.22.128.229:9090]
[148]   1 socket used, resolved to [172.22.128.229:9090]
[149]   1 socket used, resolved to [172.22.128.229:9090]
[150]   1 socket used, resolved to [172.22.128.229:9090]
[151]   1 socket used, resolved to [172.22.128.229:9090]
[152]   1 socket used, resolved to [172.22.128.229:9090]
[153]   1 socket used, resolved to [172.22.128.229:9090]
[154]   1 socket used, resolved to [172.22.128.229:9090]
[155]   1 socket used, resolved to [172.22.128.229:9090]
[156]   1 socket used, resolved to [172.22.128.229:9090]
[157]   1 socket used, resolved to [172.22.128.229:9090]
[158]   1 socket used, resolved to [172.22.128.229:9090]
[159]   1 socket used, resolved to [172.22.128.229:9090]
[160]   1 socket used, resolved to [172.22.128.229:9090]
[161]   1 socket used, resolved to [172.22.128.229:9090]
[162]   1 socket used, resolved to [172.22.128.229:9090]
[163]   1 socket used, resolved to [172.22.128.229:9090]
[164]   1 socket used, resolved to [172.22.128.229:9090]
[165]   1 socket used, resolved to [172.22.128.229:9090]
[166]   1 socket used, resolved to [172.22.128.229:9090]
[167]   1 socket used, resolved to [172.22.128.229:9090]
[168]   1 socket used, resolved to [172.22.128.229:9090]
[169]   1 socket used, resolved to [172.22.128.229:9090]
[170]   1 socket used, resolved to [172.22.128.229:9090]
[171]   1 socket used, resolved to [172.22.128.229:9090]
[172]   1 socket used, resolved to [172.22.128.229:9090]
[173]   1 socket used, resolved to [172.22.128.229:9090]
[174]   1 socket used, resolved to [172.22.128.229:9090]
[175]   1 socket used, resolved to [172.22.128.229:9090]
[176]   1 socket used, resolved to [172.22.128.229:9090]
[177]   1 socket used, resolved to [172.22.128.229:9090]
[178]   1 socket used, resolved to [172.22.128.229:9090]
[179]   1 socket used, resolved to [172.22.128.229:9090]
[180]   1 socket used, resolved to [172.22.128.229:9090]
[181]   1 socket used, resolved to [172.22.128.229:9090]
[182]   1 socket used, resolved to [172.22.128.229:9090]
[183]   1 socket used, resolved to [172.22.128.229:9090]
[184]   1 socket used, resolved to [172.22.128.229:9090]
[185]   1 socket used, resolved to [172.22.128.229:9090]
[186]   1 socket used, resolved to [172.22.128.229:9090]
[187]   1 socket used, resolved to [172.22.128.229:9090]
[188]   1 socket used, resolved to [172.22.128.229:9090]
[189]   1 socket used, resolved to [172.22.128.229:9090]
[190]   1 socket used, resolved to [172.22.128.229:9090]
[191]   1 socket used, resolved to [172.22.128.229:9090]
[192]   1 socket used, resolved to [172.22.128.229:9090]
[193]   1 socket used, resolved to [172.22.128.229:9090]
[194]   1 socket used, resolved to [172.22.128.229:9090]
[195]   1 socket used, resolved to [172.22.128.229:9090]
[196]   1 socket used, resolved to [172.22.128.229:9090]
[197]   1 socket used, resolved to [172.22.128.229:9090]
[198]   1 socket used, resolved to [172.22.128.229:9090]
[199]   1 socket used, resolved to [172.22.128.229:9090]
[200]   1 socket used, resolved to [172.22.128.229:9090]
[201]   1 socket used, resolved to [172.22.128.229:9090]
[202]   1 socket used, resolved to [172.22.128.229:9090]
[203]   1 socket used, resolved to [172.22.128.229:9090]
[204]   1 socket used, resolved to [172.22.128.229:9090]
[205]   1 socket used, resolved to [172.22.128.229:9090]
[206]   1 socket used, resolved to [172.22.128.229:9090]
[207]   1 socket used, resolved to [172.22.128.229:9090]
[208]   1 socket used, resolved to [172.22.128.229:9090]
[209]   1 socket used, resolved to [172.22.128.229:9090]
[210]   1 socket used, resolved to [172.22.128.229:9090]
[211]   1 socket used, resolved to [172.22.128.229:9090]
[212]   1 socket used, resolved to [172.22.128.229:9090]
[213]   1 socket used, resolved to [172.22.128.229:9090]
[214]   1 socket used, resolved to [172.22.128.229:9090]
[215]   1 socket used, resolved to [172.22.128.229:9090]
[216]   1 socket used, resolved to [172.22.128.229:9090]
[217]   1 socket used, resolved to [172.22.128.229:9090]
[218]   1 socket used, resolved to [172.22.128.229:9090]
[219]   1 socket used, resolved to [172.22.128.229:9090]
[220]   1 socket used, resolved to [172.22.128.229:9090]
[221]   1 socket used, resolved to [172.22.128.229:9090]
[222]   1 socket used, resolved to [172.22.128.229:9090]
[223]   1 socket used, resolved to [172.22.128.229:9090]
[224]   1 socket used, resolved to [172.22.128.229:9090]
[225]   1 socket used, resolved to [172.22.128.229:9090]
[226]   1 socket used, resolved to [172.22.128.229:9090]
[227]   1 socket used, resolved to [172.22.128.229:9090]
[228]   1 socket used, resolved to [172.22.128.229:9090]
[229]   1 socket used, resolved to [172.22.128.229:9090]
[230]   1 socket used, resolved to [172.22.128.229:9090]
[231]   1 socket used, resolved to [172.22.128.229:9090]
[232]   1 socket used, resolved to [172.22.128.229:9090]
[233]   1 socket used, resolved to [172.22.128.229:9090]
[234]   1 socket used, resolved to [172.22.128.229:9090]
[235]   1 socket used, resolved to [172.22.128.229:9090]
[236]   1 socket used, resolved to [172.22.128.229:9090]
[237]   1 socket used, resolved to [172.22.128.229:9090]
[238]   1 socket used, resolved to [172.22.128.229:9090]
[239]   1 socket used, resolved to [172.22.128.229:9090]
[240]   1 socket used, resolved to [172.22.128.229:9090]
[241]   1 socket used, resolved to [172.22.128.229:9090]
[242]   1 socket used, resolved to [172.22.128.229:9090]
[243]   1 socket used, resolved to [172.22.128.229:9090]
[244]   1 socket used, resolved to [172.22.128.229:9090]
[245]   1 socket used, resolved to [172.22.128.229:9090]
[246]   1 socket used, resolved to [172.22.128.229:9090]
[247]   1 socket used, resolved to [172.22.128.229:9090]
[248]   1 socket used, resolved to [172.22.128.229:9090]
[249]   1 socket used, resolved to [172.22.128.229:9090]
[250]   1 socket used, resolved to [172.22.128.229:9090]
[251]   1 socket used, resolved to [172.22.128.229:9090]
[252]   1 socket used, resolved to [172.22.128.229:9090]
[253]   1 socket used, resolved to [172.22.128.229:9090]
[254]   1 socket used, resolved to [172.22.128.229:9090]
[255]   1 socket used, resolved to [172.22.128.229:9090]
[256]   1 socket used, resolved to [172.22.128.229:9090]
[257]   1 socket used, resolved to [172.22.128.229:9090]
[258]   1 socket used, resolved to [172.22.128.229:9090]
[259]   1 socket used, resolved to [172.22.128.229:9090]
[260]   1 socket used, resolved to [172.22.128.229:9090]
[261]   1 socket used, resolved to [172.22.128.229:9090]
[262]   1 socket used, resolved to [172.22.128.229:9090]
[263]   1 socket used, resolved to [172.22.128.229:9090]
[264]   1 socket used, resolved to [172.22.128.229:9090]
[265]   1 socket used, resolved to [172.22.128.229:9090]
[266]   1 socket used, resolved to [172.22.128.229:9090]
[267]   1 socket used, resolved to [172.22.128.229:9090]
[268]   1 socket used, resolved to [172.22.128.229:9090]
[269]   1 socket used, resolved to [172.22.128.229:9090]
[270]   1 socket used, resolved to [172.22.128.229:9090]
[271]   1 socket used, resolved to [172.22.128.229:9090]
[272]   1 socket used, resolved to [172.22.128.229:9090]
[273]   1 socket used, resolved to [172.22.128.229:9090]
[274]   1 socket used, resolved to [172.22.128.229:9090]
[275]   1 socket used, resolved to [172.22.128.229:9090]
[276]   1 socket used, resolved to [172.22.128.229:9090]
[277]   1 socket used, resolved to [172.22.128.229:9090]
[278]   1 socket used, resolved to [172.22.128.229:9090]
[279]   1 socket used, resolved to [172.22.128.229:9090]
[280]   1 socket used, resolved to [172.22.128.229:9090]
[281]   1 socket used, resolved to [172.22.128.229:9090]
[282]   1 socket used, resolved to [172.22.128.229:9090]
[283]   1 socket used, resolved to [172.22.128.229:9090]
[284]   1 socket used, resolved to [172.22.128.229:9090]
[285]   1 socket used, resolved to [172.22.128.229:9090]
[286]   1 socket used, resolved to [172.22.128.229:9090]
[287]   1 socket used, resolved to [172.22.128.229:9090]
[288]   1 socket used, resolved to [172.22.128.229:9090]
[289]   1 socket used, resolved to [172.22.128.229:9090]
[290]   1 socket used, resolved to [172.22.128.229:9090]
[291]   1 socket used, resolved to [172.22.128.229:9090]
[292]   1 socket used, resolved to [172.22.128.229:9090]
[293]   1 socket used, resolved to [172.22.128.229:9090]
[294]   1 socket used, resolved to [172.22.128.229:9090]
[295]   1 socket used, resolved to [172.22.128.229:9090]
[296]   1 socket used, resolved to [172.22.128.229:9090]
[297]   1 socket used, resolved to [172.22.128.229:9090]
[298]   1 socket used, resolved to [172.22.128.229:9090]
[299]   1 socket used, resolved to [172.22.128.229:9090]
Sockets used: 300 (for perfect keepalive, would be 300)
Uniform: false, Jitter: false
IP addresses distribution:
172.22.128.229:9090: 300
Code 200 : 9000 (100.0 %)
Response Header Sizes : count 9000 avg 158.94156 +/- 0.2346 min 158 max 159 sum 1430474
Response Body/Total Sizes : count 9000 avg 282.94156 +/- 0.2346 min 282 max 283 sum 2546474
All done 9000 calls (plus 300 warmup) 32.932 ms avg, 299.6 qps

Oct 07 '22 10:10 penghuazhou

@JorTurFer, can you help me, thanks?

Oct 08 '22 11:10 penghuazhou

Could KEDA pod be limited by CPU? I mean, are you monitoring the CPU usage per pod? It seems that KEDA is responding slowly due to whatever

Oct 08 '22 14:10 JorTurFer

@JorTurFer cpu usage is low.

Oct 09 '22 07:10 penghuazhou

@JorTurFer It also timeout or abort while handling when i only use cron scaler.

apiVersion: keda.sh/v1alpha1
kind: ScaledObject
metadata:
  finalizers:
    - finalizer.keda.sh
  labels:
    app.kubernetes.io/name: bservice5
    devops.zego.im/center-name: smalpha
    devops.zego.im/cluster-name: smalpha
    devops.zego.im/env: alpha
    devops.zego.im/group: media
    devops.zego.im/operator-version: v1.3.0
    devops.zego.im/system-name: rtc
    scaledobject.keda.sh/name: so-bservice5
  name: so-bservice5
  namespace: test-infra
spec:
  #  pollingInterval: 86400
  pollingInterval: 30
  advanced:
    horizontalPodAutoscalerConfig:
      behavior:
        scaleDown:
          policies:
            - periodSeconds: 600
              type: Percent
              value: 5
            - periodSeconds: 300
              type: Pods
              value: 1
          selectPolicy: Min
          stabilizationWindowSeconds: 1800
        scaleUp:
          policies:
            - periodSeconds: 15
              type: Pods
              value: 8
            - periodSeconds: 15
              type: Percent
              value: 100
          selectPolicy: Max
          stabilizationWindowSeconds: 0
  maxReplicaCount: 1
  minReplicaCount: 1
  scaleTargetRef:
    apiVersion: apps.zego.im/v1alpha3
    kind: AppGroup
    name: bservice5
  triggers:
    - metadata:
        desiredReplicas: '2'
        end: 55 * * * *
        start: 0 * * * *
        timezone: Asia/Shanghai
      type: cron
    - metadata:
        desiredReplicas: '2'
        end: 55 3 * * *
        start: 0 2 * * *
        timezone: Asia/Shanghai
      type: cron

E1009 10:49:59.360210 1 writers.go:131] apiserver was unable to write a fallback JSON response: http: Handler timeout
--
Sun, Oct 9 2022 6:49:59 pm | E1009 10:49:59.361350 1 timeout.go:141] post-timeout activity - time-elapsed: 2.209796ms, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>
Sun, Oct 9 2022 6:50:29 pm | E1009 10:50:29.358029 1 writers.go:118] apiserver was unable to write a JSON response: http2: stream closed
Sun, Oct 9 2022 6:50:29 pm | E1009 10:50:29.358055 1 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"http2: stream closed"}: http2: stream closed
Sun, Oct 9 2022 6:50:29 pm | E1009 10:50:29.358058 1 wrap.go:53] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="08498b3d-f419-4e27-b1da-64b025ca29de"
Sun, Oct 9 2022 6:50:29 pm | E1009 10:50:29.358059 1 wrap.go:53] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="aa55df56-1281-499c-8e6e-2cbf28e829d9"
Sun, Oct 9 2022 6:50:29 pm | E1009 10:50:29.358086 1 timeout.go:141] post-timeout activity - time-elapsed: 1.806µs, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>
Sun, Oct 9 2022 6:50:29 pm | E1009 10:50:29.358095 1 wrap.go:53] timeout or abort while handling: method=GET URI="/apis/external.metrics.k8s.io/v1beta1" audit-ID="465f8416-da76-4843-9cfc-c7bfcf32204c"
Sun, Oct 9 2022 6:50:29 pm | E1009 10:50:29.358098 1 timeout.go:141] post-timeout activity - time-elapsed: 2.474µs, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>
Sun, Oct 9 2022 6:50:29 pm | E1009 10:50:29.359342 1 writers.go:131] apiserver was unable to write a fallback JSON response: http: Handler timeout
Sun, Oct 9 2022 6:50:29 pm | E1009 10:50:29.360835 1 timeout.go:141] post-timeout activity - time-elapsed: 2.710346ms, GET "/apis/external.metrics.k8s.io/v1beta1" result: <nil>

Oct 09 '22 10:10 penghuazhou

@JorTurFer, can you help me, thanks?

Oct 11 '22 08:10 penghuazhou

Could you try to list metrics manually the metrics? kubectl get --raw "/apis/external.metrics.k8s.io/v1beta1" How much time does it need? Are you running your cluster in some cloud provider or on-prem?

Oct 11 '22 08:10 JorTurFer

@JorTurFer It about 0.1s when i exec kubectl get --raw blow. I run my cluster in aks（https://www.aliyun.com/product/kubernetes） and tke(https://cloud.tencent.com/product/tke).

Oct 11 '22 13:10 penghuazhou

@JorTurFer, can you help me, thanks?

Oct 13 '22 09:10 penghuazhou

It's weird, IDK what's happening, maybe @zroubalik or @v-shenoy have more experience with k8s api. I have been reviewing and it seems that the HTTP request is throwing a timeout, but the default value AFAI can see is 1 minute. Are you facing with scaling issues or the problem is only related with the logs?

Oct 13 '22 19:10 JorTurFer

yes, only related with the logs

Oct 14 '22 02:10 penghuazhou

@JorTurFer, Can you work well when you have 200 scaledobject?

Oct 19 '22 06:10 penghuazhou

I haven't noticed issues with > 150 ScaledObjects in the same cluster, but it depends directly on the amount and type of the triggers. We are working on improving this, but atm we are totally dependent of that. I know about end users with > 500 ScaledObjects working together, but IDK about the exact usage they are doing. In fact, there is an issue reporting problems with more than 1000 https://github.com/kedacore/keda/issues/2382, so I guess that 200 will work

Oct 19 '22 11:10 JorTurFer

@JorTurFer, I modify ListAllExternalMetrics method return a small response. Then it work well。Do you know which case will call "/apis/external.metrics.k8s.io/v1beta1".

before modify

after modify

Oct 20 '22 03:10 penghuazhou

To add to this issue , i have the same errors from keda metric server:

1 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"http2: stream closed"}: http2: stream closed`

Latest version of keda.

querying only 13 Prometheus type triggers each has 1 simple query , This is what i tried so far:

Resizing resources (CPU+Mem) and replicas of - Prometheus server - Keda metric server - K8s metric server x2 Increasing pollingInterval: 60

nothing helped, Prometheus resides on the same k8s cluster. Only removing 1 (any one) of the ScaledObject with type Prometheus and stay with 12 of them stopped the errors. Could it be also related to cache size?

@JorTurFer

Oct 21 '22 11:10 ShimonOhayon

@JorTurFer, I think we can discuss here，can we reopen this issue? https://github.com/kedacore/keda/issues/1797

Oct 22 '22 03:10 penghuazhou

@JorTurFer, can you help me?

Oct 22 '22 12:10 penghuazhou

The case here is that we should respond with all the metrics available in the server because this method is for listing metrics, and we should respect it. I'm checking if there is any improvement we can do there to improve this method, but atm I don't have any idea

Nov 03 '22 21:11 JorTurFer

keda keda copied to clipboard

Timeout or abort while handling GET external metrics with 1500 scaledobjects

Report

Expected Behavior

Actual Behavior

Steps to Reproduce the Problem

Logs from KEDA operator

KEDA Version

Kubernetes Version

Platform

Scaler Details

Anything else?

keda
keda copied to clipboard