Batch logs output to speedup `minikube logs` command #11274

spowelljr · 2021-05-04T00:44:53Z

Currently each line of logs calls out.Styled, out.Styled calls klog.Flush, so flushing on many lines repeatedly slows down the output.

The PR batches large amounts of lines into a single string before calling out.Styled, greatly reducing the output time.

Before:

minikube logs
26.578 seconds

After:

minikube logs
2.591 seconds

medyagh

beautiful ! lets add integration test for it, so we never break this agian,

no user should ever have to wait for Text file more than 5 seconds to be shown up

minikube-bot · 2021-05-04T00:50:03Z

Can one of the admins verify this patch?

test/integration/aaa_download_only_test.go

medyagh · 2021-05-04T20:27:50Z

/ok-to-test

test/integration/aaa_download_only_test.go

minikube-pr-bot · 2021-05-04T21:10:55Z

kvm2 driver with docker runtime

+----------------+----------+---------------------+
|    COMMAND     | MINIKUBE | MINIKUBE (PR 11274) |
+----------------+----------+---------------------+
| minikube start | 51.0s    | 51.0s               |
| enable ingress | 35.3s    | 35.8s               |
+----------------+----------+---------------------+

Times for minikube ingress: 34.3s 35.3s 34.8s 35.3s 36.9s
Times for minikube (PR 11274) ingress: 35.8s 34.7s 35.3s 34.3s 38.8s

Times for minikube start: 55.6s 52.8s 50.6s 47.7s 48.4s
Times for minikube (PR 11274) start: 50.8s 52.1s 50.4s 51.3s 50.2s

docker driver with docker runtime

+----------------+----------+---------------------+
|    COMMAND     | MINIKUBE | MINIKUBE (PR 11274) |
+----------------+----------+---------------------+
| minikube start | 21.5s    | 21.8s               |
| enable ingress | 34.0s    | 33.9s               |
+----------------+----------+---------------------+

Times for minikube ingress: 35.0s 33.5s 32.5s 35.0s 34.0s
Times for minikube (PR 11274) ingress: 35.0s 30.5s 36.5s 37.0s 30.5s

Times for minikube start: 22.4s 21.3s 21.3s 20.8s 21.6s
Times for minikube (PR 11274) start: 22.0s 21.4s 21.9s 21.6s 22.3s

docker driver with containerd runtime

+----------------+----------+---------------------+
|    COMMAND     | MINIKUBE | MINIKUBE (PR 11274) |
+----------------+----------+---------------------+
| minikube start | 44.8s    | 44.8s               |
| enable ingress |          |                     |
+----------------+----------+---------------------+

Times for minikube start: 43.5s 47.0s 43.6s 42.8s 46.8s
Times for minikube (PR 11274) start: 43.1s 47.8s 47.0s 43.5s 42.5s

minikube-pr-bot · 2021-05-04T21:44:09Z

kvm2 driver with docker runtime

+----------------+----------+---------------------+
|    COMMAND     | MINIKUBE | MINIKUBE (PR 11274) |
+----------------+----------+---------------------+
| minikube start | 51.7s    | 51.4s               |
| enable ingress | 35.6s    | 36.7s               |
+----------------+----------+---------------------+

Times for minikube start: 51.2s 47.0s 55.4s 55.5s 49.5s
Times for minikube (PR 11274) start: 50.4s 48.1s 54.1s 48.8s 55.7s

Times for minikube ingress: 34.7s 35.3s 35.4s 36.9s 35.8s
Times for minikube (PR 11274) ingress: 35.3s 35.3s 35.3s 34.4s 43.0s

docker driver with docker runtime

+----------------+----------+---------------------+
|    COMMAND     | MINIKUBE | MINIKUBE (PR 11274) |
+----------------+----------+---------------------+
| minikube start | 22.7s    | 22.8s               |
| enable ingress | 34.6s    | 34.3s               |
+----------------+----------+---------------------+

Times for minikube start: 23.6s 23.2s 22.6s 22.3s 21.9s
Times for minikube (PR 11274) start: 23.0s 22.8s 22.8s 22.5s 23.0s

Times for minikube ingress: 33.5s 37.0s 31.6s 33.6s 37.5s
Times for minikube (PR 11274) ingress: 33.1s 34.6s 37.5s 34.0s 32.5s

docker driver with containerd runtime

+----------------+----------+---------------------+
|    COMMAND     | MINIKUBE | MINIKUBE (PR 11274) |
+----------------+----------+---------------------+
| minikube start | 45.9s    | 44.8s               |
| enable ingress |          |                     |
+----------------+----------+---------------------+

Times for minikube start: 48.4s 43.1s 47.2s 47.1s 43.6s
Times for minikube (PR 11274) start: 43.3s 47.1s 43.7s 42.8s 47.1s

test/integration/aaa_download_only_test.go

medyagh · 2021-05-04T22:53:35Z

test/integration/aaa_download_only_test.go

+				defer cancel()
+				args := []string{"logs", "-p", profile}
+				if _, err := Run(t, exec.CommandContext(ctx, Target(), args...)); err != nil {
+					t.Errorf("minikube logs failed with error: %v", err)


can ignore minikube logs error here...just care about the duration.

Can't ignore error or linting fails, I replaced with a t.Logf so it won't fail the test.

minikube-pr-bot · 2021-05-05T00:08:57Z

kvm2 driver with docker runtime

+----------------+----------+---------------------+
|    COMMAND     | MINIKUBE | MINIKUBE (PR 11274) |
+----------------+----------+---------------------+
| minikube start | 53.2s    | 52.1s               |
| enable ingress | 36.7s    | 35.1s               |
+----------------+----------+---------------------+

Times for minikube start: 53.4s 52.1s 55.9s 49.4s 55.2s
Times for minikube (PR 11274) start: 54.8s 50.2s 51.8s 49.3s 54.5s

Times for minikube ingress: 41.3s 37.2s 34.7s 35.3s 34.8s
Times for minikube (PR 11274) ingress: 35.2s 36.2s 33.7s 36.8s 33.7s

docker driver with docker runtime

+----------------+----------+---------------------+
|    COMMAND     | MINIKUBE | MINIKUBE (PR 11274) |
+----------------+----------+---------------------+
| minikube start | 21.7s    | 21.6s               |
| enable ingress | 31.6s    | 29.5s               |
+----------------+----------+---------------------+

Times for minikube start: 22.2s 22.3s 21.7s 20.8s 21.5s
Times for minikube (PR 11274) start: 21.6s 22.1s 21.7s 21.2s 21.1s

Times for minikube ingress: 32.5s 34.5s 33.0s 30.5s 27.5s
Times for minikube (PR 11274) ingress: 28.5s 27.5s 32.0s 30.5s 29.0s

docker driver with containerd runtime

+----------------+----------+---------------------+
|    COMMAND     | MINIKUBE | MINIKUBE (PR 11274) |
+----------------+----------+---------------------+
| minikube start | 42.1s    | 45.3s               |
| enable ingress |          |                     |
+----------------+----------+---------------------+

Times for minikube start: 31.1s 46.7s 46.9s 43.1s 42.7s
Times for minikube (PR 11274) start: 47.0s 43.0s 42.3s 47.1s 47.2s

minikube-pr-bot · 2021-05-05T00:40:40Z

kvm2 driver with docker runtime

+----------------+----------+---------------------+
|    COMMAND     | MINIKUBE | MINIKUBE (PR 11274) |
+----------------+----------+---------------------+
| minikube start | 49.3s    | 50.0s               |
| enable ingress | 35.2s    | 35.6s               |
+----------------+----------+---------------------+

Times for minikube ingress: 33.8s 35.9s 37.4s 35.2s 33.7s
Times for minikube (PR 11274) ingress: 36.8s 35.4s 35.4s 35.9s 34.3s

Times for minikube (PR 11274) start: 47.9s 47.8s 46.9s 55.8s 51.3s
Times for minikube start: 49.3s 50.0s 51.7s 47.6s 47.7s

docker driver with docker runtime

+----------------+----------+---------------------+
|    COMMAND     | MINIKUBE | MINIKUBE (PR 11274) |
+----------------+----------+---------------------+
| minikube start | 21.6s    | 21.7s               |
| enable ingress | 30.9s    | 29.4s               |
+----------------+----------+---------------------+

Times for minikube ingress: 31.0s 32.0s 26.5s 30.0s 35.0s
Times for minikube (PR 11274) ingress: 29.5s 29.0s 28.5s 30.0s 30.0s

Times for minikube start: 21.7s 21.5s 22.8s 21.1s 20.9s
Times for minikube (PR 11274) start: 21.2s 21.4s 21.5s 22.8s 21.7s

docker driver with containerd runtime

+----------------+----------+---------------------+
|    COMMAND     | MINIKUBE | MINIKUBE (PR 11274) |
+----------------+----------+---------------------+
| minikube start | 44.0s    | 45.5s               |
| enable ingress |          |                     |
+----------------+----------+---------------------+

Times for minikube start: 43.5s 42.3s 47.5s 43.4s 43.2s
Times for minikube (PR 11274) start: 46.8s 43.1s 47.5s 46.7s 43.6s

tstromberg · 2021-05-05T02:55:42Z

I can confirm this PR results in a 9.2X speed up in minikube logs performance on my macOS machine (32s -> 3.5s), and resolves #10854

k8s-ci-robot · 2021-05-05T07:12:43Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: medyagh, spowelljr

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

batch logs output to speedup command

616401e

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. labels May 4, 2021

k8s-ci-robot requested review from ilya-zuyev and prasadkatti May 4, 2021 00:45

medyagh reviewed May 4, 2021

View reviewed changes

added minikube logs timeout integration test

e269057

k8s-ci-robot added size/S Denotes a PR that changes 10-29 lines, ignoring generated files. and removed size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. labels May 4, 2021

medyagh requested changes May 4, 2021

View reviewed changes

test/integration/aaa_download_only_test.go Show resolved Hide resolved

add explicit timeout failure message

8071aad

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

medyagh reviewed May 4, 2021

View reviewed changes

test/integration/aaa_download_only_test.go Outdated Show resolved Hide resolved

explicitly check for DeadlineExceeded

29a6825

medyagh requested changes May 4, 2021

View reviewed changes

spowelljr added 2 commits May 4, 2021 16:12

dont check exit code of minikube logs in logs duration test

459c42b

added back error check

9d98c09

medyagh approved these changes May 5, 2021

View reviewed changes

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label May 5, 2021

medyagh merged commit b850829 into kubernetes:master May 5, 2021

spowelljr deleted the improveLogsCommand branch June 28, 2021 17:43

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Batch logs output to speedup `minikube logs` command #11274

Batch logs output to speedup `minikube logs` command #11274

spowelljr commented May 4, 2021 •

edited

Loading

medyagh left a comment

minikube-bot commented May 4, 2021

medyagh commented May 4, 2021

minikube-pr-bot commented May 4, 2021

minikube-pr-bot commented May 4, 2021

medyagh May 4, 2021

spowelljr May 4, 2021 •

edited

Loading

minikube-pr-bot commented May 5, 2021

minikube-pr-bot commented May 5, 2021

tstromberg commented May 5, 2021 •

edited

Loading

k8s-ci-robot commented May 5, 2021

Batch logs output to speedup minikube logs command #11274

Batch logs output to speedup minikube logs command #11274

Conversation

spowelljr commented May 4, 2021 • edited Loading

medyagh left a comment

Choose a reason for hiding this comment

minikube-bot commented May 4, 2021

medyagh commented May 4, 2021

minikube-pr-bot commented May 4, 2021

minikube-pr-bot commented May 4, 2021

medyagh May 4, 2021

Choose a reason for hiding this comment

spowelljr May 4, 2021 • edited Loading

Choose a reason for hiding this comment

minikube-pr-bot commented May 5, 2021

minikube-pr-bot commented May 5, 2021

tstromberg commented May 5, 2021 • edited Loading

k8s-ci-robot commented May 5, 2021

Batch logs output to speedup `minikube logs` command #11274

Batch logs output to speedup `minikube logs` command #11274

spowelljr commented May 4, 2021 •

edited

Loading

spowelljr May 4, 2021 •

edited

Loading

tstromberg commented May 5, 2021 •

edited

Loading