Add support for timing per log and printing out timings per log to mkcmp

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]")

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
+}

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)
+		}
+	}
+}

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
+}

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("<details>\n")
+	fmt.Println("```")
+	t.Render() // Send output
+	fmt.Println("```\n")
+	fmt.Println("</details>")
+}
+
+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
+}

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
 }

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