Self-review, round 2

log/event.go

@@ -13,6 +13,7 @@ import (
 const (
 	tagField        = "tag"
 	errorField      = "error"
+	timeTakenField  = "time_taken_ms"
 	exitCodeField   = "exit_code"
 	timestampFormat = "2006-01-02T15:04:05.999Z07:00"
 )
@@ -80,6 +81,13 @@ func (e *Event) Time(t time.Time) *Event {
 	return e
 }
 
+// Timing runs f and records the time if took to execute it in "time_taken_ms"
+func (e *Event) Timing(f func()) *Event {
+	start := time.Now()
+	f()
+	return e.Field(timeTakenField, time.Since(start).Milliseconds())
+}
+
 // Err adds an "error" field to the log event
 func (e *Event) Err(err error) *Event {
 	if err == nil {

log/log.go

@@ -78,6 +78,11 @@ func Time(time time.Time) *Event {
 	return newEvent().Time(time)
 }
 
+// Timing runs f and records the time if took to execute it in "time_taken_ms"
+func Timing(f func()) *Event {
+	return newEvent().Timing(f)
+}
+
 // CurrentLevel returns the current log level
 func CurrentLevel() Level {
 	mu.Lock()

log/log_test.go

@@ -2,6 +2,7 @@ package log
 
 import (
 	"bytes"
+	"encoding/json"
 	"github.com/stretchr/testify/require"
 	"os"
 	"testing"
@@ -131,6 +132,25 @@ func TestLog_NoAllocIfNotPrinted(t *testing.T) {
 	require.Equal(t, expected, out.String())
 }
 
+func TestLog_Timing(t *testing.T) {
+	t.Cleanup(resetState)
+
+	var out bytes.Buffer
+	SetOutput(&out)
+	SetFormat(JSONFormat)
+
+	Timing(func() { time.Sleep(300 * time.Millisecond) }).
+		Time(time.Unix(12, 0).UTC()).
+		Info("A thing that takes a while")
+
+	var ev struct {
+		TimeTakenMs int64 `json:"time_taken_ms"`
+	}
+	require.Nil(t, json.Unmarshal(out.Bytes(), &ev))
+	require.True(t, ev.TimeTakenMs >= 300)
+	require.Contains(t, out.String(), `{"time":"1970-01-01T00:00:12Z","level":"INFO","message":"A thing that takes a while","time_taken_ms":`)
+}
+
 type fakeError struct {
 	Code    int
 	Message string