Merge pull request #8091 from priyawadhwa/open

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,144 @@
+/*
+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>")
+	fmt.Println()
+	fmt.Println("```")
+	t.Render() // Send output
+	fmt.Println("```")
+	fmt.Println()
+	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
+}