Only copy new or modified files into VM on restart #5864

priyawadhwa · 2019-11-07T19:48:49Z

When minikube restarts, we can save time by only copying over files that
have changes or don't exist in the VM. The code in this PR first checks
if the file already exists in the VM, and skips copying it over again if
it does.

Relevant logs on restart w/ this change:

I1107 13:47:50.618240  140681 ssh_runner.go:150] Skipping copying /usr/local/google/home/priyawadhwa/.minikube/cache/v1.16.2/kubeadm as it already exists
I1107 13:47:50.619329  140681 ssh_runner.go:150] Skipping copying /usr/local/google/home/priyawadhwa/.minikube/cache/v1.16.2/kubelet as it already exists
I1107 13:47:50.622824  140681 ssh_runner.go:167] Transferring 1146 bytes to /var/tmp/minikube/kubeadm.yaml
I1107 13:47:50.623198  140681 ssh_runner.go:186] kubeadm.yaml: copied 1146 bytes
I1107 13:47:50.634250  140681 ssh_runner.go:167] Transferring 561 bytes to /etc/systemd/system/kubelet.service.d/10-kubeadm.conf
I1107 13:47:50.634687  140681 ssh_runner.go:186] 10-kubeadm.conf: copied 561 bytes
I1107 13:47:50.646033  140681 ssh_runner.go:167] Transferring 349 bytes to /lib/systemd/system/kubelet.service
I1107 13:47:50.646465  140681 ssh_runner.go:186] kubelet.service: copied 349 bytes
I1107 13:47:50.658771  140681 ssh_runner.go:167] Transferring 1532 bytes to /etc/kubernetes/manifests/addon-manager.yaml.tmpl
I1107 13:47:50.659606  140681 ssh_runner.go:186] addon-manager.yaml.tmpl: copied 1532 bytes
I1107 13:47:50.672420  140681 ssh_runner.go:167] Transferring 1709 bytes to /etc/kubernetes/addons/storage-provisioner.yaml
I1107 13:47:50.673033  140681 ssh_runner.go:186] storage-provisioner.yaml: copied 1709 bytes
I1107 13:47:50.689584  140681 ssh_runner.go:167] Transferring 271 bytes to /etc/kubernetes/addons/storageclass.yaml
I1107 13:47:50.690156  140681 ssh_runner.go:186] storageclass.yaml: copied 271 bytes
I1107 13:47:50.700486  140681 ssh_runner.go:98] (SSHRunner) Run:  /bin/bash -c "sudo systemctl daemon-reload && sudo systemctl start kubelet"
I1107 13:47:50.783600  140681 certs.go:75] acquiring lock: {Name:setupCerts Clock:{} Delay:15s Timeout:0s Cancel:<nil>}
I1107 13:47:50.783780  140681 certs.go:83] Setting up /usr/local/google/home/priyawadhwa/.minikube for IP: 192.168.39.206
I1107 13:47:50.783902  140681 crypto.go:69] Generating cert /usr/local/google/home/priyawadhwa/.minikube/client.crt with IP's: []
I1107 13:47:50.789069  140681 crypto.go:157] Writing cert to /usr/local/google/home/priyawadhwa/.minikube/client.crt ...
I1107 13:47:50.789100  140681 lock.go:41] attempting to write to file "/usr/local/google/home/priyawadhwa/.minikube/client.crt" with filemode -rw-r--r--
I1107 13:47:50.789384  140681 crypto.go:165] Writing key to /usr/local/google/home/priyawadhwa/.minikube/client.key ...
I1107 13:47:50.789405  140681 lock.go:41] attempting to write to file "/usr/local/google/home/priyawadhwa/.minikube/client.key" with filemode -rw-------
I1107 13:47:50.789582  140681 crypto.go:69] Generating cert /usr/local/google/home/priyawadhwa/.minikube/apiserver.crt with IP's: [192.168.39.206 10.96.0.1 10.0.0.1]
I1107 13:47:50.793944  140681 crypto.go:157] Writing cert to /usr/local/google/home/priyawadhwa/.minikube/apiserver.crt ...
I1107 13:47:50.793971  140681 lock.go:41] attempting to write to file "/usr/local/google/home/priyawadhwa/.minikube/apiserver.crt" with filemode -rw-r--r--
I1107 13:47:50.794207  140681 crypto.go:165] Writing key to /usr/local/google/home/priyawadhwa/.minikube/apiserver.key ...
I1107 13:47:50.794227  140681 lock.go:41] attempting to write to file "/usr/local/google/home/priyawadhwa/.minikube/apiserver.key" with filemode -rw-------
I1107 13:47:50.794401  140681 crypto.go:69] Generating cert /usr/local/google/home/priyawadhwa/.minikube/proxy-client.crt with IP's: []
I1107 13:47:50.798704  140681 crypto.go:157] Writing cert to /usr/local/google/home/priyawadhwa/.minikube/proxy-client.crt ...
I1107 13:47:50.798732  140681 lock.go:41] attempting to write to file "/usr/local/google/home/priyawadhwa/.minikube/proxy-client.crt" with filemode -rw-r--r--
I1107 13:47:50.798954  140681 crypto.go:165] Writing key to /usr/local/google/home/priyawadhwa/.minikube/proxy-client.key ...
I1107 13:47:50.798974  140681 lock.go:41] attempting to write to file "/usr/local/google/home/priyawadhwa/.minikube/proxy-client.key" with filemode -rw-------
I1107 13:47:50.809628  140681 ssh_runner.go:150] Skipping copying /usr/local/google/home/priyawadhwa/.minikube/ca.crt as it already exists
I1107 13:47:50.816440  140681 ssh_runner.go:150] Skipping copying /usr/local/google/home/priyawadhwa/.minikube/ca.key as it already exists
I1107 13:47:50.827031  140681 ssh_runner.go:167] Transferring 1298 bytes to /var/lib/minikube/certs/apiserver.crt
I1107 13:47:50.827574  140681 ssh_runner.go:186] apiserver.crt: copied 1298 bytes
I1107 13:47:50.851183  140681 ssh_runner.go:167] Transferring 1675 bytes to /var/lib/minikube/certs/apiserver.key
I1107 13:47:50.851816  140681 ssh_runner.go:186] apiserver.key: copied 1675 bytes
I1107 13:47:50.866694  140681 ssh_runner.go:150] Skipping copying /usr/local/google/home/priyawadhwa/.minikube/proxy-client-ca.crt as it already exists
I1107 13:47:50.873270  140681 ssh_runner.go:150] Skipping copying /usr/local/google/home/priyawadhwa/.minikube/proxy-client-ca.key as it already exists
I1107 13:47:50.887705  140681 ssh_runner.go:167] Transferring 1103 bytes to /var/lib/minikube/certs/proxy-client.crt
I1107 13:47:50.888300  140681 ssh_runner.go:186] proxy-client.crt: copied 1103 bytes
I1107 13:47:50.903875  140681 ssh_runner.go:167] Transferring 1675 bytes to /var/lib/minikube/certs/proxy-client.key
I1107 13:47:50.906373  140681 ssh_runner.go:186] proxy-client.key: copied 1675 bytes
I1107 13:47:50.920302  140681 ssh_runner.go:167] Transferring 1066 bytes to /usr/share/ca-certificates/minikubeCA.pem
I1107 13:47:50.920692  140681 ssh_runner.go:186] minikubeCA.pem: copied 1066 bytes
I1107 13:47:50.939007  140681 ssh_runner.go:150] Skipping copying  as it already exists

Right now, mkcmp only tracks performance for minikube start after a minikube delete. I'll either update mkcmp to also look at restarts, or comment w/ timings from my local machine (this would be much faster).

k8s-ci-robot · 2019-11-07T19:49:28Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: priyawadhwa

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [priyawadhwa]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

codecov-io · 2019-11-07T19:54:54Z

Codecov Report

Merging #5864 into master will decrease coverage by 0.17%.
The diff coverage is 0%.

@@            Coverage Diff             @@
##           master    #5864      +/-   ##
==========================================
- Coverage    36.5%   36.32%   -0.18%     
==========================================
  Files         110      110              
  Lines        8123     8162      +39     
==========================================
  Hits         2965     2965              
- Misses       4769     4808      +39     
  Partials      389      389

Impacted Files	Coverage Δ
pkg/minikube/assets/vm_assets.go	`36.79% <0%> (-2.61%)`	⬇️
pkg/minikube/command/ssh_runner.go	`10.56% <0%> (-3.08%)`	⬇️

When minikube restarts, we can save time by only copying over files that have changes or don't exist in the VM. The code in this PR first checks if the file already exists in the VM, and skips copying it over again if it does.

tstromberg · 2019-11-08T05:33:27Z

/ok-to-test

pkg/minikube/command/ssh_runner.go

pkg/minikube/assets/vm_assets.go

pkg/minikube/command/ssh_runner.go

minikube-bot · 2019-11-08T06:08:34Z

Error: running mkcmp: exit status 1

Also, copy over the mtime correctly in Copy so that we can make sure they are equal in `sameFileExists`

minikube-bot · 2019-11-08T22:28:17Z

All Times minikube: [ 199.063633 206.319336 206.711071]
All Times Minikube (PR 5864): [ 217.402187 202.427218 206.215070]

Average minikube: 204.031347
Average Minikube (PR 5864): 208.681492

Averages Time Per Log

+------------------------+-----------+--------------------+
|          LOG           | MINIKUBE  | MINIKUBE (PR 5864) |
+------------------------+-----------+--------------------+
| minikube v             |  0.419475 |           0.392569 |
| Creating kvm2          | 52.588741 |          54.826816 |
| Preparing Kubernetes   | 54.989875 |          57.604280 |
| Pulling images         |  2.651087 |           3.324090 |
| Launching Kubernetes   | 20.966829 |          21.953813 |
| Waiting for: apiserver | 72.415339 |          70.579923 |
+------------------------+-----------+--------------------+

tstromberg

Nice! This PR appears to save 8-10 seconds off of a restart. Specifically, it makes live start 2X faster (8.87s vs 16.24s) and stopped 'start' about 10% faster (56s vs 65s)

tstromberg

Looks great!

pkg/minikube/assets/vm_assets.go

pkg/minikube/command/ssh_runner.go

priyawadhwa · 2019-11-11T19:40:59Z

Timed restart 3x on my Mac:

All Times master.minikube: [ 59.438086 57.969959 57.576127]
All Times copy-files.minikube: [ 56.711668 57.380655 57.444348]

Average master.minikube: 58.328057
Average copy-files.minikube: 57.178891

Averages Time Per Log

+--------------------------------+-----------------+---------------------+
|              LOG               | MASTER MINIKUBE | COPY-FILES MINIKUBE |
+--------------------------------+-----------------+---------------------+
| minikube v                     |        0.359189 |            0.389497 |
| Starting existing hyperkit VM  |        0.096348 |            0.096817 |
| Waiting for the host to be     |       36.863596 |           36.918882 |
| provisioned                    |                 |                     |
| Preparing Kubernetes           |        4.142760 |            2.356717 |
| Relaunching Kubernetes using   |       16.840471 |           17.394082 |
| kubeadm                        |                 |                     |
| Waiting for: apiserver         |        0.024143 |            0.021273 |
+--------------------------------+-----------------+---------------------+

minikube-bot · 2019-11-11T22:56:08Z

Error: building minikube at head: updating minikube master branch: running [git pull origin master] in /home/performance-monitor/minikube:
From https://github.com/kubernetes/minikube

branch master -> FETCH_HEAD
1d0ca6c..fb5430f master -> origin/master
error: Your local changes to the following files would be overwritten by merge:
go.mod
Please commit your changes or stash them before you merge.
Aborting
Updating 1d0ca6c..fb5430f
: exit status 1

tstromberg · 2019-11-12T06:17:17Z

/ok-to-test

tstromberg · 2019-11-13T06:21:26Z

Timed restart 3x on my Mac:

All Times master.minikube: [ 59.438086 57.969959 57.576127]
All Times copy-files.minikube: [ 56.711668 57.380655 57.444348]

Average master.minikube: 58.328057
Average copy-files.minikube: 57.178891

Averages Time Per Log

+--------------------------------+-----------------+---------------------+
|              LOG               | MASTER MINIKUBE | COPY-FILES MINIKUBE |
+--------------------------------+-----------------+---------------------+
| minikube v                     |        0.359189 |            0.389497 |
| Starting existing hyperkit VM  |        0.096348 |            0.096817 |
| Waiting for the host to be     |       36.863596 |           36.918882 |
| provisioned                    |                 |                     |
| Preparing Kubernetes           |        4.142760 |            2.356717 |
| Relaunching Kubernetes using   |       16.840471 |           17.394082 |
| kubeadm                        |                 |                     |
| Waiting for: apiserver         |        0.024143 |            0.021273 |
+--------------------------------+-----------------+---------------------+

I believe the reason you aren't seeing the performance increase is because LoadImages is run as a background thread, and in many cases, won't block as the apiserver takes longer than it to become healthy.

I did some reading through the logs though, and your PR has a dramatic 7X improvement for LoadImages: 23s vs 3s. This only works if the previous run of minikube start was from this PR rather than head, as the mtime may be different.

Anyways, this appears to work really well. Next step for this sort of improvement: see if we can skip loading the image if the cached hash matches what the remote container runtime has already.

tstromberg · 2019-11-13T07:21:11Z

/ok-to-test

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Nov 7, 2019

k8s-ci-robot requested review from medyagh and RA489 November 7, 2019 19:49

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Nov 7, 2019

priyawadhwa force-pushed the copy-files branch from e958862 to a2e123b Compare November 7, 2019 19:51

priyawadhwa force-pushed the copy-files branch 2 times, most recently from 76b81bc to 822a336 Compare November 7, 2019 21:03

Only copy new or modified files into VM on restart

38823e9

When minikube restarts, we can save time by only copying over files that have changes or don't exist in the VM. The code in this PR first checks if the file already exists in the VM, and skips copying it over again if it does.

priyawadhwa force-pushed the copy-files branch from 822a336 to 38823e9 Compare November 7, 2019 21:46

k8s-ci-robot added the ok-to-test Indicates a non-member PR verified by an org member that is safe to test. label Nov 8, 2019

tstromberg reviewed Nov 8, 2019

View reviewed changes

pkg/minikube/command/ssh_runner.go Outdated Show resolved Hide resolved

tstromberg suggested changes Nov 8, 2019

View reviewed changes

Check for file size and mtime at the same time

006b802

Also, copy over the mtime correctly in Copy so that we can make sure they are equal in `sameFileExists`

priyawadhwa requested a review from tstromberg November 8, 2019 22:09

tstromberg reviewed Nov 8, 2019

View reviewed changes

tstromberg suggested changes Nov 8, 2019

View reviewed changes

Simplify command to get size and modtime

e9d2126

priyawadhwa requested a review from tstromberg November 11, 2019 22:29

tstromberg merged commit 484fdcc into kubernetes:master Nov 13, 2019

tstromberg mentioned this pull request Nov 15, 2019

Update changelog for v1.6.0-beta.0 release #5929

Merged

priyawadhwa deleted the copy-files branch February 24, 2020 18:58

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Only copy new or modified files into VM on restart #5864

Only copy new or modified files into VM on restart #5864

priyawadhwa commented Nov 7, 2019 •

edited

Loading

k8s-ci-robot commented Nov 7, 2019

codecov-io commented Nov 7, 2019 •

edited

Loading

tstromberg commented Nov 8, 2019

minikube-bot commented Nov 8, 2019

minikube-bot commented Nov 8, 2019

tstromberg left a comment

tstromberg left a comment

priyawadhwa commented Nov 11, 2019

minikube-bot commented Nov 11, 2019

tstromberg commented Nov 12, 2019

tstromberg commented Nov 13, 2019

tstromberg commented Nov 13, 2019

Only copy new or modified files into VM on restart #5864

Only copy new or modified files into VM on restart #5864

Conversation

priyawadhwa commented Nov 7, 2019 • edited Loading

k8s-ci-robot commented Nov 7, 2019

codecov-io commented Nov 7, 2019 • edited Loading

Codecov Report

tstromberg commented Nov 8, 2019

minikube-bot commented Nov 8, 2019

minikube-bot commented Nov 8, 2019

tstromberg left a comment

Choose a reason for hiding this comment

tstromberg left a comment

Choose a reason for hiding this comment

priyawadhwa commented Nov 11, 2019

minikube-bot commented Nov 11, 2019

tstromberg commented Nov 12, 2019

tstromberg commented Nov 13, 2019

tstromberg commented Nov 13, 2019

priyawadhwa commented Nov 7, 2019 •

edited

Loading

codecov-io commented Nov 7, 2019 •

edited

Loading