diff --git a/cmd/performance/mkcmp/cmd/mkcmp.go b/cmd/performance/mkcmp/cmd/mkcmp.go index 2a40dd9d5f..16ed30ae40 100644 --- a/cmd/performance/mkcmp/cmd/mkcmp.go +++ b/cmd/performance/mkcmp/cmd/mkcmp.go @@ -19,6 +19,7 @@ package cmd import ( "context" "errors" + "flag" "fmt" "os" @@ -43,6 +44,10 @@ var rootCmd = &cobra.Command{ }, } +func init() { + flag.Parse() +} + func validateArgs(args []string) error { if len(args) != 2 { return errors.New("mkcmp requires two minikube binaries to compare: mkcmp [path to first binary] [path to second binary]") diff --git a/pkg/minikube/perf/logs.go b/pkg/minikube/perf/logs.go new file mode 100644 index 0000000000..885f556b40 --- /dev/null +++ b/pkg/minikube/perf/logs.go @@ -0,0 +1,72 @@ +/* +Copyright 2020 The Kubernetes Authors All rights reserved. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package perf + +import ( + "bufio" + "log" + "os/exec" + "strings" + "time" + + "github.com/golang/glog" + "github.com/pkg/errors" +) + +// timeCommandLogs runs command and watches stdout to time how long each new log takes +// it stores each log, and the time it took, in result +func timeCommandLogs(cmd *exec.Cmd) (*result, error) { + // matches each log with the amount of time spent on that log + r := newResult() + + stdout, err := cmd.StdoutPipe() + if err != nil { + return nil, errors.Wrap(err, "getting stdout pipe") + } + scanner := bufio.NewScanner(stdout) + scanner.Split(bufio.ScanLines) + + log.Printf("Running: %v...", cmd.Args) + if err := cmd.Start(); err != nil { + return nil, errors.Wrap(err, "starting cmd") + } + + timer := time.Now() + var logs []string + var timings []float64 + + for scanner.Scan() { + log := scanner.Text() + // this is the time it took to complete the previous log + timeTaken := time.Since(timer).Seconds() + glog.Infof("%f: %s", timeTaken, log) + + timer = time.Now() + logs = append(logs, log) + timings = append(timings, timeTaken) + } + // add the time it took to get from the final log to finishing the command + timings = append(timings, time.Since(timer).Seconds()) + for i, log := range logs { + r.addTimedLog(strings.Trim(log, "\n"), timings[i+1]) + } + + if err := cmd.Wait(); err != nil { + return nil, errors.Wrap(err, "waiting for minikube") + } + return r, nil +} diff --git a/pkg/minikube/perf/logs_test.go b/pkg/minikube/perf/logs_test.go new file mode 100644 index 0000000000..b62e0cb295 --- /dev/null +++ b/pkg/minikube/perf/logs_test.go @@ -0,0 +1,45 @@ +// +build linux darwin + +/* +Copyright 2020 The Kubernetes Authors All rights reserved. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package perf + +import ( + "os/exec" + "testing" +) + +func TestTimeCommandLogs(t *testing.T) { + cmd := exec.Command("sh", "-c", "echo hi && sleep 3 && echo hey && sleep 1") + actual, err := timeCommandLogs(cmd) + if err != nil { + t.Fatalf("error timing logs: %v", err) + } + expected := newResult() + expected.timedLogs["hi"] = 3.0 + expected.timedLogs["hey"] = 1.0 + + for log, time := range expected.timedLogs { + actualTime, ok := actual.timedLogs[log] + if !ok { + t.Fatalf("expected log %s but didn't find it", log) + } + if actualTime < time { + t.Fatalf("expected log \"%s\" to take more time than it actually did. got %v, expected > %v", log, actualTime, time) + } + } +} diff --git a/pkg/minikube/perf/result.go b/pkg/minikube/perf/result.go new file mode 100644 index 0000000000..fdfb41caea --- /dev/null +++ b/pkg/minikube/perf/result.go @@ -0,0 +1,33 @@ +/* +Copyright 2020 The Kubernetes Authors All rights reserved. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package perf + +type result struct { + logs []string + timedLogs map[string]float64 +} + +func newResult() *result { + return &result{ + timedLogs: map[string]float64{}, + } +} + +func (r *result) addTimedLog(log string, time float64) { + r.logs = append(r.logs, log) + r.timedLogs[log] = time +} diff --git a/pkg/minikube/perf/result_manager.go b/pkg/minikube/perf/result_manager.go new file mode 100644 index 0000000000..8488d5bad4 --- /dev/null +++ b/pkg/minikube/perf/result_manager.go @@ -0,0 +1,142 @@ +/* +Copyright 2020 The Kubernetes Authors All rights reserved. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package perf + +import ( + "fmt" + "os" + "strings" + + "github.com/olekukonko/tablewriter" +) + +type resultManager struct { + results map[*Binary][]*result +} + +func newResultManager() *resultManager { + return &resultManager{ + results: map[*Binary][]*result{}, + } +} + +func (rm *resultManager) addResult(binary *Binary, r *result) { + _, ok := rm.results[binary] + if !ok { + rm.results[binary] = []*result{r} + return + } + rm.results[binary] = append(rm.results[binary], r) +} + +func (rm *resultManager) totalTimes(binary *Binary) []float64 { + var totals []float64 + results, ok := rm.results[binary] + if !ok { + return nil + } + for _, r := range results { + total := 0.0 + for _, t := range r.timedLogs { + total += t + } + totals = append(totals, total) + } + return totals +} + +func (rm *resultManager) averageTime(binary *Binary) float64 { + times := rm.totalTimes(binary) + return average(times) +} + +func (rm *resultManager) summarizeResults(binaries []*Binary) { + // print total and average times + for _, b := range binaries { + fmt.Printf("Times for %s: %v\n", b.Name(), rm.totalTimes(b)) + fmt.Printf("Average time for %s: %v\n\n", b.Name(), rm.averageTime(b)) + } + + // print out summary per log + rm.summarizeTimesPerLog(binaries) +} + +func (rm *resultManager) summarizeTimesPerLog(binaries []*Binary) { + results := rm.results[binaries[0]] + logs := results[0].logs + + table := make([][]string, len(logs)) + for i := range table { + table[i] = make([]string, len(binaries)+1) + } + + for i, l := range logs { + table[i][0] = l + } + + for i, b := range binaries { + results := rm.results[b] + averageTimeForLog := averageTimePerLog(results) + for log, time := range averageTimeForLog { + index := indexForLog(logs, log) + if index == -1 { + continue + } + table[index][i+1] = fmt.Sprintf("%f", time) + } + } + + t := tablewriter.NewWriter(os.Stdout) + t.SetHeader([]string{"Log", binaries[0].Name(), binaries[1].Name()}) + + for _, v := range table { + t.Append(v) + } + fmt.Println("Averages Time Per Log") + fmt.Println("
\n") + fmt.Println("```") + t.Render() // Send output + fmt.Println("```\n") + fmt.Println("
") +} + +func indexForLog(logs []string, log string) int { + for i, l := range logs { + if strings.Contains(log, l) { + return i + } + } + return -1 +} + +func averageTimePerLog(results []*result) map[string]float64 { + collection := map[string][]float64{} + for _, r := range results { + for log, time := range r.timedLogs { + if _, ok := collection[log]; !ok { + collection[log] = []float64{time} + } else { + collection[log] = append(collection[log], time) + } + } + } + avgs := map[string]float64{} + for log, times := range collection { + avgs[log] = average(times) + } + return avgs +} diff --git a/pkg/minikube/perf/start.go b/pkg/minikube/perf/start.go index 7b7bd28bf3..bd1c73827d 100644 --- a/pkg/minikube/perf/start.go +++ b/pkg/minikube/perf/start.go @@ -18,12 +18,10 @@ package perf import ( "context" - "fmt" "io" "log" "os" "os/exec" - "time" "github.com/pkg/errors" ) @@ -33,45 +31,29 @@ const ( runs = 1 ) -var ( - // For testing - collectTimeMinikubeStart = collectTimes -) - // CompareMinikubeStart compares the time to run `minikube start` between two minikube binaries func CompareMinikubeStart(ctx context.Context, out io.Writer, binaries []*Binary) error { - durations, err := collectTimeMinikubeStart(ctx, binaries) + rm, err := collectResults(ctx, binaries) if err != nil { - return err + return errors.Wrapf(err, "collecting results") } - - for i, d := range durations { - fmt.Fprintf(out, "Results for %s:\n", binaries[i].Name()) - fmt.Fprintf(out, "Times: %v\n", d) - fmt.Fprintf(out, "Average Time: %f\n\n", average(d)) - } - + rm.summarizeResults(binaries) return nil } -func collectTimes(ctx context.Context, binaries []*Binary) ([][]float64, error) { - durations := make([][]float64, len(binaries)) - for i := range durations { - durations[i] = make([]float64, runs) - } - +func collectResults(ctx context.Context, binaries []*Binary) (*resultManager, error) { + rm := newResultManager() for r := 0; r < runs; r++ { - log.Printf("Executing run %d...", r) - for index, binary := range binaries { - duration, err := timeMinikubeStart(ctx, binary) + log.Printf("Executing run %d/%d...", r, runs) + for _, binary := range binaries { + r, err := timeMinikubeStart(ctx, binary) if err != nil { - return nil, errors.Wrapf(err, "timing run %d with %s", r, binary.Name()) + return nil, errors.Wrapf(err, "timing run %d with %s", r, binary) } - durations[index][r] = duration + rm.addResult(binary, r) } } - - return durations, nil + return rm, nil } func average(nums []float64) float64 { @@ -84,9 +66,8 @@ func average(nums []float64) float64 { // timeMinikubeStart returns the time it takes to execute `minikube start` // It deletes the VM after `minikube start`. -func timeMinikubeStart(ctx context.Context, binary *Binary) (float64, error) { +func timeMinikubeStart(ctx context.Context, binary *Binary) (*result, error) { startCmd := exec.CommandContext(ctx, binary.path, "start") - startCmd.Stdout = os.Stdout startCmd.Stderr = os.Stderr deleteCmd := exec.CommandContext(ctx, binary.path, "delete") @@ -97,11 +78,9 @@ func timeMinikubeStart(ctx context.Context, binary *Binary) (float64, error) { }() log.Printf("Running: %v...", startCmd.Args) - start := time.Now() - if err := startCmd.Run(); err != nil { - return 0, errors.Wrap(err, "starting minikube") + r, err := timeCommandLogs(startCmd) + if err != nil { + return nil, errors.Wrapf(err, "timing cmd: %v", startCmd.Args) } - - s := time.Since(start).Seconds() - return s, nil + return r, nil } diff --git a/pkg/minikube/perf/start_test.go b/pkg/minikube/perf/start_test.go index 2d802f7d9c..c5f643d5d1 100644 --- a/pkg/minikube/perf/start_test.go +++ b/pkg/minikube/perf/start_test.go @@ -17,66 +17,9 @@ limitations under the License. package perf import ( - "bytes" - "context" "testing" - - "github.com/google/go-cmp/cmp" ) -func mockCollectTimes(times [][]float64) func(ctx context.Context, binaries []*Binary) ([][]float64, error) { - return func(ctx context.Context, binaries []*Binary) ([][]float64, error) { - return times, nil - } -} - -func TestCompareMinikubeStartOutput(t *testing.T) { - binaries := []*Binary{ - { - path: "minikube1", - }, { - path: "minikube2", - }, - } - tests := []struct { - description string - times [][]float64 - expected string - }{ - { - description: "standard run", - times: [][]float64{{4.5, 6}, {1, 2}}, - expected: `Results for minikube1: -Times: [4.5 6] -Average Time: 5.250000 - -Results for minikube2: -Times: [1 2] -Average Time: 1.500000 - -`, - }, - } - - for _, test := range tests { - t.Run(test.description, func(t *testing.T) { - originalCollectTimes := collectTimes - collectTimeMinikubeStart = mockCollectTimes(test.times) - defer func() { collectTimeMinikubeStart = originalCollectTimes }() - - buf := bytes.NewBuffer([]byte{}) - err := CompareMinikubeStart(context.Background(), buf, binaries) - if err != nil { - t.Fatalf("error comparing minikube start: %v", err) - } - - actual := buf.String() - if diff := cmp.Diff(test.expected, actual); diff != "" { - t.Errorf("machines mismatch (-want +got):\n%s", diff) - } - }) - } -} func TestAverage(t *testing.T) { tests := []struct { description string