accesslog: export the delimeter used on default formatter and improve its performance

relative to: #1601 and #1622

README.md

@@ -73,7 +73,7 @@ For a more detailed technical documentation you can head over to our [godocs](ht
 
 [![follow Iris web framework on twitter](https://img.shields.io/twitter/follow/iris_framework?color=ee7506&logoColor=ee7506&style=for-the-badge&logo=twitter)](https://twitter.com/intent/follow?screen_name=iris_framework)
 
-[![follow Iris web framework on facebook](https://img.shields.io/badge/Follow%20%40Iris.framework-453-2D88FF.svg?style=for-the-badge&logo=facebook)](https://www.facebook.com/iris.framework)
+[![follow Iris web framework on facebook](https://img.shields.io/badge/Follow%20%40Iris.framework-460-2D88FF.svg?style=for-the-badge&logo=facebook)](https://www.facebook.com/iris.framework)
 
 You can [request](https://www.iris-go.com/#ebookDonateForm) a PDF and online access of the **Iris E-Book** (New Edition, **future v12.2.0+**) today and be participated in the development of Iris.
 

_examples/logging/request-logger/accesslog/main.go

@@ -12,6 +12,10 @@ import (
 	rotatelogs "github.com/lestrrat-go/file-rotatelogs"
 )
 
+// Default line format:
+// Time|Latency|Code|Method|Path|IP|Path Params Query Fields|Bytes Received|Bytes Sent|Request|Response|
+//
+// Read the example and its comments carefully.
 func makeAccessLog() *accesslog.AccessLog {
 	// Optionally, let's Go with log rotation.
 	pathToAccessLog := "./access_log.%Y%m%d%H%M"

middleware/accesslog/accesslog.go

@@ -6,6 +6,7 @@ import (
 	"io"
 	"net/http/httputil"
 	"os"
+	"strconv"
 	"strings"
 	"sync"
 	"time"
@@ -132,6 +133,12 @@ type AccessLog struct {
 	//
 	// Defaults to false.
 	Async bool
+
+	// The delimeter between fields when logging with the default format.
+	// See `SetFormatter` to customize the log even further.
+	//
+	// Defaults to '|'.
+	Delim rune
 	// The time format for current time on log print.
 	// Defaults to ""2006-01-02 15:04:05" on `New` function.
 	// Set it to empty to inherit the Iris Application's TimeFormat.
@@ -179,6 +186,7 @@ type AccessLog struct {
 	broker    *Broker
 
 	logsPool *sync.Pool
+	bufPool  *sync.Pool
 }
 
 // PanicLog holds the type for the available panic log levels.
@@ -207,6 +215,7 @@ const defaultTimeFormat = "2006-01-02 15:04:05"
 func New(w io.Writer) *AccessLog {
 	ac := &AccessLog{
 		Clock:              clockFunc(time.Now),
+		Delim:              defaultDelim,
 		TimeFormat:         defaultTimeFormat,
 		IP:                 true,
 		BytesReceived:      true,
@@ -218,6 +227,9 @@ func New(w io.Writer) *AccessLog {
 		logsPool: &sync.Pool{New: func() interface{} {
 			return new(Log)
 		}},
+		bufPool: &sync.Pool{New: func() interface{} {
+			return new(bytes.Buffer)
+		}},
 	}
 
 	if w == nil {
@@ -558,6 +570,8 @@ func (ac *AccessLog) after(ctx *context.Context, lat time.Duration, method, path
 	}
 }
 
+const defaultDelim = '|'
+
 // Print writes a log manually.
 // The `Handler` method calls it.
 func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeFormat string, code int, method, path, ip, reqBody, respBody string, bytesReceived, bytesSent int, params *context.RequestParams, query []memstore.StringEntry, fields []memstore.Entry) (err error) {
@@ -609,19 +623,45 @@ func (ac *AccessLog) Print(ctx *context.Context, latency time.Duration, timeForm
 
 	// the number of separators are the same, in order to be easier
 	// for 3rd-party programs to read the result log file.
-	_, err = fmt.Fprintf(ac, "%s|%s|%d|%s|%s|%s|%s|%s|%s|%s|%s|\n",
-		now.Format(timeFormat),
-		latency,
-		code,
-		method,
-		path,
-		ip,
-		requestValues,
-		formatBytes(bytesReceived),
-		formatBytes(bytesSent),
-		reqBody,
-		respBody,
-	)
+	builder := ac.bufPool.Get().(*bytes.Buffer)
+	builder.WriteString(now.Format(timeFormat))
+	builder.WriteRune(ac.Delim)
+
+	builder.WriteString(latency.String())
+	builder.WriteRune(ac.Delim)
+
+	builder.WriteString(strconv.Itoa(code))
+	builder.WriteRune(ac.Delim)
+
+	builder.WriteString(method)
+	builder.WriteRune(ac.Delim)
+
+	builder.WriteString(path)
+	builder.WriteRune(ac.Delim)
+
+	builder.WriteString(ip)
+	builder.WriteRune(ac.Delim)
+
+	builder.WriteString(requestValues)
+	builder.WriteRune(ac.Delim)
+
+	builder.WriteString(formatBytes(bytesReceived))
+	builder.WriteRune(ac.Delim)
+
+	builder.WriteString(formatBytes(bytesSent))
+	builder.WriteRune(ac.Delim)
+
+	builder.WriteString(reqBody)
+	builder.WriteRune(ac.Delim)
+
+	builder.WriteString(respBody)
+	builder.WriteRune(ac.Delim)
+
+	builder.WriteRune('\n')
+
+	ac.Write(builder.Bytes())
+	builder.Reset()
+	ac.bufPool.Put(builder)
 
 	return
 }

middleware/accesslog/accesslog_test.go

@@ -160,6 +160,14 @@ func (*noOpFormatter) Format(*Log) (bool, error) {
 
 // go test -run=^$ -bench=BenchmarkAccessLogAfter -benchmem
 func BenchmarkAccessLogAfter(b *testing.B) {
+	benchmarkAccessLogAfter(b, true, false)
+}
+
+func BenchmarkAccessLogAfterPrint(b *testing.B) {
+	benchmarkAccessLogAfter(b, false, false)
+}
+
+func benchmarkAccessLogAfter(b *testing.B, withLogStruct, async bool) {
 	ac := New(ioutil.Discard)
 	ac.Clock = TClock(time.Time{})
 	ac.BytesReceived = false
@@ -170,7 +178,10 @@ func BenchmarkAccessLogAfter(b *testing.B) {
 	ac.KeepMultiLineError = true
 	ac.Async = false
 	ac.IP = false
-	ac.SetFormatter(new(noOpFormatter)) // just to create the log structure.)
+	ac.LockWriter = async
+	if withLogStruct {
+		ac.SetFormatter(new(noOpFormatter)) // just to create the log structure, here we test the log creation time only.
+	}
 
 	ctx := new(context.Context)
 	req, err := http.NewRequest("GET", "/", nil)
@@ -183,9 +194,25 @@ func BenchmarkAccessLogAfter(b *testing.B) {
 	w.BeginResponse(recorder)
 	ctx.ResetResponseWriter(w)
 
+	wg := new(sync.WaitGroup)
+	if async {
+		wg.Add(b.N)
+	}
+
 	b.ResetTimer()
 	for n := 0; n < b.N; n++ {
-		ac.after(ctx, time.Millisecond, "GET", "/")
+		if async {
+			go func() {
+				ac.after(ctx, time.Millisecond, "GET", "/")
+				wg.Done()
+			}()
+		} else {
+			ac.after(ctx, time.Millisecond, "GET", "/")
+		}
+	}
+	b.StopTimer()
+	if async {
+		wg.Wait()
 	}
 	w.EndResponse()
 }