Performance degradation in minikube profile list between 1.13.1 and 1.14.0

[kschaab]

Run minikube profile list --output json
This is taking .218s on my machine with v1.13.1 and 2:31.77 with v1.14.0. This seems to be because minikube is attempting to ssh into each VM in series and times out:

I1026 10:03:10.269184   57548 sshutil.go:44] new ssh client: &{IP:192.168.64.8 Port:22 SSHKeyPath:/Users/keithsc/.minikube/machines/minikube/id_rsa Username:docker}
W1026 10:04:26.073314   57548 sshutil.go:55] dial failure (will retry): dial tcp 192.168.64.8:22: connect: operation timed out
W1026 10:04:26.073485   57548 api_server.go:150] stopped: unable to get apiserver pid: NewSession: new client: new client: dial tcp 192.168.64.8:22: connect: operation timed out

Full logs:

❯ time /Users/keithsc/Library/Application\ Support/cloud-code/installer/google-cloud-sdk/bin/minikube profile list --alsologtostderr
I1026 10:03:09.818467   57548 cli_runner.go:110] Run: docker ps -a --filter label=name.minikube.sigs.k8s.io --format {{.Names}}
I1026 10:03:10.160527   57548 host.go:65] Checking if "cloud-code-minikube" exists ...
I1026 10:03:10.161294   57548 cli_runner.go:110] Run: docker container inspect -f "'{{(index (index .NetworkSettings.Ports "8443/tcp") 0).HostPort}}'" cloud-code-minikube
W1026 10:03:10.209357   57548 cli_runner.go:148] docker container inspect -f "'{{(index (index .NetworkSettings.Ports "8443/tcp") 0).HostPort}}'" cloud-code-minikube returned with exit code 1
W1026 10:03:10.209965   57548 profile_list.go:107] error loading profiles: get port 8443 for "cloud-code-minikube": docker container inspect -f "'{{(index (index .NetworkSettings.Ports "8443/tcp") 0).HostPort}}'" cloud-code-minikube: exit status 1
stdout:


stderr:
Template parsing error: template: :1:4: executing "" at <index (index .NetworkSettings.Ports "8443/tcp") 0>: error calling index: index of untyped nil
I1026 10:03:10.209992   57548 host.go:65] Checking if "cloud-run-dev-internal" exists ...
I1026 10:03:10.210566   57548 cli_runner.go:110] Run: docker container inspect -f "'{{(index (index .NetworkSettings.Ports "8443/tcp") 0).HostPort}}'" cloud-run-dev-internal
W1026 10:03:10.252118   57548 cli_runner.go:148] docker container inspect -f "'{{(index (index .NetworkSettings.Ports "8443/tcp") 0).HostPort}}'" cloud-run-dev-internal returned with exit code 1
W1026 10:03:10.252199   57548 profile_list.go:107] error loading profiles: get port 8443 for "cloud-run-dev-internal": docker container inspect -f "'{{(index (index .NetworkSettings.Ports "8443/tcp") 0).HostPort}}'" cloud-run-dev-internal: exit status 1
stdout:


stderr:
Template parsing error: template: :1:4: executing "" at <index (index .NetworkSettings.Ports "8443/tcp") 0>: error calling index: index of untyped nil
I1026 10:03:10.252227   57548 host.go:65] Checking if "minikube" exists ...
I1026 10:03:10.253104   57548 main.go:118] libmachine: Found binary path at /Users/keithsc/.minikube/bin/docker-machine-driver-hyperkit
I1026 10:03:10.253197   57548 main.go:118] libmachine: Launching plugin server for driver hyperkit
I1026 10:03:10.265887   57548 main.go:118] libmachine: Plugin server listening at address 127.0.0.1:51876
I1026 10:03:10.266885   57548 main.go:118] libmachine: () Calling .GetVersion
I1026 10:03:10.267696   57548 main.go:118] libmachine: Using API Version  1
I1026 10:03:10.267725   57548 main.go:118] libmachine: () Calling .SetConfigRaw
I1026 10:03:10.268195   57548 main.go:118] libmachine: () Calling .GetMachineName
I1026 10:03:10.268370   57548 main.go:118] libmachine: (minikube) Calling .DriverName
I1026 10:03:10.268518   57548 api_server.go:146] Checking apiserver status ...
I1026 10:03:10.268627   57548 ssh_runner.go:148] Run: sudo pgrep -xnf kube-apiserver.*minikube.*
I1026 10:03:10.268654   57548 main.go:118] libmachine: (minikube) Calling .GetSSHHostname
I1026 10:03:10.268785   57548 main.go:118] libmachine: (minikube) Calling .GetSSHPort
I1026 10:03:10.268908   57548 main.go:118] libmachine: (minikube) Calling .GetSSHKeyPath
I1026 10:03:10.269056   57548 main.go:118] libmachine: (minikube) Calling .GetSSHUsername
I1026 10:03:10.269184   57548 sshutil.go:44] new ssh client: &{IP:192.168.64.8 Port:22 SSHKeyPath:/Users/keithsc/.minikube/machines/minikube/id_rsa Username:docker}
W1026 10:04:26.073314   57548 sshutil.go:55] dial failure (will retry): dial tcp 192.168.64.8:22: connect: operation timed out
W1026 10:04:26.073485   57548 api_server.go:150] stopped: unable to get apiserver pid: NewSession: new client: new client: dial tcp 192.168.64.8:22: connect: operation timed out
I1026 10:04:26.073573   57548 host.go:65] Checking if "test-no-context" exists ...
I1026 10:04:26.074522   57548 main.go:118] libmachine: Found binary path at /Users/keithsc/.minikube/bin/docker-machine-driver-hyperkit
I1026 10:04:26.074601   57548 main.go:118] libmachine: Launching plugin server for driver hyperkit
I1026 10:04:26.091884   57548 main.go:118] libmachine: Plugin server listening at address 127.0.0.1:51990
I1026 10:04:26.092956   57548 main.go:118] libmachine: () Calling .GetVersion
I1026 10:04:26.093820   57548 main.go:118] libmachine: Using API Version  1
I1026 10:04:26.093847   57548 main.go:118] libmachine: () Calling .SetConfigRaw
I1026 10:04:26.094227   57548 main.go:118] libmachine: () Calling .GetMachineName
I1026 10:04:26.094432   57548 main.go:118] libmachine: (test-no-context) Calling .DriverName
I1026 10:04:26.094622   57548 api_server.go:146] Checking apiserver status ...
I1026 10:04:26.100334   57548 ssh_runner.go:148] Run: sudo pgrep -xnf kube-apiserver.*minikube.*
I1026 10:04:26.100379   57548 main.go:118] libmachine: (test-no-context) Calling .GetSSHHostname
I1026 10:04:26.100626   57548 main.go:118] libmachine: (test-no-context) Calling .GetSSHPort
I1026 10:04:26.100807   57548 main.go:118] libmachine: (test-no-context) Calling .GetSSHKeyPath
I1026 10:04:26.100947   57548 main.go:118] libmachine: (test-no-context) Calling .GetSSHUsername
I1026 10:04:26.101090   57548 sshutil.go:44] new ssh client: &{IP:192.168.64.6 Port:22 SSHKeyPath:/Users/keithsc/.minikube/machines/test-no-context/id_rsa Username:docker}
W1026 10:05:41.801226   57548 sshutil.go:55] dial failure (will retry): dial tcp 192.168.64.6:22: connect: operation timed out
W1026 10:05:41.801312   57548 api_server.go:150] stopped: unable to get apiserver pid: NewSession: new client: new client: dial tcp 192.168.64.6:22: connect: operation timed out
I1026 10:05:41.801392   57548 main.go:118] libmachine: Making call to close driver server
I1026 10:05:41.801450   57548 main.go:118] libmachine: (minikube) Calling .Close
I1026 10:05:41.801732   57548 main.go:118] libmachine: Successfully made call to close driver server
I1026 10:05:41.801755   57548 main.go:118] libmachine: Making call to close connection to plugin binary
I1026 10:05:41.801790   57548 main.go:118] libmachine: (minikube) DBG | Closing plugin on server side
I1026 10:05:41.801792   57548 main.go:118] libmachine: Making call to close driver server
I1026 10:05:41.801817   57548 main.go:118] libmachine: (test-no-context) Calling .Close
I1026 10:05:41.802097   57548 main.go:118] libmachine: (test-no-context) DBG | Closing plugin on server side
I1026 10:05:41.802110   57548 main.go:118] libmachine: Successfully made call to close driver server
I1026 10:05:41.802124   57548 main.go:118] libmachine: Making call to close connection to plugin binary
|------------------------|-----------|---------|--------------|------|---------|---------|
|        Profile         | VM Driver | Runtime |      IP      | Port | Version | Status  |
|------------------------|-----------|---------|--------------|------|---------|---------|
| cloud-code-minikube    | docker    | docker  | 172.17.0.2   | 8443 | v1.18.3 | Unknown |
| cloud-run-dev-internal | docker    | docker  | 192.168.49.2 | 8443 | v1.19.2 | Unknown |
| minikube               | hyperkit  | docker  | 192.168.64.8 | 8443 | v1.17.3 | Stopped |
| test-no-context        | hyperkit  | docker  | 192.168.64.6 | 8443 | v1.18.0 | Stopped |
|------------------------|-----------|---------|--------------|------|---------|---------|
 profile list --alsologtostderr  0.19s user 0.20s system 0% cpu 2:32.04 total

[kschaab]

Timing for docker info docker info 0.06s user 0.18s system 36% cpu 0.662 total
Timing for v1.14.1 ~/Downloads/minikube-darwin-amd64 profile list 0.18s user 0.12s system 0% cpu 2:32.25 total

[medyagh]

do you mind checking if this problem exist with latest version v1.14.1 ?

[kschaab]

@medyagh timing for v1.14.1 is above. It still reproduces.

[medyagh]

btw I noticed you have 4 kuberentes clusters,
and two of them are docker, do you mind sharing, how big is your Docker Desktop allocated memory ? in Docker Desktop , Settings, Resources ?

[tstromberg]

This issue appears to be a duplicate of #9553, do you mind if we move the conversation there?

Ths way we can centralize the content relating to the issue. If you feel that this issue is not in fact a duplicate, please re-open it using /reopen. If you have additional information to share, please add it to the new issue.

Thank you for reporting this!