perf: improve perf of accesslog (#46)

accesslog/accesslog.go

@@ -44,16 +44,15 @@ package accesslog
 import (
 	"context"
 	"fmt"
-	"io"
 	"os"
 	"strconv"
 	"strings"
+	"sync"
 	"sync/atomic"
 	"time"
 
 	"github.com/cloudwego/hertz/pkg/app"
 	"github.com/cloudwego/hertz/pkg/common/bytebufferpool"
-	"github.com/hertz-contrib/logger/accesslog/internal/fasttemplate"
 )
 
 var defaultFormat = " %s | %3d | %7v | %-7s | %-s "
@@ -71,8 +70,6 @@ func new(ctx context.Context, opts ...Option) app.HandlerFunc {
 	// Check if format contains latency
 	cfg.enableLatency = strings.Contains(cfg.format, "${latency}")
 
-	tmpl := fasttemplate.New(cfg.format, "${", "}")
-
 	// Create correct time format
 	var timestamp atomic.Value
 	timestamp.Store(time.Now().In(cfg.timeZoneLocation).Format(cfg.timeFormat))
@@ -93,20 +90,34 @@ func new(ctx context.Context, opts ...Option) app.HandlerFunc {
 
 	// Set PID once and add tag
 	pid := strconv.Itoa(os.Getpid())
-	Tags[TagPid] = func(ctx context.Context, c *app.RequestContext, buf *bytebufferpool.ByteBuffer) (int, error) {
-		return buf.WriteString(pid)
+
+	dataPool := sync.Pool{
+		New: func() interface{} {
+			return &Data{}
+		},
 	}
-	Tags[TagTime] = func(ctx context.Context, c *app.RequestContext, buf *bytebufferpool.ByteBuffer) (int, error) {
-		return buf.WriteString(timestamp.Load().(string))
+
+	// instead of analyzing the template inside(handler) each time, this is done once before
+	// and we create several slices of the same length with the functions to be executed and fixed parts.
+	tmplChain, logFunChain, err := buildLogFuncChain(cfg, Tags)
+	if err != nil {
+		panic(err)
 	}
 
 	return func(ctx context.Context, c *app.RequestContext) {
 		var start, stop time.Time
 
+		// Logger data
+		data := dataPool.Get().(*Data) //nolint:forcetypeassert,errcheck // We store nothing else in the pool
+		// no need for a reset, as long as we always override everything
+		data.Pid = pid
+		data.Timestamp = timestamp
+		// put data back in the pool
+		defer dataPool.Put(data)
+
 		// Set latency start time
 		if cfg.enableLatency {
-			start = time.Now()
-			c.Set("start", start)
+			data.Start = time.Now()
 		}
 
 		c.Next(ctx)
@@ -116,8 +127,7 @@ func new(ctx context.Context, opts ...Option) app.HandlerFunc {
 		}
 
 		if cfg.enableLatency {
-			stop = time.Now()
-			c.Set("stop", stop)
+			data.Stop = time.Now()
 		}
 
 		// Get new buffer
@@ -138,12 +148,20 @@ func new(ctx context.Context, opts ...Option) app.HandlerFunc {
 			return
 		}
 
-		_, err := tmpl.ExecuteFunc(buf, func(w io.Writer, tag string) (int, error) {
-			if function, ok := Tags[tag]; ok {
-				return function(ctx, c, buf)
+		// Loop over template parts execute dynamic parts and add fixed parts to the buffer
+		for i, logFunc := range logFunChain {
+			if logFunc == nil {
+				_, _ = buf.Write(tmplChain[i]) //nolint:errcheck // This will never fail
+			} else if tmplChain[i] == nil {
+				_, err = logFunc(buf, c, data, "")
+			} else {
+				_, err = logFunc(buf, c, data, unsafeString(tmplChain[i]))
 			}
-			return 0, nil
-		})
+			if err != nil {
+				break
+			}
+		}
+
 		// Also write errors to the buffer
 		if err != nil {
 			_, _ = buf.WriteString(err.Error())
@@ -153,10 +171,10 @@ func new(ctx context.Context, opts ...Option) app.HandlerFunc {
 	}
 }
 
-func appendInt(buf *bytebufferpool.ByteBuffer, v int) (int, error) {
-	old := len(buf.B)
-	buf.B = appendUint(buf.B, v)
-	return len(buf.B) - old, nil
+func appendInt(output Buffer, v int) (int, error) {
+	old := output.Len()
+	output.Set(appendUint(output.Bytes(), v))
+	return output.Len() - old, nil
 }
 
 func appendUint(dst []byte, n int) []byte {

accesslog/accesslog_test.go

@@ -44,10 +44,13 @@ package accesslog
 import (
 	"context"
 	"fmt"
+	"io"
 	"os"
 	"strings"
 	"testing"
 
+	"github.com/cloudwego/hertz/pkg/protocol"
+
 	"github.com/cloudwego/hertz/pkg/app"
 	"github.com/cloudwego/hertz/pkg/common/bytebufferpool"
 	"github.com/cloudwego/hertz/pkg/common/config"
@@ -120,3 +123,43 @@ func TestRespBody(t *testing.T) {
 	assert.DeepEqual(t, 200, w.StatusCode())
 	assert.DeepEqual(t, postBody+"\n", buf.String()[len(buf.String())-len(postBody)-1:])
 }
+
+// go test -v -run=^$ -bench=Benchmark_Logger -benchmem -count=4
+func Benchmark_AccessLog(b *testing.B) {
+	hlog.SetOutput(io.Discard)
+
+	benchSetup := func(b *testing.B, engine *route.Engine) {
+		b.Helper()
+
+		ctx := engine.NewContext()
+		req := protocol.NewRequest("GET", "/", nil)
+
+		b.ReportAllocs()
+		b.ResetTimer()
+
+		for n := 0; n < b.N; n++ {
+			req.CopyTo(&ctx.Request)
+			engine.ServeHTTP(context.Background(), ctx)
+			ctx.Reset()
+		}
+	}
+
+	b.Run("Base", func(bb *testing.B) {
+		engine := route.NewEngine(config.NewOptions([]config.Option{}))
+		engine.Use(New(WithFormat("${bytesReceived} ${bytesSent} ${status}")))
+		engine.GET("/", func(c context.Context, ctx *app.RequestContext) {
+			ctx.Response.Header.Set("test", "test")
+
+			ctx.String(200, "hello world")
+		})
+		benchSetup(bb, engine)
+	})
+
+	b.Run("DefaultFormat", func(bb *testing.B) {
+		engine := route.NewEngine(config.NewOptions([]config.Option{}))
+		engine.Use(New())
+		engine.GET("/", func(c context.Context, ctx *app.RequestContext) {
+			ctx.String(200, "hello world")
+		})
+	})
+}

accesslog/go.mod

@@ -2,4 +2,4 @@ module github.com/hertz-contrib/logger/accesslog
 
 go 1.16
 
-require github.com/cloudwego/hertz v0.6.8
+require github.com/cloudwego/hertz v0.7.2

accesslog/go.sum

@@ -10,10 +10,10 @@ github.com/bytedance/sonic v1.8.1/go.mod h1:i736AoUSYt75HyZLoJW9ERYxcy6eaN6h4BZX
 github.com/chenzhuoyu/base64x v0.0.0-20211019084208-fb5309c8db06/go.mod h1:DH46F32mSOjUmXrMHnKwZdA8wcEefY7UVqBKYGjpdQY=
 github.com/chenzhuoyu/base64x v0.0.0-20221115062448-fe3a3abad311 h1:qSGYFH7+jGhDF8vLC+iwCD4WpbV1EBDSzWkJODFLams=
 github.com/chenzhuoyu/base64x v0.0.0-20221115062448-fe3a3abad311/go.mod h1:b583jCggY9gE99b6G5LEC39OIiVsWj+R97kbl5odCEk=
-github.com/cloudwego/hertz v0.6.8 h1:nuUp2YuD3DJ4jjL9gP2IJRb84aSigbEUumuwQt0mjfc=
-github.com/cloudwego/hertz v0.6.8/go.mod h1:KhztQcZtMQ46gOjZcmCy557AKD29cbumGEV0BzwevwA=
-github.com/cloudwego/netpoll v0.3.2 h1:/998ICrNMVBo4mlul4j7qcIeY7QnEfuCCPPwck9S3X4=
-github.com/cloudwego/netpoll v0.3.2/go.mod h1:xVefXptcyheopwNDZjDPcfU6kIjZXZ4nY550k1yH9eQ=
+github.com/cloudwego/hertz v0.7.2 h1:3Wrm6AWK4EBaXXqvyG8RahafHgcxZ21WFsosBBoobQ0=
+github.com/cloudwego/hertz v0.7.2/go.mod h1:WliNtVbwihWHHgAaIQEbVXl0O3aWj0ks1eoPrcEAnjs=
+github.com/cloudwego/netpoll v0.5.0 h1:oRrOp58cPCvK2QbMozZNDESvrxQaEHW2dCimmwH1lcU=
+github.com/cloudwego/netpoll v0.5.0/go.mod h1:xVefXptcyheopwNDZjDPcfU6kIjZXZ4nY550k1yH9eQ=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
@@ -54,8 +54,8 @@ github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO
 github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk=
 github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
 github.com/tidwall/gjson v1.9.3/go.mod h1:/wbyibRr2FHMks5tjHJ5F8dMZh3AcwJEMf5vlfC0lxk=
-github.com/tidwall/gjson v1.13.0 h1:3TFY9yxOQShrvmjdM76K+jc66zJeT6D3/VFFYCGQf7M=
-github.com/tidwall/gjson v1.13.0/go.mod h1:/wbyibRr2FHMks5tjHJ5F8dMZh3AcwJEMf5vlfC0lxk=
+github.com/tidwall/gjson v1.14.4 h1:uo0p8EbA09J7RQaflQ1aBRffTR7xedD2bcIVSYxLnkM=
+github.com/tidwall/gjson v1.14.4/go.mod h1:/wbyibRr2FHMks5tjHJ5F8dMZh3AcwJEMf5vlfC0lxk=
 github.com/tidwall/match v1.1.1 h1:+Ho715JplO36QYgwN9PGYNhgZvoUSc9X2c80KVTi+GA=
 github.com/tidwall/match v1.1.1/go.mod h1:eRSPERbgtNPcGhD8UCthc6PmLEQXEWd3PRB5JTxsfmM=
 github.com/tidwall/pretty v1.2.0 h1:RWIZEg2iJ8/g6fDDYzMpobmaoGh5OLl4AXtGUGPcqCs=