Codebase list golang-github-go-logr-logr / 75eaec3
funcr: Pre-render WithValues() This saves a potentially significant amount of time on each log call (Info()/Error()) at the cost of making WithValues() slower. Added a benchmark: before: ``` BenchmarkFuncrLogInfoWithValues-6 644568 1751 ns/op BenchmarkFuncrJSONLogInfoWithValues-6 669440 1788 ns/op ``` after: ``` BenchmarkFuncrLogInfoWithValues-6 868016 1254 ns/op BenchmarkFuncrJSONLogInfoWithValues-6 875338 1363 ns/op ``` Tim Hockin 2 years ago
3 changed file(s) with 80 addition(s) and 27 deletion(s). Raw diff Collapse all Expand all
+25
-0
benchmark/benchmark_test.go less more
4040 }
4141
4242 //go:noinline
43 func doInfoWithValues(b *testing.B, log logr.Logger) {
44 log = log.WithValues("k1", "str", "k2", 222, "k3", true, "k4", 1.0)
45 for i := 0; i < b.N; i++ {
46 log.Info("multi",
47 "bool", true, "string", "str", "int", 42,
48 "float", 3.14, "struct", struct{ X, Y int }{93, 76})
49 }
50 }
51
52 //go:noinline
4353 func doV0Info(b *testing.B, log logr.Logger) {
4454 for i := 0; i < b.N; i++ {
4555 log.V(0).Info("multi",
101111 doInfoSeveralArgs(b, log)
102112 }
103113
114 func BenchmarkDiscardLogInfoWithValues(b *testing.B) {
115 var log logr.Logger = logr.Discard()
116 doInfoWithValues(b, log)
117 }
118
104119 func BenchmarkDiscardLogV0Info(b *testing.B) {
105120 var log logr.Logger = logr.Discard()
106121 doV0Info(b, log)
149164 doInfoSeveralArgs(b, log)
150165 }
151166
167 func BenchmarkFuncrLogInfoWithValues(b *testing.B) {
168 var log logr.Logger = funcr.New(noopKV, funcr.Options{})
169 doInfoWithValues(b, log)
170 }
171
172 func BenchmarkFuncrJSONLogInfoWithValues(b *testing.B) {
173 var log logr.Logger = funcr.NewJSON(noopJSON, funcr.Options{})
174 doInfoWithValues(b, log)
175 }
176
152177 func BenchmarkFuncrLogV0Info(b *testing.B) {
153178 var log logr.Logger = funcr.New(noopKV, funcr.Options{})
154179 doV0Info(b, log)
+40
-16
funcr/funcr.go less more
174174 outputFormat outputFormat
175175 prefix string
176176 values []interface{}
177 valuesStr string
177178 depth int
178179 logCaller MessageClass
179180 logTimestamp bool
190191 outputJSON
191192 )
192193
193 func (f Formatter) flatten(kvList ...interface{}) string {
194 if len(kvList)%2 != 0 {
195 kvList = append(kvList, "<no-value>")
196 }
194 // render produces a log-line, ready to use.
195 func (f Formatter) render(builtins, args []interface{}) string {
197196 // Empirically bytes.Buffer is faster than strings.Builder for this.
198197 buf := bytes.NewBuffer(make([]byte, 0, 1024))
199198 if f.outputFormat == outputJSON {
200199 buf.WriteRune('{')
201200 }
201 f.flatten(buf, builtins, false)
202 continuing := len(builtins) > 0
203 if len(f.valuesStr) > 0 {
204 if continuing {
205 if f.outputFormat == outputJSON {
206 buf.WriteRune(',')
207 } else {
208 buf.WriteRune(' ')
209 }
210 }
211 continuing = true
212 buf.WriteString(f.valuesStr)
213 }
214 f.flatten(buf, args, continuing)
215 if f.outputFormat == outputJSON {
216 buf.WriteRune('}')
217 }
218 return buf.String()
219 }
220
221 // flatten renders a list of key-value pairs into a buffer. If continuing is
222 // true, it assumes that the buffer has previous values and will emit a
223 // separator (which depends on the output format) before the first pair it
224 // writes.
225 func (f Formatter) flatten(buf *bytes.Buffer, kvList []interface{}, continuing bool) {
226 if len(kvList)%2 != 0 {
227 kvList = append(kvList, "<no-value>")
228 }
202229 for i := 0; i < len(kvList); i += 2 {
203230 k, ok := kvList[i].(string)
204231 if !ok {
205 k = fmt.Sprintf("<non-string-key-%d>", i/2)
232 k = "<non-string-key>"
206233 }
207234 v := kvList[i+1]
208235
209 if i > 0 {
236 if i > 0 || continuing {
210237 if f.outputFormat == outputJSON {
211238 buf.WriteRune(',')
212239 } else {
225252 }
226253 buf.WriteString(f.pretty(v))
227254 }
228 if f.outputFormat == outputJSON {
229 buf.WriteRune('}')
230 }
231 return buf.String()
232255 }
233256
234257 func (f Formatter) pretty(value interface{}) string {
440463 args = append(args, "caller", f.caller())
441464 }
442465 args = append(args, "level", level, "msg", msg)
443 args = append(args, f.values...)
444 args = append(args, kvList...)
445 return prefix, f.flatten(args...)
466 return prefix, f.render(args, kvList)
446467 }
447468
448469 // FormatError flattens an Error log message into strings.
467488 loggableErr = err.Error()
468489 }
469490 args = append(args, "error", loggableErr)
470 args = append(args, f.values...)
471 args = append(args, kvList...)
472 return f.prefix, f.flatten(args...)
491 return f.prefix, f.render(args, kvList)
473492 }
474493
475494 // AddName appends the specified name. funcr uses '/' characters to separate
488507 // Three slice args forces a copy.
489508 n := len(f.values)
490509 f.values = append(f.values[:n:n], kvList...)
510
511 // Pre-render values, so we don't have to do it on each Info/Error call.
512 buf := bytes.NewBuffer(make([]byte, 0, 1024))
513 f.flatten(buf, f.values, false)
514 f.valuesStr = buf.String()
491515 }
492516
493517 // AddCallDepth increases the number of stack-frames to skip when attributing
+15
-11
funcr/funcr_test.go less more
200200 return args
201201 }
202202
203 func TestFlatten(t *testing.T) {
203 func TestRender(t *testing.T) {
204204 testCases := []struct {
205205 name string
206206 kv []interface{}
229229 }, {
230230 name: "non-string key",
231231 kv: makeKV(123, "val"),
232 expectKV: `"<non-string-key-0>"="val"`,
233 expectJSON: `{"<non-string-key-0>":"val"}`,
232 expectKV: `"<non-string-key>"="val"`,
233 expectJSON: `{"<non-string-key>":"val"}`,
234234 }}
235235
236236 fKV := NewFormatter(Options{})
237237 fJSON := NewFormatterJSON(Options{})
238238 for _, tc := range testCases {
239239 t.Run(tc.name, func(t *testing.T) {
240 r := fKV.flatten(tc.kv...)
241 if r != tc.expectKV {
242 t.Errorf("expected %q, got %q", tc.expectKV, r)
243 }
244 r = fJSON.flatten(tc.kv...)
245 if r != tc.expectJSON {
246 t.Errorf("expected %q, got %q", tc.expectJSON, r)
247 }
240 t.Run("KV", func(t *testing.T) {
241 r := fKV.render(tc.kv, nil)
242 if r != tc.expectKV {
243 t.Errorf("wrong KV output:\nexpected %q\n got %q", tc.expectKV, r)
244 }
245 })
246 t.Run("JSON", func(t *testing.T) {
247 r := fJSON.render(tc.kv, nil)
248 if r != tc.expectJSON {
249 t.Errorf("wrong JSON output:\nexpected %q\n got %q", tc.expectJSON, r)
250 }
251 })
248252 })
249253 }
250254 }