cache add: load images to all profiles & skip previously cached images #5987

medyagh · 2019-11-27T02:35:11Z

before this PR as described in this bug: #5974

minikube cache add would only load images into the current profile (minikube) and other profiles had to be restarted to pick up the cache.

skip re-copy existing images if image name with same sha exists on the node.
added integration tests for (cache add, cache delete and cache list, and check image loaded inside node)
choose smaller images for in integration tests ( 6 mb instead of 655 mb)
clean up the temporary files
refactor config.Load make profile Name mandatory for config.Load
refactor cluster package to move machine to machine package (to avoid cyclic

Future PRs:

do loading in parallel loading into multi profiles
decucple logic from cluster and machine packages

k8s-ci-robot · 2019-11-27T02:35:37Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: medyagh

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~~ [medyagh]

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-27T04:14:19Z

Codecov Report

Merging #5987 into master will decrease coverage by 0.02%.
The diff coverage is 7.07%.

@@            Coverage Diff             @@
##           master    #5987      +/-   ##
==========================================
- Coverage   36.18%   36.15%   -0.03%     
==========================================
  Files         110      110              
  Lines        8214     8281      +67     
==========================================
+ Hits         2972     2994      +22     
- Misses       4851     4886      +35     
- Partials      391      401      +10

Impacted Files	Coverage Δ
pkg/minikube/cruntime/cruntime.go	`63.63% <ø> (ø)`	⬆️
pkg/minikube/bootstrapper/bootstrapper.go	`0% <ø> (ø)`	⬆️
pkg/minikube/cruntime/containerd.go	`46.59% <0%> (-2.81%)`	⬇️
cmd/minikube/cmd/config/validations.go	`39.43% <0%> (ø)`	⬆️
cmd/minikube/cmd/ssh.go	`8.69% <0%> (ø)`	⬆️
cmd/minikube/cmd/mount.go	`8.33% <0%> (ø)`	⬆️
cmd/minikube/cmd/dashboard.go	`1.76% <0%> (ø)`	⬆️
pkg/minikube/cruntime/crio.go	`41.09% <0%> (-5.06%)`	⬇️
cmd/minikube/cmd/env.go	`50.6% <0%> (ø)`	⬆️
pkg/minikube/config/config.go	`65.38% <0%> (+1.23%)`	⬆️
... and 20 more

test/integration/functional_test.go

nanikjava · 2019-11-27T21:40:46Z

The fix works as tested on local machine.

medyagh · 2019-12-04T22:54:25Z

/ok-to-test

minikube-bot · 2019-12-04T23:26:35Z

Error: running mkcmp: exit status 1

cmd/minikube/cmd/delete_test.go

pkg/minikube/config/config.go

pkg/minikube/machine/cache_images.go

minikube-bot · 2019-12-09T22:52:57Z

All Times Minikube (PR 5987): [ 146.077671 145.244935 146.165283]
All Times minikube: [ 143.759496 145.707343 146.005310]

Average minikube: 145.157383
Average Minikube (PR 5987): 145.829297

Averages Time Per Log

+----------------------+-----------+--------------------+
|         LOG          | MINIKUBE  | MINIKUBE (PR 5987) |
+----------------------+-----------+--------------------+
| minikube v           |  0.349590 |           0.353740 |
| Creating kvm2        | 50.029862 |          50.622646 |
| Preparing Kubernetes | 52.264951 |          53.083970 |
| Pulling images       | 17.568921 |          18.152932 |
| Launching Kubernetes | 21.981844 |          20.621826 |
| Waiting for cluster  |  2.909338 |           2.941449 |
+----------------------+-----------+--------------------+

medyagh · 2019-12-10T00:31:08Z

Shamefully after I added the ImageExist() ! this PR actually became 4 seconds slower when I do minikube cache add !
it seems that the expensive part is getting the image sha from the User Host.
which means in the old way as long as we had an image with a name on the host and we had same image name in the VM, that would be enough ! (didn't check the SHA)

but I believe this will be needed for iterative development, if users that build same image name and tag and wanna add that to minikube

here is logs from minikube 1.5.2 cache add ubuntu

medya@~/workspace/minikube (cache_fix2) $ time minikube cache add ubuntu --alsologtostderr I1209 16:25:28.663164 73421 cache_images.go:296] CacheImage: ubuntu -> /Users/medya/.minikube/cache/images/ubuntu I1209 16:25:28.663195 73421 cache_images.go:302] /Users/medya/.minikube/cache/images/ubuntu exists I1209 16:25:28.663208 73421 cache_images.go:298] CacheImage: ubuntu -> /Users/medya/.minikube/cache/images/ubuntu completed in 77.063µs I1209 16:25:28.663220 73421 cache_images.go:83] CacheImage ubuntu -> /Users/medya/.minikube/cache/images/ubuntu succeeded I1209 16:25:28.663230 73421 cache_images.go:90] Successfully cached all images. I1209 16:25:28.663826 73421 main.go:110] libmachine: Found binary path at /Users/medya/.minikube/bin/docker-machine-driver-hyperkit I1209 16:25:28.663940 73421 main.go:110] libmachine: Launching plugin server for driver hyperkit I1209 16:25:28.685149 73421 main.go:110] libmachine: Plugin server listening at address 127.0.0.1:50965 I1209 16:25:28.685850 73421 main.go:110] libmachine: () Calling .GetVersion I1209 16:25:28.686520 73421 main.go:110] libmachine: Using API Version 1 I1209 16:25:28.686545 73421 main.go:110] libmachine: () Calling .SetConfigRaw I1209 16:25:28.686939 73421 main.go:110] libmachine: () Calling .GetMachineName I1209 16:25:28.687097 73421 main.go:110] libmachine: (minikube) Calling .DriverName I1209 16:25:28.687238 73421 main.go:110] libmachine: (minikube) Calling .GetSSHHostname I1209 16:25:28.687372 73421 main.go:110] libmachine: (minikube) Calling .GetSSHPort I1209 16:25:28.687484 73421 main.go:110] libmachine: (minikube) Calling .GetSSHKeyPath I1209 16:25:28.687606 73421 main.go:110] libmachine: (minikube) Calling .GetSSHUsername I1209 16:25:28.734769 73421 cache_images.go:96] LoadImages start: [ubuntu] I1209 16:25:28.735219 73421 cache_images.go:211] Loading image from cache: /Users/medya/.minikube/cache/images/ubuntu I1209 16:25:28.736645 73421 ssh_runner.go:160] Transferring 29619712 bytes to /var/lib/minikube/images/ubuntu I1209 16:25:28.938606 73421 ssh_runner.go:179] ubuntu: copied 29619712 bytes I1209 16:25:28.942601 73421 docker.go:107] Loading image: /var/lib/minikube/images/ubuntu I1209 16:25:28.942812 73421 ssh_runner.go:96] (SSHRunner) Run: docker load -i /var/lib/minikube/images/ubuntu I1209 16:25:29.072987 73421 cache_images.go:237] Successfully loaded image /Users/medya/.minikube/cache/images/ubuntu from cache I1209 16:25:29.073025 73421 cache_images.go:120] Successfully loaded all cached images. I1209 16:25:29.073030 73421 cache_images.go:121] LoadImages end I1209 16:25:29.073081 73421 main.go:110] libmachine: Making call to close driver server I1209 16:25:29.073095 73421 main.go:110] libmachine: (minikube) Calling .Close I1209 16:25:29.073413 73421 main.go:110] libmachine: (minikube) DBG | Closing plugin on server side I1209 16:25:29.073448 73421 main.go:110] libmachine: Successfully made call to close driver server I1209 16:25:29.073468 73421 main.go:110] libmachine: Making call to close connection to plugin binary
real 0m0.499s
user 0m0.109s
sys 0m0.214s

and logs fro my PR

medya@~/workspace/minikube (cache_fix2) $ time ./out/minikube cache add ubuntu --alsologtostderr I1209 16:25:40.872715 73447 cache_images.go:335] CacheImage: ubuntu -> /Users/medya/.minikube/cache/images/ubuntu I1209 16:25:40.872739 73447 cache_images.go:341] /Users/medya/.minikube/cache/images/ubuntu exists I1209 16:25:40.872745 73447 cache_images.go:337] CacheImage: ubuntu -> /Users/medya/.minikube/cache/images/ubuntu completed in 55.642µs I1209 16:25:40.872757 73447 cache_images.go:85] CacheImage ubuntu -> /Users/medya/.minikube/cache/images/ubuntu succeeded I1209 16:25:40.872768 73447 cache_images.go:92] Successfully cached all images. I1209 16:25:40.873531 73447 main.go:110] libmachine: Found binary path at /Users/medya/.minikube/bin/docker-machine-driver-hyperkit I1209 16:25:40.873595 73447 main.go:110] libmachine: Launching plugin server for driver hyperkit I1209 16:25:40.891326 73447 main.go:110] libmachine: Plugin server listening at address 127.0.0.1:50975 I1209 16:25:40.892515 73447 main.go:110] libmachine: () Calling .GetVersion I1209 16:25:40.893647 73447 main.go:110] libmachine: Using API Version 1 I1209 16:25:40.893674 73447 main.go:110] libmachine: () Calling .SetConfigRaw I1209 16:25:40.894065 73447 main.go:110] libmachine: () Calling .GetMachineName I1209 16:25:40.894413 73447 main.go:110] libmachine: (minikube) Calling .GetState I1209 16:25:40.894678 73447 main.go:110] libmachine: (minikube) DBG | exe=/Users/medya/.minikube/bin/docker-machine-driver-hyperkit uid=0 I1209 16:25:40.895206 73447 main.go:110] libmachine: (minikube) DBG | hyperkit pid from json: 71959 I1209 16:25:40.897253 73447 main.go:110] libmachine: Found binary path at /Users/medya/.minikube/bin/docker-machine-driver-hyperkit I1209 16:25:40.897314 73447 main.go:110] libmachine: Launching plugin server for driver hyperkit I1209 16:25:40.913314 73447 main.go:110] libmachine: Plugin server listening at address 127.0.0.1:50981 I1209 16:25:40.914393 73447 main.go:110] libmachine: () Calling .GetVersion I1209 16:25:40.914984 73447 main.go:110] libmachine: Using API Version 1 I1209 16:25:40.915005 73447 main.go:110] libmachine: () Calling .SetConfigRaw I1209 16:25:40.915324 73447 main.go:110] libmachine: () Calling .GetMachineName I1209 16:25:40.915443 73447 main.go:110] libmachine: (minikube) Calling .DriverName I1209 16:25:40.915586 73447 main.go:110] libmachine: (minikube) Calling .GetSSHHostname I1209 16:25:40.915702 73447 main.go:110] libmachine: (minikube) Calling .GetSSHPort I1209 16:25:40.915795 73447 main.go:110] libmachine: (minikube) Calling .GetSSHKeyPath I1209 16:25:40.915920 73447 main.go:110] libmachine: (minikube) Calling .GetSSHUsername I1209 16:25:40.961382 73447 cache_images.go:98] LoadImages start: [ubuntu] I1209 16:25:40.961456 73447 cache_images.go:396] retrieving image: index.docker.io/library/ubuntu:latest I1209 16:25:42.608673 73447 cache_images.go:399] found index.docker.io/library/ubuntu:latest locally; caching I1209 16:25:44.493066 73447 ssh_runner.go:102] Run: docker inspect --format='{{.Id}}' ubuntu I1209 16:25:44.517507 73447 cache_images.go:248] skipping re-loading image "ubuntu" because sha "775349758637aff77bf85e2ff0597e86e3e859183ef0baba8b3e8fc8d3cba51c" already exists I1209 16:25:44.517534 73447 cache_images.go:114] Successfully loaded all cached images. I1209 16:25:44.517538 73447 cache_images.go:115] LoadImages end I1209 16:25:44.517563 73447 main.go:110] libmachine: Making call to close driver server I1209 16:25:44.517572 73447 main.go:110] libmachine: (minikube) Calling .Close I1209 16:25:44.517787 73447 main.go:110] libmachine: (minikube) DBG | Closing plugin on server side I1209 16:25:44.517816 73447 main.go:110] libmachine: Successfully made call to close driver server I1209 16:25:44.517829 73447 main.go:110] libmachine: Making call to close connection to plugin binary I1209 16:25:44.517839 73447 main.go:110] libmachine: Making call to close driver server I1209 16:25:44.517865 73447 main.go:110] libmachine: (minikube) Calling .Close I1209 16:25:44.518032 73447 main.go:110] libmachine: (minikube) DBG | Closing plugin on server side I1209 16:25:44.518073 73447 main.go:110] libmachine: Successfully made call to close driver server I1209 16:25:44.518093 73447 main.go:110] libmachine: Making call to close connection to plugin binary real 0m3.765s user 0m2.222s sys 0m0.785s

minikube-bot · 2019-12-10T18:50:56Z

All Times minikube: [ 145.500571 146.254375 145.847824]
All Times Minikube (PR 5987): [ 143.075956 140.595136 142.383854]

Average minikube: 145.867590
Average Minikube (PR 5987): 142.018315

Averages Time Per Log

+----------------------+-----------+--------------------+
|         LOG          | MINIKUBE  | MINIKUBE (PR 5987) |
+----------------------+-----------+--------------------+
| minikube v           |  0.366954 |           0.349126 |
| Creating kvm2        | 49.514362 |          48.066793 |
| Preparing Kubernetes | 55.603367 |          51.876809 |
| Pulling images       | 17.628895 |          18.172625 |
| Launching Kubernetes | 19.959421 |          21.099292 |
| Waiting for cluster  |  2.743355 |           2.402922 |
+----------------------+-----------+--------------------+

medyagh · 2019-12-10T19:12:36Z

Update: I believe I fixed the performance issue of getting image sha.
and now a re-start minikube takes 18 seconds less !

there is still room for 3s improvement on cache, if we use docker cli, I created an issue here google/go-containerregistry#627


-----------------------------------THIS PR------------------------------------------------------
medya@~/workspace/minikube (cache_fix2) $ time ./out/minikube start 
real    2m6.519s
user    0m7.788s
sys     0m8.187s
medya@~/workspace/minikube (cache_fix2) $ time ./out/minikube start 
real    0m7.614s
user    0m1.162s
sys     0m0.909s
medya@~/workspace/minikube (cache_fix2) $ time ./out/minikube stop
real    0m8.193s
user    0m0.087s
sys     0m0.094s
medya@~/workspace/minikube (cache_fix2) $ time ./out/minikube start
real    0m56.333s
user    0m1.084s
sys     0m0.887s

-----------------------------------HEAD------------------------------------------------------
 $ ./out/minikube delete --all --purge

$ time ./out/minikube start 
real    2m23.678s
user    0m9.359s
sys     0m10.000s


medya@~/workspace/minikube (master) $ time ./out/minikube start 
real    0m9.885s
user    0m0.670s
sys     0m0.446s

medya@~/workspace/minikube (master) $ time ./out/minikube stop
real    0m8.228s
user    0m0.087s
sys     0m0.109s

$ time ./out/minikube start
real    1m14.063s
user    0m0.555s
sys     0m0.467s

minikube-bot · 2019-12-10T19:41:07Z

All Times minikube: [ 151.845473 153.206847 150.546376]
All Times Minikube (PR 5987): [ 155.359390 153.692005 151.795843]

Average minikube: 151.866232
Average Minikube (PR 5987): 153.615746

Averages Time Per Log

+----------------------+-----------+--------------------+
|         LOG          | MINIKUBE  | MINIKUBE (PR 5987) |
+----------------------+-----------+--------------------+
| minikube v           |  0.358817 |           0.373533 |
| Creating kvm2        | 51.699864 |          53.926456 |
| Preparing Kubernetes | 56.688268 |          57.230720 |
| Pulling images       | 18.266935 |          18.553208 |
| Launching Kubernetes | 22.059831 |          20.555701 |
| Waiting for cluster  |  2.739274 |           2.922809 |
+----------------------+-----------+--------------------+

tstromberg

Please change the title to mention the behavioral change, as it will show up in the release notes.

minikube-bot · 2019-12-10T20:37:23Z

All Times minikube: [ 153.221096 151.958725 157.419655]
All Times Minikube (PR 5987): [ 154.240608 152.824335 160.182547]

Average minikube: 154.199825
Average Minikube (PR 5987): 155.749163

Averages Time Per Log

+----------------------+-----------+--------------------+
|         LOG          | MINIKUBE  | MINIKUBE (PR 5987) |
+----------------------+-----------+--------------------+
| minikube v           |  0.380745 |           0.377667 |
| Creating kvm2        | 54.367220 |          54.116999 |
| Preparing Kubernetes | 54.827068 |          57.978696 |
| Pulling images       | 18.296186 |          19.165901 |
| Launching Kubernetes | 22.308415 |          20.942441 |
| Waiting for cluster  |  3.100516 |           3.113201 |
+----------------------+-----------+--------------------+

medyagh added 5 commits November 26, 2019 16:08

add integrationn tests for cache

63868db

organize cache functional test

71857f4

clean up temp files

72b1743

remove cyclic depdenecy and make cluster pkg smaller

6c08fed

refactor config to allow load profile config

cdb68a1

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

k8s-ci-robot requested review from afbjorklund and tstromberg November 27, 2019 02:35

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

fix typo and remove debugging logs

d8d7849

medyagh changed the title ~~fix minikube cache add~~ fix and improve minikube cache add Nov 27, 2019

medyagh mentioned this pull request Nov 27, 2019

wip: Improve minikube cache #5975

Closed

fix unit tests and improve naming

d7b6e66

nanikjava reviewed Nov 27, 2019

View reviewed changes

test/integration/functional_test.go Show resolved Hide resolved

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

tstromberg suggested changes Dec 9, 2019

View reviewed changes

cmd/minikube/cmd/delete_test.go Outdated Show resolved Hide resolved

pkg/minikube/config/config.go Outdated Show resolved Hide resolved

pkg/minikube/machine/cache_images.go Show resolved Hide resolved

medyagh added 3 commits December 9, 2019 14:30

Skip loading image if already cached based on sha

2895971

make profile name mandatory for config.Load

35ad8e2

move machine path to localpath package

6034682

Use a faster way to get image sha

b7176b9

This was referenced Dec 10, 2019

getting image ID (sha) takes longer than docker cli google/go-containerregistry#627

Closed

Performance Test: measure start a stopped minikube #6040

Closed

lint

7b8cfe1

tstromberg approved these changes Dec 10, 2019

View reviewed changes

medyagh changed the title ~~fix and improve minikube cache add~~ improve "cache add" to load images to all profiles if already loaded based on Image SHA Dec 10, 2019

medyagh changed the title ~~improve "cache add" to load images to all profiles if already loaded based on Image SHA~~ improve "cache add" to load images and skip already cached based on image sha. Dec 10, 2019

medyagh changed the title ~~improve "cache add" to load images and skip already cached based on image sha.~~ Change "cache add" to load images to all running profiles and skip already cached based on image sha. Dec 10, 2019

fix integration test logic for cache

b49425d

tstromberg changed the title ~~Change "cache add" to load images to all running profiles and skip already cached based on image sha.~~ cache add: load images to all profiles & skip previously cached images Dec 10, 2019

tstromberg merged commit 349f414 into kubernetes:master Dec 10, 2019

medyagh deleted the cache_fix2 branch December 10, 2019 22:00

tstromberg mentioned this pull request Dec 17, 2019

offline support broken: LoadImages makes HTTPS queries #6103

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cache add: load images to all profiles & skip previously cached images #5987

cache add: load images to all profiles & skip previously cached images #5987

medyagh commented Nov 27, 2019 •

edited

Loading

k8s-ci-robot commented Nov 27, 2019

codecov-io commented Nov 27, 2019 •

edited

Loading

nanikjava commented Nov 27, 2019

medyagh commented Dec 4, 2019

minikube-bot commented Dec 4, 2019

minikube-bot commented Dec 9, 2019

medyagh commented Dec 10, 2019 •

edited

Loading

minikube-bot commented Dec 10, 2019

medyagh commented Dec 10, 2019 •

edited

Loading

minikube-bot commented Dec 10, 2019

tstromberg left a comment

minikube-bot commented Dec 10, 2019

cache add: load images to all profiles & skip previously cached images #5987

cache add: load images to all profiles & skip previously cached images #5987

Conversation

medyagh commented Nov 27, 2019 • edited Loading

k8s-ci-robot commented Nov 27, 2019

codecov-io commented Nov 27, 2019 • edited Loading

Codecov Report

nanikjava commented Nov 27, 2019

medyagh commented Dec 4, 2019

minikube-bot commented Dec 4, 2019

minikube-bot commented Dec 9, 2019

medyagh commented Dec 10, 2019 • edited Loading

minikube-bot commented Dec 10, 2019

medyagh commented Dec 10, 2019 • edited Loading

minikube-bot commented Dec 10, 2019

tstromberg left a comment

Choose a reason for hiding this comment

minikube-bot commented Dec 10, 2019

medyagh commented Nov 27, 2019 •

edited

Loading

codecov-io commented Nov 27, 2019 •

edited

Loading

medyagh commented Dec 10, 2019 •

edited

Loading

medyagh commented Dec 10, 2019 •

edited

Loading