Use monotonic clock instead of wall time clock for metrics.
From several dashboards, there are high spikes from several
builds where the real time of executing a part of the build
system took many many hours. This is due to using the wall
time clock when calculating the duration. For metrics, the
monotonic clock should be used for more accurate measurement.
Also, cleaned up the time.go file to use the proper proto
functions when marshalling perf protobuf and deleted
unnecessary functions.
Bug: b/143492984
Test: Wrote and ran unit test case.
Change-Id: I1540cfbf37915e3045ecedaa2595c1f9429bcd62
Merged-In: I1540cfbf37915e3045ecedaa2595c1f9429bcd62
diff --git a/ui/metrics/Android.bp b/ui/metrics/Android.bp
index 3596e10..8188a69 100644
--- a/ui/metrics/Android.bp
+++ b/ui/metrics/Android.bp
@@ -25,6 +25,9 @@
"metrics.go",
"time.go",
],
+ testSrcs: [
+ "time_test.go",
+ ],
}
bootstrap_go_package {
diff --git a/ui/metrics/time.go b/ui/metrics/time.go
index 7e8801a..c0de357 100644
--- a/ui/metrics/time.go
+++ b/ui/metrics/time.go
@@ -19,13 +19,18 @@
"android/soong/ui/metrics/metrics_proto"
"android/soong/ui/tracer"
+ "github.com/golang/protobuf/proto"
)
+// for testing purpose only
+var _now = now
+
type timeEvent struct {
desc string
name string
- atNanos uint64 // timestamp measured in nanoseconds since the reference date
+ // the time that the event started to occur.
+ start time.Time
}
type TimeTracer interface {
@@ -39,33 +44,26 @@
var _ TimeTracer = &timeTracerImpl{}
-func (t *timeTracerImpl) now() uint64 {
- return uint64(time.Now().UnixNano())
+func now() time.Time {
+ return time.Now()
}
-func (t *timeTracerImpl) Begin(name, desc string, thread tracer.Thread) {
- t.beginAt(name, desc, t.now())
+func (t *timeTracerImpl) Begin(name, desc string, _ tracer.Thread) {
+ t.activeEvents = append(t.activeEvents, timeEvent{name: name, desc: desc, start: _now()})
}
-func (t *timeTracerImpl) beginAt(name, desc string, atNanos uint64) {
- t.activeEvents = append(t.activeEvents, timeEvent{name: name, desc: desc, atNanos: atNanos})
-}
-
-func (t *timeTracerImpl) End(thread tracer.Thread) metrics_proto.PerfInfo {
- return t.endAt(t.now())
-}
-
-func (t *timeTracerImpl) endAt(atNanos uint64) metrics_proto.PerfInfo {
+func (t *timeTracerImpl) End(tracer.Thread) metrics_proto.PerfInfo {
if len(t.activeEvents) < 1 {
panic("Internal error: No pending events for endAt to end!")
}
lastEvent := t.activeEvents[len(t.activeEvents)-1]
t.activeEvents = t.activeEvents[:len(t.activeEvents)-1]
- realTime := atNanos - lastEvent.atNanos
+ realTime := uint64(_now().Sub(lastEvent.start).Nanoseconds())
return metrics_proto.PerfInfo{
- Desc: &lastEvent.desc,
- Name: &lastEvent.name,
- StartTime: &lastEvent.atNanos,
- RealTime: &realTime}
+ Desc: proto.String(lastEvent.desc),
+ Name: proto.String(lastEvent.name),
+ StartTime: proto.Uint64(uint64(lastEvent.start.UnixNano())),
+ RealTime: proto.Uint64(realTime),
+ }
}
diff --git a/ui/metrics/time_test.go b/ui/metrics/time_test.go
new file mode 100644
index 0000000..d73080a
--- /dev/null
+++ b/ui/metrics/time_test.go
@@ -0,0 +1,42 @@
+// Copyright 2020 Google Inc. 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 metrics
+
+import (
+ "testing"
+ "time"
+
+ "android/soong/ui/tracer"
+)
+
+func TestEnd(t *testing.T) {
+ startTime := time.Date(2020, time.July, 13, 13, 0, 0, 0, time.UTC)
+ dur := time.Nanosecond * 10
+ initialNow := _now
+ _now = func() time.Time { return startTime.Add(dur) }
+ defer func() { _now = initialNow }()
+
+ timeTracer := &timeTracerImpl{}
+ timeTracer.activeEvents = append(timeTracer.activeEvents, timeEvent{
+ desc: "test",
+ name: "test",
+ start: startTime,
+ })
+
+ perf := timeTracer.End(tracer.Thread(0))
+ if perf.GetRealTime() != uint64(dur.Nanoseconds()) {
+ t.Errorf("got %d, want %d nanoseconds for event duration", perf.GetRealTime(), dur.Nanoseconds())
+ }
+}
