From: Joe Tsai Date: Thu, 23 Mar 2023 08:01:46 +0000 (-0700) Subject: log/slog: simplify and optimize RFC3339 handling X-Git-Tag: go1.22rc1~1239 X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=d63652b7c69d106a6bab787fbdf7726d39e42406;p=gostls13.git log/slog: simplify and optimize RFC3339 handling In CL 421877 and CL 444278, time.Time.AppendFormat has been specially optimized for the time.RFC3339Nano representation. Relying on that optimization and modify the output to obtain the fixed-width millisecond resolution that slog uses. This both removes a lot of code and also improves performance: name old time/op new time/op delta WriteTime 93.0ns ± 1% 80.8ns ± 0% -13.17% (p=0.000 n=8+9) Change-Id: I61e8f4476c111443e3e2098a45b2c21a76137345 Reviewed-on: https://go-review.googlesource.com/c/go/+/478757 Reviewed-by: Dmitri Shuralyov TryBot-Result: Gopher Robot Run-TryBot: Joseph Tsai Reviewed-by: Jonathan Amsterdam Auto-Submit: Joseph Tsai --- diff --git a/src/log/slog/handler.go b/src/log/slog/handler.go index b737612fb1..52c8e7e6ad 100644 --- a/src/log/slog/handler.go +++ b/src/log/slog/handler.go @@ -545,41 +545,19 @@ func (s *handleState) appendTime(t time.Time) { if s.h.json { appendJSONTime(s, t) } else { - writeTimeRFC3339Millis(s.buf, t) + *s.buf = appendRFC3339Millis(*s.buf, t) } } -// This takes half the time of Time.AppendFormat. -func writeTimeRFC3339Millis(buf *buffer.Buffer, t time.Time) { - year, month, day := t.Date() - buf.WritePosIntWidth(year, 4) - buf.WriteByte('-') - buf.WritePosIntWidth(int(month), 2) - buf.WriteByte('-') - buf.WritePosIntWidth(day, 2) - buf.WriteByte('T') - hour, min, sec := t.Clock() - buf.WritePosIntWidth(hour, 2) - buf.WriteByte(':') - buf.WritePosIntWidth(min, 2) - buf.WriteByte(':') - buf.WritePosIntWidth(sec, 2) - ns := t.Nanosecond() - buf.WriteByte('.') - buf.WritePosIntWidth(ns/1e6, 3) - _, offsetSeconds := t.Zone() - if offsetSeconds == 0 { - buf.WriteByte('Z') - } else { - offsetMinutes := offsetSeconds / 60 - if offsetMinutes < 0 { - buf.WriteByte('-') - offsetMinutes = -offsetMinutes - } else { - buf.WriteByte('+') - } - buf.WritePosIntWidth(offsetMinutes/60, 2) - buf.WriteByte(':') - buf.WritePosIntWidth(offsetMinutes%60, 2) - } +func appendRFC3339Millis(b []byte, t time.Time) []byte { + // Format according to time.RFC3339Nano since it is highly optimized, + // but truncate it to use millisecond resolution. + // Unfortunately, that format trims trailing 0s, so add 1/10 millisecond + // to guarantee that there are exactly 4 digits after the period. + const prefixLen = len("2006-01-02T15:04:05.000") + n := len(b) + t = t.Truncate(time.Millisecond).Add(time.Millisecond / 10) + b = t.AppendFormat(b, time.RFC3339Nano) + b = append(b[:n+prefixLen], b[n+prefixLen+1:]...) // drop the 4th digit + return b } diff --git a/src/log/slog/handler_test.go b/src/log/slog/handler_test.go index 4f10ee5028..21c31929b1 100644 --- a/src/log/slog/handler_test.go +++ b/src/log/slog/handler_test.go @@ -11,7 +11,6 @@ import ( "context" "encoding/json" "io" - "log/slog/internal/buffer" "path/filepath" "slices" "strconv" @@ -603,11 +602,8 @@ func TestWriteTimeRFC3339(t *testing.T) { time.Date(2000, 1, 2, 3, 4, 5, 400, time.Local), time.Date(2000, 11, 12, 3, 4, 500, 5e7, time.UTC), } { + got := string(appendRFC3339Millis(nil, tm)) want := tm.Format(rfc3339Millis) - buf := buffer.New() - defer buf.Free() - writeTimeRFC3339Millis(buf, tm) - got := buf.String() if got != want { t.Errorf("got %s, want %s", got, want) } @@ -615,12 +611,10 @@ func TestWriteTimeRFC3339(t *testing.T) { } func BenchmarkWriteTime(b *testing.B) { - buf := buffer.New() - defer buf.Free() tm := time.Date(2022, 3, 4, 5, 6, 7, 823456789, time.Local) b.ResetTimer() + var buf []byte for i := 0; i < b.N; i++ { - writeTimeRFC3339Millis(buf, tm) - buf.Reset() + buf = appendRFC3339Millis(buf[:0], tm) } } diff --git a/src/log/slog/internal/buffer/buffer.go b/src/log/slog/internal/buffer/buffer.go index c4fcefd775..13546d42fd 100644 --- a/src/log/slog/internal/buffer/buffer.go +++ b/src/log/slog/internal/buffer/buffer.go @@ -50,35 +50,6 @@ func (b *Buffer) WriteByte(c byte) error { return nil } -func (b *Buffer) WritePosInt(i int) { - b.WritePosIntWidth(i, 0) -} - -// WritePosIntWidth writes non-negative integer i to the buffer, padded on the left -// by zeroes to the given width. Use a width of 0 to omit padding. -func (b *Buffer) WritePosIntWidth(i, width int) { - // Cheap integer to fixed-width decimal ASCII. - // Copied from log/log.go. - - if i < 0 { - panic("negative int") - } - - // Assemble decimal in reverse order. - var bb [20]byte - bp := len(bb) - 1 - for i >= 10 || width > 1 { - width-- - q := i / 10 - bb[bp] = byte('0' + i - q*10) - bp-- - i = q - } - // i < 10 - bb[bp] = byte('0' + i) - b.Write(bb[bp:]) -} - func (b *Buffer) String() string { return string(*b) } diff --git a/src/log/slog/internal/buffer/buffer_test.go b/src/log/slog/internal/buffer/buffer_test.go index 40b1d1fda8..06f8284651 100644 --- a/src/log/slog/internal/buffer/buffer_test.go +++ b/src/log/slog/internal/buffer/buffer_test.go @@ -16,10 +16,9 @@ func Test(t *testing.T) { b.WriteString("hello") b.WriteByte(',') b.Write([]byte(" world")) - b.WritePosIntWidth(17, 4) got := b.String() - want := "hello, world0017" + want := "hello, world" if got != want { t.Errorf("got %q, want %q", got, want) }