From 1e0efb675899a9217d289db02c3f226b54e036c4 Mon Sep 17 00:00:00 2001 From: Emmanuel T Odeke Date: Fri, 28 May 2021 20:27:47 +0300 Subject: [PATCH] libs/log: use fmt.Fprintf directly with *bytes.Buffer to avoid unnecessary allocations (#6503) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Noticed from profiling that the loggers are memory hungry and alas, we were passing fmt.Sprintf strings to (*bytes.Buffer).WriteString which defeats the purpose of using fmt.* This change fixes that and instead directly invokes fmt.Fprintf. The benchmarks show the improvement: ```shell $ benchstat before.txt after.txt name old time/op new time/op delta TMLoggerSimple-8 1.67µs ± 4% 1.69µs ±13% ~ (p=0.118 n=20+19) TMLoggerContextual-8 2.01µs ± 8% 1.94µs ± 1% -3.79% (p=0.000 n=18+20) TMFmtLoggerSimple-8 1.20µs ± 3% 1.16µs ± 2% -3.39% (p=0.000 n=20+16) TMFmtLoggerContextual-8 1.53µs ±19% 1.43µs ±13% -6.10% (p=0.001 n=20+20) name old alloc/op new alloc/op delta TMLoggerSimple-8 696B ± 0% 616B ± 0% -11.49% (p=0.000 n=20+20) TMLoggerContextual-8 1.02kB ± 0% 0.94kB ± 0% -7.87% (p=0.000 n=20+20) TMFmtLoggerSimple-8 240B ± 0% 160B ± 0% -33.33% (p=0.000 n=20+20) TMFmtLoggerContextual-8 416B ± 0% 336B ± 0% -19.23% (p=0.000 n=20+20) name old allocs/op new allocs/op delta TMLoggerSimple-8 13.0 ± 0% 12.0 ± 0% -7.69% (p=0.000 n=20+20) TMLoggerContextual-8 17.0 ± 0% 16.0 ± 0% -5.88% (p=0.000 n=20+20) TMFmtLoggerSimple-8 6.00 ± 0% 5.00 ± 0% -16.67% (p=0.000 n=20+20) TMFmtLoggerContextual-8 8.00 ± 0% 7.00 ± 0% -12.50% (p=0.000 n=20+20) ``` Fixes #6502 --- libs/log/tmfmt_logger.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libs/log/tmfmt_logger.go b/libs/log/tmfmt_logger.go index c6004cc62..b9389b18e 100644 --- a/libs/log/tmfmt_logger.go +++ b/libs/log/tmfmt_logger.go @@ -98,7 +98,7 @@ func (l tmfmtLogger) Log(keyvals ...interface{}) error { // D - first character of the level, uppercase (ASCII only) // [2016-05-02|11:06:44.322] - our time format (see https://golang.org/src/time/format.go) // Stopping ... - message - enc.buf.WriteString(fmt.Sprintf("%c[%s] %-44s ", lvl[0]-32, time.Now().Format("2006-01-02|15:04:05.000"), msg)) + fmt.Fprintf(&enc.buf, "%c[%s] %-44s ", lvl[0]-32, time.Now().Format("2006-01-02|15:04:05.000"), msg) if module != unknown { enc.buf.WriteString("module=" + module + " ")