Repository: kubernetes
Issue: Pod stuck in ContainerCreating for too long due to volumeManager
Labels: kind/bug,sig/storage,lifecycle/rotten,needs-triage

### What happened?

Recently I found newly created pod needs too long to get ready, nearly 14 mins, and most of time waiting for the volume mounted.
```
I0510 18:42:17.107493   24862 config.go:383] "Receiving a new pod" pod="default/k8s-deploy-test-5f87b8dd98-mgl45"
I0510 18:42:17.109962   24862 kubelet.go:1937] "SyncLoop ADD" source="api" pods=[default/k8s-deploy-test-5f87b8dd98-mgl45]
I0510 18:42:17.131637   24862 volume_manager.go:373] "Waiting for volumes to attach and mount for pod" pod="default/k8s-deploy-test-5f87b8dd98-mgl45"
I0510 18:42:18.136456   24862 kubelet.go:1950] "SyncLoop RECONCILE" source="api" pods=[default/k8s-deploy-test-5f87b8dd98-mgl45]
E0510 18:44:20.133669   24862 kubelet.go:1701] "Unable to attach or mount volumes for pod; skipping pod" err="unmounted volumes=[kube-api-access-dwkfj], unattached volumes=[kube-api-access-dwkfj]: timed out waiting for the condition" pod="default/k8s-deploy-test-5f87b8dd98-mgl45"
E0510 18:44:20.133721   24862 pod_workers.go:190] "Error syncing pod, skipping" err="unmounted volumes=[kube-api-access-dwkfj], unattached volumes=[kube-api-access-dwkfj]: timed out waiting for the condition" pod="default/k8s-deploy-test-5f87b8dd98-mgl45" podUID=547908ab-dec8-4851-8f39-e1a2706e318c
I0510 18:44:20.133771   24862 event.go:291] "Event occurred" object="default/k8s-deploy-test-5f87b8dd98-mgl45" kind="Pod" apiVersion="v1" type="Warning" reason="FailedMount" message="Unable to attach or mount volumes: unmounted volumes=[kube-api-access-dwkfj], unattached volumes=[kube-api-access-dwkfj]: timed out waiting for the condition"
...
I0510 18:56:11.390064   24862 desired_state_of_world_populator.go:349] "Added volume to desired state" pod="default/k8s-deploy-test-5f87b8dd98-mgl45" volumeName="kube-api-access-dwkfj" volumeSpecName="kube-api-access-dwkfj"
I0510 18:56:11.429051   24862 reconciler.go:215] "Starting operationExecutor.VerifyControllerAttachedVolume for volume \"kube-api-access-dwkfj\" (UniqueName: \"kubernetes.io/projected/547908ab-dec8-4851-8f39-e1a2706e318c-kube-api-access-dwkfj\") pod \"k8s-deploy-test-5f87b8dd98-mgl45\" (UID: \"547908ab-dec8-4851-8f39-e1a2706e318c\") "
I0510 18:56:11.429096   24862 reconciler.go:228] "operationExecutor.VerifyControllerAttachedVolume started for volume \"kube-api-access-dwkfj\" (UniqueName:\"kubernetes.io/projected/547908ab-dec8-4851-8f39-e1a2706e318c-kube-api-access-dwkfj\") pod \"k8s-deploy-test-5f87b8dd98-mgl45\" (UID: \"547908ab-dec8-4851-8f39-e1a2706e318c\") "
I0510 18:56:11.536353   24862 reconciler.go:258] "Starting operationExecutor.MountVolume for volume \"kube-api-access-dwkfj\" (UniqueName: \"kubernetes.io/projected/547908ab-dec8-4851-8f39-e1a2706e318c-kube-api-access-dwkfj\") pod \"k8s-deploy-test-5f87b8dd98-mgl45\" (UID: \"547908ab-dec8-4851-8f39-e1a2706e318c\") "
I0510 18:56:11.536412   24862 reconciler.go:273] "operationExecutor.MountVolume started for volume \"kube-api-access-dwkfj\" (UniqueName: \"kubernetes.io/projected/547908ab-dec8-4851-8f39-e1a2706e318c-kube-api-access-dwkfj\") pod \"k8s-deploy-test-5f87b8dd98-mgl45\" (UID: \"547908ab-dec8-4851-8f39-e1a2706e318c\") "
...
I0510 18:56:14.344592   24862 kubelet.go:1975] "SyncLoop (PLEG): event for pod" pod="default/k8s-deploy-test-5f87b8dd98-mgl45" event=&{ID:547908ab-dec8-4851-8f39-e1a2706e318c Type:ContainerStarted Data:abf3f20f8cd769a40fc66a4990251ac4ca6430bbf8c5ecb7d0d700b4aff081d0}
```

After deep analysis, it seems block point lies down [populatorLoop](https://github.com/kubernetes/kubernetes/blob/9d85e18ec0dc09f681650d04d65e3db5237bef96/pkg/kubelet/volumemanager/populator/desired_state_of_world_populator.go#L154) of  `desiredStateOfWorldPopulator`, which runs periodically. 

When getting PV and PVC for every volume of every pod in [createVolumeSpec](https://github.com/kubernetes/kubernetes/blob/9d85e18ec0dc09f681650d04d65e3db5237bef96/pkg/kubelet/volumemanager/populator/desired_state_of_world_populator.go#L439), the function [getPVCExtractPV](https://github.com/kubernetes/kubernetes/blob/9d85e18ec0dc09f681650d04d65e3db5237bef96/pkg/kubelet/volumemanager/populator/desired_state_of_world_populator.go#L541) and [getPVSpec](https://github.com/kubernetes/kubernetes/blob/9d85e18ec0dc09f681650d04d65e3db5237bef96/pkg/kubelet/volumemanager/populator/desired_state_of_world_populator.go#L574) **directly get resource via connecting APIServer, which is time consuming when there are too much volumes and pods on node.**

In this specific node of our cluster, every request to APIServer consume 200ms; one volume needs to request for PV and PVC, i.e 400ms for every volume; there are 50 pvc type volumes mounted in one pod, i.e 20s for every pod, and there are 40 pods running in this node, i.e every loop needs 800s, nearly 13 mins.

Of course, this would only happen in the cluster when every pod mount lots of pvc type volume, but I think we could use pv/pvc informer here, to reduce time for this high frequency task.

### What did you expect to happen?

Newly created Pod Running quickly.

### How can we reproduce it (as minimally and precisely as possible)?

Create pod in cluster, where there are many pods with lots of pvc type volume mounted running.

### Anything else we need to know?

_No response_

### Kubernetes version

<details>

```console
$ kubectl version
Client Version: version.Info{Major:"1", Minor:"21+", GitVersion:"v1.21.6", GitCommit:"bebe216b204e80bebf57c1992e61e1857ff2a86d", GitTreeState:"clean", BuildDate:"2021-11-19T10:08:58Z", GoVersion:"go1.16.9", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"21+", GitVersion:"v1.21.6", GitCommit:"bebe216b204e80bebf57c1992e61e1857ff2a86d", GitTreeState:"clean", BuildDate:"2021-11-19T10:08:58Z", GoVersion:"go1.16.9", Compiler:"gc", Platform:"linux/amd64"}
You have new mail in /var/spool/mail/root
```

</details>


### Cloud provider

<details>

</details>


### OS version

<details>

```console
# On Linux:
$ cat /etc/os-release
NAME="CentOS Linux"
VERSION="7 (Core)"
ID="centos"
ID_LIKE="rhel fedora"
VERSION_ID="7"
PRETTY_NAME="CentOS Linux 7 (Core)"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:centos:centos:7"
HOME_URL="https://www.centos.org/"
BUG_REPORT_URL="https://bugs.centos.org/"

CENTOS_MANTISBT_PROJECT="CentOS-7"
CENTOS_MANTISBT_PROJECT_VERSION="7"
REDHAT_SUPPORT_PRODUCT="centos"
REDHAT_SUPPORT_PRODUCT_VERSION="7"
$ uname -a
Linux 3.10.0-957.el7.x86_64 #1 SMP Thu Nov 8 23:39:32 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

# On Windows:
C:\> wmic os get Caption, Version, BuildNumber, OSArchitecture
# paste output here
```

</details>


### Install tools

<details>

</details>


### Container runtime (CRI) and version (if applicable)

<details>

</details>


### Related plugins (CNI, CSI, ...) and versions (if applicable)

<details>

</details>