high latency after adding linkerd to grpc application

[sumit-joshi-mt]

What is the issue?
We observed latency is increased after injecting linkerd sidecar to deployment and throughput is decreased.

The background is we have 2 grpc go applications running on Kubernetes, we are doing load-test for this application. For load-test we are just using get call which returns a text message as response. We have added a sleep of 50ms in call here.
After adding linkerd latency is increased:
latency after adding linkerd p90 =75.10ms p90=77.61 ms and p99=82.54 ms
latency without linkerd p90=51.82 ms, p95=51.99 ms and p99=52.80 ms

Another observation is throughput is also decreased after adding linkerd without linkerd application was able to process 3.8k/sec, after adding linkerd if fall down 2.8k/sec.

Results before adding linkerd:
Summary:
Count: 2338821
Total: 600.00 s
Slowest: 85.85 ms
Fastest: 50.31 ms
Average: 51.25 ms
Requests/sec: 3898.03

Latency distribution:
10 % in 50.64 ms
25 % in 50.76 ms
50 % in 51.39 ms
75 % in 51.62 ms
90 % in 51.82 ms
95 % in 51.99 ms
99 % in 52.80 ms

Status code distribution:
[OK] 2338625 responses
[Unavailable] 196 responses

Error distribution:
[196] rpc error: code = Unavailable desc = transport is closing

After adding linkerd:
Summary:
Count: 1731486
Total: 600.00 s
Slowest: 107.58 ms
Fastest: 54.59 ms
Average: 69.26 ms
Requests/sec: 2885.81

Latency distribution:
10 % in 64.56 ms
25 % in 66.43 ms
50 % in 68.76 ms
75 % in 71.64 ms
90 % in 75.10 ms
95 % in 77.61 ms
99 % in 82.54 ms

Status code distribution:
[OK] 1731286 responses
[Unavailable] 200 responses

Error distribution:
[200] rpc error: code = Unavailable desc = transport is closing

I have also noticed that CPU utilization of linkerd proxy at client side is increasing heavily. Is there something I have not configured properly that would cause this kind of behavior?

Linkerd Proxy CPU at client side:

Output of linkerd check

➜  ~ linkerd check
kubernetes-api
--------------
√ can initialize the client
√ can query the Kubernetes API

kubernetes-version
------------------
√ is running the minimum Kubernetes API version
√ is running the minimum kubectl version

linkerd-existence
-----------------
√ 'linkerd-config' config map exists
√ heartbeat ServiceAccount exist
√ control plane replica sets are ready
√ no unschedulable pods
√ controller pod is running
√ can initialize the client
√ can query the control plane API

linkerd-config
--------------
√ control plane Namespace exists
√ control plane ClusterRoles exist
√ control plane ClusterRoleBindings exist
√ control plane ServiceAccounts exist
√ control plane CustomResourceDefinitions exist
√ control plane MutatingWebhookConfigurations exist
√ control plane ValidatingWebhookConfigurations exist
√ control plane PodSecurityPolicies exist

linkerd-identity
----------------
√ certificate config is valid
√ trust anchors are using supported crypto algorithm
√ trust anchors are within their validity period
√ trust anchors are valid for at least 60 days
√ issuer cert is using supported crypto algorithm
√ issuer cert is within its validity period
√ issuer cert is valid for at least 60 days
√ issuer cert is issued by the trust anchor

linkerd-api
-----------
√ control plane pods are ready
√ control plane self-check
√ [kubernetes] control plane can talk to Kubernetes
√ [prometheus] control plane can talk to Prometheus
√ tap api service is running

linkerd-version
---------------
√ can determine the latest version
√ cli is up-to-date

control-plane-version
---------------------
√ control plane is up-to-date
√ control plane and cli versions match

linkerd-addons
--------------
√ 'linkerd-config-addons' config map exists

linkerd-grafana
---------------
√ grafana add-on service account exists
√ grafana add-on config map exists
√ grafana pod is running

Status check results are √

Deployment annotations:

annotations:
        config.linkerd.io/proxy-cpu-limit: "4"
        config.linkerd.io/proxy-cpu-request: "3.5"
        config.linkerd.io/proxy-memory-limit: 1Gi
        config.linkerd.io/proxy-memory-request: 512Mi
        linkerd.io/inject: enabled

Environment:
Kubernetes: v1.17.9
Platform: EKS
Linkerd: stable-2.8.1
Tool used for load-test: ghz

I can see there are other issues which talks about this:
#3755
#4671

[ihcsim]

@sumit-joshi-mt Can you try with the latest edge release? The team did some work in the proxy to support multi-threaded runtime recently. Just curious to see what the latency will look like in your setup.

I am also curious about how the values in the CPU usage chart is calculated. Can you share the PromQL query behind it? Thanks.

[sumit-joshi-mt]

Hi @ihcsim , I tried using latest edge release (edge-20.9.1). Latency and throughput seems to be comparable with results before adding linkerd now. Latency has reduced with edge release.

Results with edge release:
Summary:
Count: 2304869
Total: 600.00 s
Slowest: 98.11 ms
Fastest: 51.24 ms
Average: 52.01 ms
Requests/sec: 3841.44

Response time histogram:
51.238 [1] |
55.925 [998216] |∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎
60.613 [1094] |
65.301 [283] |
69.988 [105] |
74.676 [92] |
79.363 [103] |
84.051 [82] |
88.738 [18] |
93.426 [2] |
98.114 [4] |

Latency distribution:
10 % in 51.52 ms
25 % in 51.60 ms
50 % in 51.79 ms
75 % in 52.43 ms
90 % in 52.60 ms
95 % in 52.71 ms
99 % in 53.10 ms

Status code distribution:
[OK] 2304670 responses
[Unavailable] 199 responses

Error distribution:
[199] rpc error: code = Unavailable desc = transport is closing

However, I still see spike in CPU. As request/sec increases CPU of linkerd sidecar increases.

Here is PromQL you asked for:
avg by (container) (rate(container_cpu_usage_seconds_total{namespace="$namespace", image!="", container=~"$container", container!="POD", pod="$pod"}[2m]))

[ihcsim]

Glad to hear that the latency distribution looks much better with the latest edge. The proxy is CPU-bound so the increase in CPU usage is expected as the rps increases. What other CPU behaviour are you expecting to see?