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 <dmitshur@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Joseph Tsai <joetsai@digital-static.net>
Reviewed-by: Jonathan Amsterdam <jba@google.com>
Auto-Submit: Joseph Tsai <joetsai@digital-static.net>

diff --git a/src/log/slog/handler.go b/src/log/slog/handler.go
index b737612fb142ca57d2629b3e0df81bc058ae442c..52c8e7e6adb476f27775b9fb307ccf3a484432f5 100644 (file)
--- 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 4f10ee5028c24592555868eef2be3b8820de7043..21c31929b12cb983cf4348ed7769064a3ced0096 100644 (file)
--- 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 c4fcefd77536b04d1ef34720f905c9982383b425..13546d42fd6fdaa9cbe9078abe6329e8de3b1507 100644 (file)
--- 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 40b1d1fda8aa925e01891a81098d9c8dee8d8c16..06f8284651151c9e27c8042cded46f471fcb1e6c 100644 (file)
--- 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)
        }