Bug 1392357 - Volume Attach/Mount is slow on AWS
Summary: Volume Attach/Mount is slow on AWS
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Storage
Version: 3.4.0
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ---
: ---
Assignee: Hemant Kumar
QA Contact: Chao Yang
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-11-07 10:06 UTC by Chao Yang
Modified: 2017-08-16 19:51 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: Enhancement
Doc Text:
Feature: Improve efficiency of attach operation on AWS. Reduce overall number of API calls being made. Reason: Attach on AWS could be slow because duplicate API calls were being made and frequent polling of volume information can cause API quota to be exceeded. Result: Removed duplicate API calls from AWS code path. Also implemented bulk polling of AWS volumes to avoid API quota problems.
Clone Of:
Environment:
Last Closed: 2017-08-10 05:15:47 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
log message (20.00 KB, application/x-tar)
2016-11-09 10:42 UTC, Chao Yang
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHEA-2017:1716 0 normal SHIPPED_LIVE Red Hat OpenShift Container Platform 3.6 RPM Release Advisory 2017-08-10 09:02:50 UTC

Description Chao Yang 2016-11-07 10:06:28 UTC
Description of problem:
6 pods could not be running if create 50 pods using ebs volumes at one time

Version-Release number of selected component (if applicable):
openshift v3.4.0.22+5c56720
kubernetes v1.4.0+776c994
etcd 3.1.0-rc.0
[root@ip-172-18-7-175 ~]# cat /etc/redhat-release 
Red Hat Enterprise Linux Server release 7.3 (Maipo)

How reproducible:
80%

Steps to Reproduce:
1.Update env to support 50 ebs volumes per node
2.Create 50 pv, pvc and pods
3.After some time,6 pods could not be running
4.
[root@ip-172-18-12-250 test]# oc describe pods mypod50
Name:			mypod50
Namespace:		default
Security Policy:	anyuid
Node:			ip-172-18-7-175.ec2.internal/172.18.7.175
Start Time:		Mon, 07 Nov 2016 04:14:27 -0500
Labels:			name=frontendhttp
Status:			Pending
IP:			
Controllers:		<none>
Containers:
  myfrontend:
    Container ID:	
    Image:		aosqe/hello-openshift
    Image ID:		
    Port:		80/TCP
    State:		Waiting
      Reason:		ContainerCreating
    Ready:		False
    Restart Count:	0
    Volume Mounts:
      /tmp from aws (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from default-token-8qnna (ro)
    Environment Variables:	<none>
Conditions:
  Type		Status
  Initialized 	True 
  Ready 	False 
  PodScheduled 	True 
Volumes:
  aws:
    Type:	PersistentVolumeClaim (a reference to a PersistentVolumeClaim in the same namespace)
    ClaimName:	ebs50
    ReadOnly:	false
  default-token-8qnna:
    Type:	Secret (a volume populated by a Secret)
    SecretName:	default-token-8qnna
QoS Class:	BestEffort
Tolerations:	<none>
Events:
  FirstSeen	LastSeen	Count	From					SubobjectPath	Type		Reason		Message
  ---------	--------	-----	----					-------------	--------	------		-------
  24m		24m		1	{default-scheduler }					Normal		Scheduled	Successfully assigned mypod50 to ip-172-18-7-175.ec2.internal
  22m		2m		10	{kubelet ip-172-18-7-175.ec2.internal}			Warning		FailedMount	Unable to mount volumes for pod "mypod50_default(92172d4a-a4ca-11e6-bf36-0e259d96f826)": timeout expired waiting for volumes to attach/mount for pod "mypod50"/"default". list of unattached/unmounted volumes=[aws]
  22m		2m		10	{kubelet ip-172-18-7-175.ec2.internal}			Warning		FailedSync	Error syncing pod, skipping: timeout expired waiting for volumes to attach/mount for pod "mypod50"/"default". list of unattached/unmounted volumes=[aws]



Actual results:
Some of pods could not be running

Expected results:
All of 50 pods should be running

Additional info:
[root@ip-172-18-7-175 ~]# grep -r ddd7c443 /var/log/messages
Nov  7 04:14:35 ip-172-18-7-175 atomic-openshift-node: I1107 04:14:35.146015   78899 reconciler.go:225] VerifyControllerAttachedVolume operation started for volume "kubernetes.io/aws-ebs/aws://us-east-1d/vol-ddd7c443" (spec.Name: "ebs19") pod "92172d4a-a4ca-11e6-bf36-0e259d96f826" (UID: "92172d4a-a4ca-11e6-bf36-0e259d96f826")
Nov  7 04:14:35 ip-172-18-7-175 atomic-openshift-node: E1107 04:14:35.146133   78899 nestedpendingoperations.go:253] Operation for "\"kubernetes.io/aws-ebs/aws://us-east-1d/vol-ddd7c443\"" failed. No retries permitted until 2016-11-07 04:14:43.146109937 -0500 EST (durationBeforeRetry 8s). Error: Volume "kubernetes.io/aws-ebs/aws://us-east-1d/vol-ddd7c443" (spec.Name: "ebs19") pod "92172d4a-a4ca-11e6-bf36-0e259d96f826" (UID: "92172d4a-a4ca-11e6-bf36-0e259d96f826") has not yet been added to the list of VolumesInUse in the node's volume status.
Nov  7 04:16:35 ip-172-18-7-175 atomic-openshift-node: I1107 04:16:35.538277   78899 reconciler.go:225] VerifyControllerAttachedVolume operation started for volume "kubernetes.io/aws-ebs/aws://us-east-1d/vol-ddd7c443" (spec.Name: "ebs19") pod "92172d4a-a4ca-11e6-bf36-0e259d96f826" (UID: "92172d4a-a4ca-11e6-bf36-0e259d96f826")
Nov  7 04:16:35 ip-172-18-7-175 atomic-openshift-node: E1107 04:16:35.544628   78899 nestedpendingoperations.go:253] Operation for "\"kubernetes.io/aws-ebs/aws://us-east-1d/vol-ddd7c443\"" failed. No retries permitted until 2016-11-07 04:18:35.544615109 -0500 EST (durationBeforeRetry 2m0s). Error: Volume "kubernetes.io/aws-ebs/aws://us-east-1d/vol-ddd7c443" (spec.Name: "ebs19") pod "92172d4a-a4ca-11e6-bf36-0e259d96f826" (UID: "92172d4a-a4ca-11e6-bf36-0e259d96f826") is not yet attached according to node status.

Comment 1 Bradley Childs 2016-11-08 17:44:46 UTC
This looks like a scenario where the AWS API Qutoa is being exhausted and the attach calls for the PVs are failing due to the lack of quota.

Can you attach the entire logs?

Thanks,

Comment 2 Chao Yang 2016-11-09 10:42:39 UTC
Created attachment 1218889 [details]
log message

Comment 3 Chao Yang 2016-11-09 10:45:55 UTC
Hi I fould the pod will be running at last, not sure which will impact the attach/mount time. please see the log attached, pv name is pvc-3d764334-a64e-11e6-94f8-0e178310007a

Comment 4 Hemant Kumar 2016-11-09 18:11:39 UTC
What is the format of log file? I untared it and it seems to have created a .bak file which looks like a binary file.

Comment 5 Troy Dawson 2016-11-09 19:53:58 UTC
Moving to "Assigned".  Modified is for when the fix is in origin and/or OCP.

Comment 6 Hemant Kumar 2016-11-09 20:50:23 UTC
Also the `.bak` file appears to be empty.

Comment 7 Chao Yang 2016-11-10 08:58:22 UTC
The Log is too big to upload. So I mailed to you as attachment.

Comment 8 Hemant Kumar 2016-11-14 20:56:14 UTC
According to AWS, *40* is the number of allowed EBS volumes on a single instance.  

http://docs.aws.amazon.com/AWSEC2/latest/UserGuide/volume_limits.html

Creating 50 or more volumes will likely lead to API limits problems we are seeing here. So we have to tread carefully to avoid this.

Having said that, I am going to try and investigate more and see how high we can go, before the limit kicks in.

Comment 10 Chao Yang 2016-11-15 06:45:06 UTC
These pods will be running after some time. So I changed the bug title
And I don't think it is caused by the limit of AWS API quota. If I try to use NFS pv I also met this issue.

Maybe there are some reason that will impact the attach and mount

Comment 11 Jan Safranek 2016-11-15 15:33:59 UTC
chaoyang, AWS is pretty slow when creating + attaching volumes to a node and you're hitting AWS API call throttling. How slow is actually slow?

Comment 12 Chao Yang 2016-11-16 07:58:45 UTC
It did not reproduce on the OCP openshift v3.4.0.26+f7e109e
I created 50 pv, 50 pvc and 50 pods, all of pods are running in 3 minutes.

But on the OCP openshift v3.4.0.22+5c56720
6 of 50 pods are in the status of "ContainerCreating" more than 7 minutes and can met the "timeout expired waiting for volumes to attach/mount" error message

(In reply to Jan Safranek from comment #11)
> chaoyang, AWS is pretty slow when creating + attaching volumes to a node and
> you're hitting AWS API call throttling. How slow is actually slow?

Comment 14 Eric Paris 2017-01-28 18:05:45 UTC
@hemant I see that 39842 has merged upstream. Is it in 1.5.2? If not, will you backport it to origin?

Is there anything we can/should do to make 39564 go faster?

Comment 17 Hemant Kumar 2017-03-29 19:32:58 UTC
The code that removes duplicate AWS calls in code has been merged in 1.5 - https://github.com/openshift/origin/pull/12740

Also code for recording metrics for aws is here - https://github.com/kubernetes/kubernetes/pull/43477

Comment 19 Chao Yang 2017-06-15 06:49:41 UTC
Test is passed on below version:
openshift v3.6.105
kubernetes v1.6.1+5115d708d7

1.Create 50 pv, pvc ,pods
2.Pods is running.
3.Delete 50 pods, pvc, pv
Repeat above steps for several times and all pods are running.

Comment 21 errata-xmlrpc 2017-08-10 05:15:47 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2017:1716


Note You need to log in before you can comment on or make changes to this bug.