From 958b89c0b5895749392b7e74e88f64119c1510e8 Mon Sep 17 00:00:00 2001
From: Patrice Arruda <patricearruda@google.com>
Date: Mon, 13 Jul 2020 18:21:14 +0000
Subject: [PATCH] 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
---
 ui/metrics/Android.bp   |  3 +++
 ui/metrics/time.go      | 36 +++++++++++++++++------------------
 ui/metrics/time_test.go | 42 +++++++++++++++++++++++++++++++++++++++++
 3 files changed, 62 insertions(+), 19 deletions(-)
 create mode 100644 ui/metrics/time_test.go

diff --git a/ui/metrics/Android.bp b/ui/metrics/Android.bp
index 3596e1019..8188a69e9 100644
--- a/ui/metrics/Android.bp
+++ b/ui/metrics/Android.bp
@@ -25,6 +25,9 @@ bootstrap_go_package {
         "metrics.go",
         "time.go",
     ],
+    testSrcs: [
+        "time_test.go",
+    ],
 }
 
 bootstrap_go_package {
diff --git a/ui/metrics/time.go b/ui/metrics/time.go
index b8baf16fd..401656337 100644
--- a/ui/metrics/time.go
+++ b/ui/metrics/time.go
@@ -19,13 +19,18 @@ import (
 
 	"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 @@ type timeTracerImpl struct {
 
 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) soong_metrics_proto.PerfInfo {
-	return t.endAt(t.now())
-}
-
-func (t *timeTracerImpl) endAt(atNanos uint64) soong_metrics_proto.PerfInfo {
+func (t *timeTracerImpl) End(tracer.Thread) soong_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 soong_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 000000000..d73080ab2
--- /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())
+	}
+}