event: make logfmt output much faster
name old time/op new time/op delta
EventLogNoExporter-16 421ns ± 2% 429ns ± 4% ~ (p=0.059 n=8+9)
EventLogNoop-16 1.59µs ± 1% 1.63µs ± 6% +2.58% (p=0.041 n=8+10)
EventLogDiscard-16 15.1µs ± 2% 8.7µs ± 2% -42.61% (p=0.000 n=9+9)
EventLogSourceDiscard-16 29.6µs ± 3% 22.2µs ± 2% -25.26% (p=0.000 n=9+10)
EventLogfDiscard-16 18.4µs ± 3% 11.9µs ± 4% -35.47% (p=0.000 n=9+10)
EventTraceNoop-16 4.26µs ± 3% 4.32µs ± 3% +1.48% (p=0.046 n=9+10)
EventTraceDiscard-16 25.4µs ± 6% 16.2µs ± 4% -36.12% (p=0.000 n=10+10)
EventMetricNoop-16 2.96µs ± 4% 2.99µs ± 2% ~ (p=0.161 n=9+9)
EventMetricDiscard-16 49.3µs ± 3% 31.0µs ± 6% -37.09% (p=0.000 n=10+10)
Change-Id: Ia35a336811b2805bb387c2d8e164c8b9a39533df
Reviewed-on: https://go-review.googlesource.com/c/exp/+/329794
Trust: Ian Cottrell <iancottrell@google.com>
Run-TryBot: Ian Cottrell <iancottrell@google.com>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Jonathan Amsterdam <jba@google.com>
diff --git a/event/adapter/logfmt/logfmt.go b/event/adapter/logfmt/logfmt.go
index 2ca6e38..32eadbe 100644
--- a/event/adapter/logfmt/logfmt.go
+++ b/event/adapter/logfmt/logfmt.go
@@ -10,7 +10,7 @@
"fmt"
"io"
"strconv"
- "unicode"
+ "time"
"unicode/utf8"
"golang.org/x/exp/event"
@@ -48,7 +48,10 @@
func (p *Printer) Event(w io.Writer, ev *event.Event) {
p.needSep = false
if !ev.At.IsZero() {
- p.Label(w, event.Bytes("time", ev.At.AppendFormat(p.buf[:0], TimeFormat)))
+ p.separator(w)
+ io.WriteString(w, `time="`)
+ p.time(w, ev.At)
+ io.WriteString(w, `"`)
}
if !p.SuppressNamespace && ev.Namespace != "" {
@@ -56,7 +59,9 @@
}
if ev.Parent != 0 {
- p.Label(w, event.Bytes("parent", strconv.AppendUint(p.buf[:0], ev.Parent, 10)))
+ p.separator(w)
+ io.WriteString(w, `parent=`)
+ w.Write(strconv.AppendUint(p.buf[:0], ev.Parent, 10))
}
for _, l := range ev.Labels {
if l.Name == "" {
@@ -66,42 +71,39 @@
}
if ev.TraceID != 0 {
- p.Label(w, event.Uint64("trace", ev.TraceID))
+ p.separator(w)
+ io.WriteString(w, `trace=`)
+ w.Write(strconv.AppendUint(p.buf[:0], ev.TraceID, 10))
}
if ev.Kind == event.EndKind {
- p.Label(w, event.Value("end", nil))
+ p.separator(w)
+ io.WriteString(w, `end`)
}
io.WriteString(w, "\n")
}
+func (p *Printer) separator(w io.Writer) {
+ if p.needSep {
+ io.WriteString(w, " ")
+ }
+ p.needSep = true
+}
+
func (p *Printer) Label(w io.Writer, l event.Label) {
if l.Name == "" {
return
}
- if p.needSep {
- io.WriteString(w, " ")
- }
- p.needSep = true
+ p.separator(w)
p.Ident(w, l.Name)
if l.HasValue() {
io.WriteString(w, "=")
switch {
case l.IsString():
- s := l.String()
- if p.QuoteValues || stringNeedQuote(s) {
- p.quoteString(w, s)
- } else {
- io.WriteString(w, s)
- }
+ p.string(w, l.String())
case l.IsBytes():
- buf := l.Bytes()
- if p.QuoteValues || bytesNeedQuote(buf) {
- p.quoteBytes(w, buf)
- } else {
- w.Write(buf)
- }
+ p.bytes(w, l.Bytes())
case l.IsInt64():
w.Write(strconv.AppendInt(p.buf[:0], l.Int64(), 10))
case l.IsUint64():
@@ -115,17 +117,21 @@
io.WriteString(w, "false")
}
default:
- if p.w.Cap() == 0 {
- // we rely on the inliner to cause this to not allocate
- p.w = *bytes.NewBuffer(p.buf[:0])
- }
- fmt.Fprint(&p.w, l.Interface())
- b := p.w.Bytes()
- p.w.Reset()
- if p.QuoteValues || bytesNeedQuote(b) {
- p.quoteBytes(w, b)
- } else {
- w.Write(b)
+ v := l.Interface()
+ switch v := v.(type) {
+ case string:
+ p.string(w, v)
+ case fmt.Stringer:
+ p.string(w, v.String())
+ default:
+ if p.w.Cap() == 0 {
+ // we rely on the inliner to cause this to not allocate
+ p.w = *bytes.NewBuffer(p.buf[:0])
+ }
+ fmt.Fprint(&p.w, v)
+ b := p.w.Bytes()
+ p.w.Reset()
+ p.bytes(w, b)
}
}
}
@@ -139,6 +145,14 @@
p.quoteString(w, s)
}
+func (p *Printer) string(w io.Writer, s string) {
+ if p.QuoteValues || stringNeedQuote(s) {
+ p.quoteString(w, s)
+ } else {
+ io.WriteString(w, s)
+ }
+}
+
func (p *Printer) quoteString(w io.Writer, s string) {
io.WriteString(w, `"`)
written := 0
@@ -157,6 +171,14 @@
io.WriteString(w, `"`)
}
+func (p *Printer) bytes(w io.Writer, buf []byte) {
+ if p.QuoteValues || stringNeedQuote(string(buf)) {
+ p.quoteBytes(w, buf)
+ } else {
+ w.Write(buf)
+ }
+}
+
// Bytes writes a byte array in string form to the printer.
func (p *Printer) quoteBytes(w io.Writer, buf []byte) {
io.WriteString(w, `"`)
@@ -178,33 +200,44 @@
io.WriteString(w, `"`)
}
+// time writes a timstamp in the same format as
+func (p *Printer) time(w io.Writer, t time.Time) {
+ year, month, day := t.Date()
+ hour, minute, second := t.Clock()
+ p.padInt(w, int64(year), 4)
+ io.WriteString(w, `/`)
+ p.padInt(w, int64(month), 2)
+ io.WriteString(w, `/`)
+ p.padInt(w, int64(day), 2)
+ io.WriteString(w, ` `)
+ p.padInt(w, int64(hour), 2)
+ io.WriteString(w, `:`)
+ p.padInt(w, int64(minute), 2)
+ io.WriteString(w, `:`)
+ p.padInt(w, int64(second), 2)
+}
+
+func (p *Printer) padInt(w io.Writer, v int64, width int) {
+ b := strconv.AppendInt(p.buf[:0], int64(v), 10)
+ if len(b) < width {
+ io.WriteString(w, "0000"[:width-len(b)])
+ }
+ w.Write(b)
+}
+
func stringNeedQuote(s string) bool {
if len(s) == 0 {
return true
}
- for _, r := range s {
- if runeForcesQuote(r) {
+ for i := 0; i < len(s); i++ {
+ c := s[i]
+ if c >= utf8.RuneSelf || c == ' ' || c == '"' || c == '\n' || c == '\\' {
return true
}
}
return false
}
-func bytesNeedQuote(buf []byte) bool {
- for offset := 0; offset < len(buf); {
- r, size := utf8.DecodeRune(buf[offset:])
- offset += size
- if runeForcesQuote(r) {
- return true
- }
- }
- return false
-}
-
-func runeForcesQuote(r rune) bool {
- return !unicode.IsLetter(r) && !unicode.IsNumber(r)
-}
-
func quoteRune(r rune) string {
switch r {
case '"':
diff --git a/event/adapter/logfmt/logfmt_test.go b/event/adapter/logfmt/logfmt_test.go
index 45379ce..072caaa 100644
--- a/event/adapter/logfmt/logfmt_test.go
+++ b/event/adapter/logfmt/logfmt_test.go
@@ -37,7 +37,7 @@
}, {
name: "namespace",
event: event.Event{Namespace: "golang.org/x/exp/event"},
- expect: `in="golang.org/x/exp/event"`,
+ expect: `in=golang.org/x/exp/event`,
}, {
name: "at",
event: event.Event{At: at},
@@ -177,7 +177,7 @@
Namespace: "golang.org/x/exp/event",
Labels: []event.Label{event.String("msg", "some text")},
},
- before: `in="golang.org/x/exp/event" msg="some text"`,
+ before: `in=golang.org/x/exp/event msg="some text"`,
after: `msg="some text"`,
}} {
t.Run(test.name, func(t *testing.T) {
