From a30bbb61f77c0772f41c6baf0656bacc7cfc7d31 Mon Sep 17 00:00:00 2001 From: "Gerasimos (Makis) Maropoulos" Date: Fri, 11 Sep 2020 23:22:18 +0300 Subject: [PATCH] accesslog: export the delimeter used on default formatter and improve its performance relative to: #1601 and #1622 --- README.md | 2 +- .../logging/request-logger/accesslog/main.go | 4 ++ middleware/accesslog/accesslog.go | 66 +++++++++++++++---- middleware/accesslog/accesslog_test.go | 31 ++++++++- 4 files changed, 87 insertions(+), 16 deletions(-) diff --git a/README.md b/README.md index fa9449ce..f41e8a12 100644 --- a/README.md +++ b/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. diff --git a/_examples/logging/request-logger/accesslog/main.go b/_examples/logging/request-logger/accesslog/main.go index 24e7c205..8467f8e0 100644 --- a/_examples/logging/request-logger/accesslog/main.go +++ b/_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" diff --git a/middleware/accesslog/accesslog.go b/middleware/accesslog/accesslog.go index eb7446d6..bb5804d1 100644 --- a/middleware/accesslog/accesslog.go +++ b/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 } diff --git a/middleware/accesslog/accesslog_test.go b/middleware/accesslog/accesslog_test.go index 3d414fb9..040cddb3 100644 --- a/middleware/accesslog/accesslog_test.go +++ b/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() }