Merge pull request #54992 from porridge/perf-timing

Automatic merge from submit-queue. If you want to cherry-pick this change to another branch, please follow the instructions <a href="https://github.com/kubernetes/community/blob/master/contributors/devel/cherry-picks.md">here</a>.

Add performance test phase timing export.

**What this PR does / why we need it**:

First step totwards allowing us to get a quick overview of test length
via perf-dash.k8s.io.

**Release note**:
```release-note
NONE
```

@kubernetes/sig-scalability-feature-requests

test/e2e/framework/BUILD

@@ -161,6 +161,7 @@ filegroup(
         ":package-srcs",
         "//test/e2e/framework/ginkgowrapper:all-srcs",
         "//test/e2e/framework/metrics:all-srcs",
+        "//test/e2e/framework/timer:all-srcs",
     ],
     tags = ["automanaged"],
 )

test/e2e/framework/timer/BUILD

@@ -0,0 +1,34 @@
+load("@io_bazel_rules_go//go:def.bzl", "go_library", "go_test")
+
+go_library(
+    name = "go_default_library",
+    srcs = ["timer.go"],
+    importpath = "k8s.io/kubernetes/test/e2e/framework/timer",
+    visibility = ["//visibility:public"],
+    deps = [
+        "//test/e2e/framework:go_default_library",
+        "//test/e2e/perftype:go_default_library",
+    ],
+)
+
+go_test(
+    name = "go_default_test",
+    srcs = ["timer_test.go"],
+    importpath = "k8s.io/kubernetes/test/e2e/framework/timer",
+    library = ":go_default_library",
+    deps = ["//vendor/github.com/onsi/gomega:go_default_library"],
+)
+
+filegroup(
+    name = "package-srcs",
+    srcs = glob(["**"]),
+    tags = ["automanaged"],
+    visibility = ["//visibility:private"],
+)
+
+filegroup(
+    name = "all-srcs",
+    srcs = [":package-srcs"],
+    tags = ["automanaged"],
+    visibility = ["//visibility:public"],
+)

test/e2e/framework/timer/timer.go

@@ -0,0 +1,126 @@
+/*
+Copyright 2017 The Kubernetes Authors.
+
+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 timer
+
+import (
+	"time"
+
+	"bytes"
+	"fmt"
+
+	"k8s.io/kubernetes/test/e2e/framework"
+	"k8s.io/kubernetes/test/e2e/perftype"
+	"sync"
+)
+
+var now = time.Now
+
+// Represents a phase of a test. Phases can overlap.
+type Phase struct {
+	sequenceNumber int
+	name           string
+	startTime      time.Time
+	endTime        time.Time
+}
+
+func (phase *Phase) ended() bool {
+	return !phase.endTime.IsZero()
+}
+
+// End marks the phase as ended, unless it had already been ended before.
+func (phase *Phase) End() {
+	if !phase.ended() {
+		phase.endTime = now()
+	}
+}
+
+func (phase *Phase) label() string {
+	return fmt.Sprintf("%03d-%s", phase.sequenceNumber, phase.name)
+}
+
+func (phase *Phase) duration() time.Duration {
+	endTime := phase.endTime
+	if !phase.ended() {
+		endTime = now()
+	}
+	return endTime.Sub(phase.startTime)
+}
+
+func (phase *Phase) humanReadable() string {
+	if phase.ended() {
+		return fmt.Sprintf("Phase %s: %v\n", phase.label(), phase.duration())
+	} else {
+		return fmt.Sprintf("Phase %s: %v so far\n", phase.label(), phase.duration())
+	}
+}
+
+// A TestPhaseTimer groups phases and provides a way to export their measurements as JSON or human-readable text.
+// It is safe to use concurrently.
+type TestPhaseTimer struct {
+	lock   sync.Mutex
+	phases []*Phase
+}
+
+// NewTestPhaseTimer creates a new TestPhaseTimer.
+func NewTestPhaseTimer() *TestPhaseTimer {
+	return &TestPhaseTimer{}
+}
+
+// StartPhase starts a new phase.
+// sequenceNumber is an integer prepended to phaseName in the output, such that lexicographic sorting
+// of phases in perfdash reconstructs the order of execution. Unfortunately it needs to be
+// provided manually, since a simple incrementing counter would have the effect that inserting
+// a new phase would renumber subsequent phases, breaking the continuity of historical records.
+func (timer *TestPhaseTimer) StartPhase(sequenceNumber int, phaseName string) *Phase {
+	timer.lock.Lock()
+	defer timer.lock.Unlock()
+	newPhase := &Phase{sequenceNumber: sequenceNumber, name: phaseName, startTime: now()}
+	timer.phases = append(timer.phases, newPhase)
+	return newPhase
+}
+
+func (timer *TestPhaseTimer) SummaryKind() string {
+	return "TestPhaseTimer"
+}
+
+func (timer *TestPhaseTimer) PrintHumanReadable() string {
+	buf := bytes.Buffer{}
+	timer.lock.Lock()
+	defer timer.lock.Unlock()
+	for _, phase := range timer.phases {
+		buf.WriteString(phase.humanReadable())
+	}
+	return buf.String()
+}
+
+func (timer *TestPhaseTimer) PrintJSON() string {
+	data := perftype.PerfData{
+		Version: "v1",
+		DataItems: []perftype.DataItem{{
+			Unit:   "s",
+			Labels: map[string]string{"test": "phases"},
+			Data:   make(map[string]float64)}}}
+	timer.lock.Lock()
+	defer timer.lock.Unlock()
+	for _, phase := range timer.phases {
+		data.DataItems[0].Data[phase.label()] = phase.duration().Seconds()
+		if !phase.ended() {
+			data.DataItems[0].Labels["ended"] = "false"
+		}
+	}
+	return framework.PrettyPrintJSON(data)
+}

test/e2e/framework/timer/timer_test.go

@@ -0,0 +1,92 @@
+/*
+Copyright 2017 The Kubernetes Authors.
+
+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 timer
+
+import (
+	"testing"
+	"time"
+
+	. "github.com/onsi/gomega"
+)
+
+var currentTime time.Time
+
+func init() {
+	setCurrentTimeSinceEpoch(0)
+	now = func() time.Time { return currentTime }
+}
+
+func setCurrentTimeSinceEpoch(duration time.Duration) {
+	currentTime = time.Unix(0, duration.Nanoseconds())
+}
+
+func testUsageWithDefer(timer *TestPhaseTimer) {
+	defer timer.StartPhase(33, "two").End()
+	setCurrentTimeSinceEpoch(6*time.Second + 500*time.Millisecond)
+}
+
+func TestTimer(t *testing.T) {
+	RegisterTestingT(t)
+
+	timer := NewTestPhaseTimer()
+	setCurrentTimeSinceEpoch(1 * time.Second)
+	phaseOne := timer.StartPhase(1, "one")
+	setCurrentTimeSinceEpoch(3 * time.Second)
+	testUsageWithDefer(timer)
+
+	Expect(timer.PrintJSON()).To(MatchJSON(`{
+		"version": "v1",
+		"dataItems": [
+			{
+				"data": {
+					"001-one": 5.5,
+					"033-two": 3.5
+				},
+				"unit": "s",
+				"labels": {
+					"test": "phases",
+					"ended": "false"
+				}
+			}
+		]
+	}`))
+	Expect(timer.PrintHumanReadable()).To(Equal(`Phase 001-one: 5.5s so far
+Phase 033-two: 3.5s
+`))
+
+	setCurrentTimeSinceEpoch(7*time.Second + 500*time.Millisecond)
+	phaseOne.End()
+
+	Expect(timer.PrintJSON()).To(MatchJSON(`{
+		"version": "v1",
+		"dataItems": [
+			{
+				"data": {
+					"001-one": 6.5,
+					"033-two": 3.5
+				},
+				"unit": "s",
+				"labels": {
+					"test": "phases"
+				}
+			}
+		]
+	}`))
+	Expect(timer.PrintHumanReadable()).To(Equal(`Phase 001-one: 6.5s
+Phase 033-two: 3.5s
+`))
+}