Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

kubelet seen consuming high RAM during iSCSI connection establishment. #2382

Closed
vishnuitta opened this Issue Feb 11, 2019 · 6 comments

Comments

@vishnuitta
Copy link
Member

vishnuitta commented Feb 11, 2019

kubelet triggers iscsiadm command to discover LUNs and reads the output of the command until it exists.
Due to the issue mentioned here open-iscsi/open-iscsi#155, kubelet ends up consuming high CPU and RAM.

@vishnuitta vishnuitta self-assigned this Feb 11, 2019

@AmitKumarDas

This comment has been minimized.

Copy link
Member

AmitKumarDas commented Feb 13, 2019

Below is one of the user's setup that has this error:

General overview of setup:
- 3 machines, 2x quad-core hyperthread/node, 24GB RAM/node, 16x SAS 146GB HDDs/node
- All nodes are master, etcd, and worker
- Fedora 29
- Kubespray/Kube 1.12.4
- Docker 128.06.1-ce via Fedora 28 Docker repos
- Rancher via helm
- Helm/metrics server/Dashboard/nginx ingress via kubespray
- Cert manager/certs via custom script
- MetalLB installed
- kubectl 1.13 via workstation

General Process:
- Run kubespray
- Copy credentials file from server to workstation
- Make sure helm works
- Run rancher-init.sh
- Run kuberang, make sure it passes
- Install MetalLB
- Install OpenEBS
- Use Rancher's catalog apps to install "efk" and Prometheus using imported config from files
@AmitKumarDas

This comment has been minimized.

Copy link
Member

AmitKumarDas commented Feb 13, 2019

These are the details from another user w.r.t this issue:

UseCase:

We attach 1 elastic block storage disk to each of the worker nodes in the cluster (3 in this case). We utilize Kubespray to deploy our clusters and helm to install OpenEBS (v0.8.0) after the clusters are up. I can deploy a few applications with PVC's that utilize the OpenEBS storage. We run into issues sometimes when we re-deploy an application (or delete the application pod to restart) with helm and it needs to use the existing PVC.

Observed Issue:

It appears that the iscsiadm command that kubelet runs (iscsiadm -m discoverydb -t sendtargets -p 10.233.46.76 3260 -I default --discover) continuously fails and repeats rapidly. For some reason this causes the memory consumption of kubelet to grow until the node goes out-of-memory and needs to be rebooted.

I have noticed that killing the iscsiadm discoverydb process stops the kubelet's memory consumption from growing.

The issue is not always reproducible. It seems to happen when trying to re-attach a PVC to a pod. Freshly created PVC's seem to attach normally.

As for network delays: We do not currently monitor any network bandwidth/latency, but our loads are these clusters are fairly low. I ran into the issue on a brand new Kubernetes cluster yesterday ( on packet.net). Until now i have never questioned their network infrastructure.

We utilize helm frequently to create/delete/upgrade deployments, but we usually keep the same PVC.

Environment Details:

Clusters on packet.net
OS=CoreOS
Kubernetes Version: 1.13.1
CoreOS Version: VERSION=2037.0.0
Linux Kernel: 4.19 (required for our product)
No additional iSCSI packages were installed
iscsiadm version 2.0-873
default iscsid config

Logs from journalctl and the cstor-istgt container to follow:

jourctl logs snippet:

Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: failed to send SendTargets PDU
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: connection login retries (reopen_max) 5 exceeded
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: Connection to Discovery Address 10.233.46.76 failed
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: failed to send SendTargets PDU
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: connection login retries (reopen_max) 5 exceeded
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: Connection to Discovery Address 10.233.46.76 failed
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: failed to send SendTargets PDU
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: connection login retries (reopen_max) 5 exceeded
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: Connection to Discovery Address 10.233.46.76 failed
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: failed to send SendTargets PDU



cstor-istgt snippet:

2019-02-05/15:43:30.250 worker            :6088: c#0.140005771040512.: iscsi_read_pdu() EOF

2019-02-05/15:43:30.250 sender            :5852: s#0.140005666154240.: sender loop ended (0:14:43084)

2019-02-05/15:43:30.251 worker            :6292: c#0.140005771040512.: worker 0/-1/43084 end (c#0.140005771040512/s#0.140005666154240)
2019-02-05/15:43:30.264 worker            :5885: c#1.140005666154240.: con:1/16 [8d614b93:43088->10.233.45.100:3260,1]
2019-02-05/15:43:30.531 istgt_iscsi_op_log:1923: c#1.140005666154240.: login failed, target not ready

2019-02-05/15:43:30.782 worker            :6088: c#1.140005666154240.: iscsi_read_pdu() EOF

2019-02-05/15:43:30.782 sender            :5852: s#1.140005649413888.: sender loop ended (1:16:43088)

2019-02-05/15:43:30.783 worker            :6292: c#1.140005666154240.: worker 1/-1/43088 end (c#1.140005666154240/s#1.140005649413888)
2019-02-05/15:43:33.285 worker            :5885: c#2.140005649413888.: con:2/18 [8d614b93:43092->10.233.45.100:3260,1]
2019-02-05/15:43:33.536 istgt_iscsi_op_log:1923: c#2.140005649413888.: login failed, target not ready

2019-02-05/15:43:33.787 worker            :6088: c#2.140005649413888.: iscsi_read_pdu() EOF

2019-02-05/15:43:33.787 sender            :5852: s#2.140005632636672.: sender loop ended (2:18:43092)

2019-02-05/15:43:33.788 worker            :6292: c#2.140005649413888.: worker 2/-1/43092 end (c#2.140005649413888/s#2.140005632636672)
2019-02-05/15:43:35.251 istgt_remove_conn :7039: c#0.140005771040512.: remove_conn->initiator:147.75.97.141(iqn.2019-02.net.packet:device.7c8ad781) Target: 10.233.109.82(dummy LU0) conn:0x7f55a4c18000:0 tsih:1 connections:0  IOPending=0
2019-02-05/15:43:36.291 worker            :5885: c#0.140005666154240.: con:0/14 [8d614b93:43094->10.233.45.100:3260,1]
2019-02-05/15:43:36.540 istgt_iscsi_op_log:1923: c#0.140005666154240.: login failed, target not ready

2019-02-05/15:43:36.791 worker            :6088: c#0.140005666154240.: iscsi_read_pdu() EOF

2019-02-05/15:43:36.791 sender            :5852: s#0.140005771040512.: sender loop ended (0:14:43094)
@kmova

This comment has been minimized.

Copy link
Member

kmova commented Feb 21, 2019

There is work to be done in K8s (kubelet) from hogging the RAM/CPU of the node when the commands it executes results in generating too many logs. This is being tracked by: kubernetes/kubernetes#70890

@kmova

This comment has been minimized.

Copy link
Member

kmova commented Feb 21, 2019

The timeout of iscsiadm discovery command was being caused by cstor target, failing to read the discovery packet that arrived few ms later after the initial connection. This was tracked down to the socket readv call being made with SO_RCVLOWAT set to 48. After setting the value to default 1, the readv calls are not blocked. As it turned out, there is a difference in OS/Kernel in handling the readv calls, where data is split cross multiple PDUs.

This was a very hard issue to reproduce and many many thanks to @proegssilb for helping with his time and setup in tracking down the issue and validating with a debug build with the fix. openebs/istgt@5df6ec1

@kmova kmova changed the title kubelet seen consuming high RAM usage with cstor volumes kubelet seen consuming high RAM during iSCSI connection establishment. Feb 21, 2019

@kmova

This comment has been minimized.

Copy link
Member

kmova commented Feb 21, 2019

The test program used to check how the OS handles delayed packets when SO_RCVLOWAT is set is available here. https://github.com/pawanpraka1/gist

When running this program by simulating the network condition of delayed packet arrivals - the read calls are getting blocked. A issue for this is raised on Fedora at: https://bugzilla.redhat.com/show_bug.cgi?id=1679565

We have verified that the issue doesn't exist on Ubuntu and RedHat.

@kmova

This comment has been minimized.

Copy link
Member

kmova commented Feb 23, 2019

The cstor target has been updated to work with slow receiving iscsi PDUs.

@kmova kmova closed this Feb 23, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.