Skip to content

Instantly share code, notes, and snippets.

@ginokent

ginokent/README.md

Last active February 21, 2022 01:24
Show Gist options
  • Save ginokent/68941357e83adb7e441e0197e94e21ea to your computer and use it in GitHub Desktop.
Save ginokent/68941357e83adb7e441e0197e94e21ea to your computer and use it in GitHub Desktop.
Download ZIP
Raw
README.md

Benchmark comparison rec.go with major logger libraries.

Comparison of benchmark results

Benchmark results are compared using benchstat.

Output of log entries with common JSON log format:

log sample:

{"timestamp":"2021-12-12T18:37:38.650683+09:00","severity":"INFO","caller":"/Users/newtstat/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/rec_____benchmark_test.go:40","message":"benchmark"}

result:

logger time/op delta
rec.go 2.03µs ± 2% -
zap 7.71µs ± 7% +279.07%
zerolog 2.13µs ±10% ~
logger alloc/op bytes delta
rec.go 208B ± 0% -
zap 328B ± 0% +57.69%
zerolog 328B ± 0% +57.69%
logger allocs/op times delta
rec.go 1.00 ± 0% -
zap 3.00 ± 0% +200.00%
zerolog 3.00 ± 0% +200.00%

Output of log entries with common JSON log format and 10 string fields:

log sample:

{"timestamp":"2021-12-12T18:37:55.616187+09:00","severity":"INFO","caller":"/Users/newtstat/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/rec_____benchmark_test.go:62","message":"benchmark","key0":"value0","key1":"value1","key2":"value2","key3":"value3","key4":"value4","key5":"value5","key6":"value6","key7":"value7","key8":"value8","key9":"value9"}

result:

logger time/op delta
rec.go 3.50µs ±10% -
zap 8.77µs ±11% +150.36%
zerolog 2.60µs ± 1% -25.87%
logger alloc/op bytes delta
rec.go 208B ± 0% -
zap 970B ± 0% +366.35%
zerolog 336B ± 0% +61.54%
logger allocs/op times delta
rec.go 1.00 ± 0% -
zap 4.00 ± 0% +300.00%
zerolog 4.00 ± 0% +300.00%

Output of log entries with common JSON log format and 1 error field:

log sample:

{"timestamp":"2021-12-12T18:38:25.405149+09:00","severity":"INFO","caller":"/Users/newtstat/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/rec_____benchmark_test.go:95","message":"benchmark","error":"EOF"}

result:

logger time/op delta
rec.go 2.25µs ± 7% -
zap 8.24µs ±10% +266.51%
zerolog 7.76µs ± 6% +245.24%
logger alloc/op bytes delta
rec.go 208B ± 0% -
zap 392B ± 0% +88.65%
zerolog 336B ± 0% +61.54%
logger allocs/op times delta
rec.go 1.00 ± 0% -
zap 4.00 ± 0% +300.00%
zerolog 4.00 ± 0% +300.00%

Output of log entries with common JSON log format and 10 error fields:

log sample:

{"timestamp":"2021-12-12T01:27:24.139634+09:00","severity":"INFO","caller":"/Users/newtstat/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/rec_benchmark_test.go:71","message":"benchmark","err0":"EOF","err1":"EOF","err2":"EOF","err3":"EOF","err4":"EOF","err5":"EOF","err6":"EOF","err7":"EOF","err8":"EOF","err9":"EOF"}

result:

logger time/op delta
rec.go 2.90µs ±10% -
zap 9.10µs ± 8% +213.74%
zerolog 7.91µs ± 7% +172.62%
logger alloc/op bytes delta
rec.go 208B ± 0% -
zap 970B ± 0% +366.35%
zerolog 336B ± 0% +61.54%
logger allocs/op times delta
rec.go 1.00 ± 0% -
zap 4.00 ± 0% +300.00%
zerolog 4.00 ± 0% +300.00%

Results

$ ./benchmark.sh
2021-12-16T03:37:38+09:00 [     INFO] clean up
2021-12-16T03:37:38+09:00 [     INFO] $ rm -f /tmp/rec_benchmark_msgnofld.log /tmp/zap_benchmark_msgnofld.log /tmp/zerolog_benchmark_msgnofld.log /tmp/rec_benchmark_str10fld.log /tmp/zap_benchmark_str10fld.log /tmp/zerolog_benchmark_str10fld.log /tmp/rec_benchmark_err01fld.log /tmp/zap_benchmark_err01fld.log /tmp/zerolog_benchmark_err01fld.log /tmp/rec_benchmark_err10fld.log /tmp/zap_benchmark_err10fld.log /tmp/zerolog_benchmark_err10fld.log

2021-12-16T03:37:39+09:00 [     INFO] $ go test -v -o /tmp/rec.test -bench ^BenchmarkRec$ -benchmem -benchtime=3000ms -count=5 -cpuprofile=/tmp/rec.cpu.prof
goos: darwin
goarch: amd64
pkg: benchmark
cpu: Intel(R) Core(TM) i7-9750H CPU @ 2.60GHz
BenchmarkRec
BenchmarkRec/benchmark.msgnofldRec
BenchmarkRec/benchmark.msgnofldRec-12            1709815              2053 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.msgnofldRec-12            1747734              2061 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.msgnofldRec-12            1691269              2058 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.msgnofldRec-12            1796599              1998 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.msgnofldRec-12            1777950              2002 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.str10fldRec
BenchmarkRec/benchmark.str10fldRec-12            1054396              3235 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.str10fldRec-12            1000000              3367 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.str10fldRec-12             997844              3710 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.str10fldRec-12             921213              3864 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.str10fldRec-12            1105514              3343 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.err01fldRec
BenchmarkRec/benchmark.err01fldRec-12            1482550              2416 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.err01fldRec-12            1618983              2154 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.err01fldRec-12            1641285              2208 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.err01fldRec-12            1621483              2234 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.err01fldRec-12            1578942              2229 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.err10fldRec
BenchmarkRec/benchmark.err10fldRec-12            1255753              2716 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.err10fldRec-12            1284099              2716 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.err10fldRec-12            1258257              2797 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.err10fldRec-12            1000000              3199 ns/op             208 B/op          1 allocs/op
BenchmarkRec/benchmark.err10fldRec-12            1000000              3077 ns/op             208 B/op          1 allocs/op
PASS
ok      benchmark       106.377s

2021-12-16T03:39:29+09:00 [     INFO] $ go test -v -o /tmp/rec.test -bench ^BenchmarkZap$ -benchmem -benchtime=3000ms -count=5 -cpuprofile=/tmp/zap.cpu.prof
goos: darwin
goarch: amd64
pkg: benchmark
cpu: Intel(R) Core(TM) i7-9750H CPU @ 2.60GHz
BenchmarkZap
BenchmarkZap/benchmark.msgnofldZap
BenchmarkZap/benchmark.msgnofldZap-12             492597              8266 ns/op             328 B/op          3 allocs/op
BenchmarkZap/benchmark.msgnofldZap-12             454812              7449 ns/op             328 B/op          3 allocs/op
BenchmarkZap/benchmark.msgnofldZap-12             503792              7213 ns/op             328 B/op          3 allocs/op
BenchmarkZap/benchmark.msgnofldZap-12             486175              7502 ns/op             328 B/op          3 allocs/op
BenchmarkZap/benchmark.msgnofldZap-12             373312              8129 ns/op             328 B/op          3 allocs/op
BenchmarkZap/benchmark.str10fldZap
BenchmarkZap/benchmark.str10fldZap-12             456920              8524 ns/op             970 B/op          4 allocs/op
BenchmarkZap/benchmark.str10fldZap-12             422215              8288 ns/op             970 B/op          4 allocs/op
BenchmarkZap/benchmark.str10fldZap-12             387847              8879 ns/op             970 B/op          4 allocs/op
BenchmarkZap/benchmark.str10fldZap-12             416850              8434 ns/op             970 B/op          4 allocs/op
BenchmarkZap/benchmark.str10fldZap-12             318793              9736 ns/op             970 B/op          4 allocs/op
BenchmarkZap/benchmark.err01fldZap
BenchmarkZap/benchmark.err01fldZap-12             517747              8324 ns/op             393 B/op          4 allocs/op
BenchmarkZap/benchmark.err01fldZap-12             471072              8279 ns/op             392 B/op          4 allocs/op
BenchmarkZap/benchmark.err01fldZap-12             358417              9035 ns/op             393 B/op          4 allocs/op
BenchmarkZap/benchmark.err01fldZap-12             462370              7686 ns/op             392 B/op          4 allocs/op
BenchmarkZap/benchmark.err01fldZap-12             454407              7875 ns/op             392 B/op          4 allocs/op
BenchmarkZap/benchmark.err10fldZap
BenchmarkZap/benchmark.err10fldZap-12             448843              8332 ns/op             970 B/op          4 allocs/op
BenchmarkZap/benchmark.err10fldZap-12             385429              9294 ns/op             970 B/op          4 allocs/op
BenchmarkZap/benchmark.err10fldZap-12             334862              8966 ns/op             970 B/op          4 allocs/op
BenchmarkZap/benchmark.err10fldZap-12             395906              9824 ns/op             970 B/op          4 allocs/op
BenchmarkZap/benchmark.err10fldZap-12             390951              9092 ns/op             970 B/op          4 allocs/op
PASS
ok      benchmark       107.066s

2021-12-16T03:41:18+09:00 [     INFO] $ go test -v -o /tmp/rec.test -bench ^BenchmarkZerolog$ -benchmem -benchtime=3000ms -count=5 -cpuprofile=/tmp/zerolog.cpu.prof
goos: darwin
goarch: amd64
pkg: benchmark
cpu: Intel(R) Core(TM) i7-9750H CPU @ 2.60GHz
BenchmarkZerolog
BenchmarkZerolog/benchmark.msgnofldZerolog
BenchmarkZerolog/benchmark.msgnofldZerolog-12            1694060              2173 ns/op             328 B/op          3 allocs/op
BenchmarkZerolog/benchmark.msgnofldZerolog-12            1646575              2295 ns/op             328 B/op          3 allocs/op
BenchmarkZerolog/benchmark.msgnofldZerolog-12            1884441              1928 ns/op             328 B/op          3 allocs/op
BenchmarkZerolog/benchmark.msgnofldZerolog-12            1620259              2317 ns/op             328 B/op          3 allocs/op
BenchmarkZerolog/benchmark.msgnofldZerolog-12            1787832              1958 ns/op             328 B/op          3 allocs/op
BenchmarkZerolog/benchmark.str10fldZerolog
BenchmarkZerolog/benchmark.str10fldZerolog-12            1291003              2610 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.str10fldZerolog-12            1336137              2570 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.str10fldZerolog-12            1346000              2617 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.str10fldZerolog-12            1405378              2608 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.str10fldZerolog-12            1351738              2582 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.err01fldZerolog
BenchmarkZerolog/benchmark.err01fldZerolog-12             536658              7924 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.err01fldZerolog-12             461550              8248 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.err01fldZerolog-12             479190              7474 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.err01fldZerolog-12             428580              7623 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.err01fldZerolog-12             488318              7539 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.err10fldZerolog
BenchmarkZerolog/benchmark.err10fldZerolog-12             415804              7375 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.err10fldZerolog-12             446952              8056 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.err10fldZerolog-12             379148              8111 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.err10fldZerolog-12             466863              7961 ns/op             336 B/op          4 allocs/op
BenchmarkZerolog/benchmark.err10fldZerolog-12             443790              8041 ns/op             336 B/op          4 allocs/op
PASS
ok      benchmark       113.033s

2021-12-16T03:43:12+09:00 [     INFO] show tail log
2021-12-16T03:43:12+09:00 [     INFO] $ tail -n 1 /tmp/rec_benchmark_msgnofld.log /tmp/zap_benchmark_msgnofld.log /tmp/zerolog_benchmark_msgnofld.log /tmp/rec_benchmark_str10fld.log /tmp/zap_benchmark_str10fld.log /tmp/zerolog_benchmark_str10fld.log /tmp/rec_benchmark_err01fld.log /tmp/zap_benchmark_err01fld.log /tmp/zerolog_benchmark_err01fld.log /tmp/rec_benchmark_err10fld.log /tmp/zap_benchmark_err10fld.log /tmp/zerolog_benchmark_err10fld.log
==> /tmp/rec_benchmark_msgnofld.log <==
{"timestamp":"2021-12-16T03:38:09.083799+09:00","severity":"INFO","caller":"/Users/kentaro.ogino/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/rec_____benchmark_test.go:40","message":"benchmark"}

==> /tmp/zap_benchmark_msgnofld.log <==
{"severity":"INFO","timestamp":"2021-12-16T03:39:58.573486+09:00","caller":"/Users/kentaro.ogino/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/zap_____benchmark_test.go:58","message":"benchmark"}

==> /tmp/zerolog_benchmark_msgnofld.log <==
{"severity":"info","timestamp":"2021-12-16T03:41:48.356838+09:00","caller":"/Users/kentaro.ogino/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/zerolog_benchmark_test.go:56","message":"benchmark"}

==> /tmp/rec_benchmark_str10fld.log <==
{"timestamp":"2021-12-16T03:38:32.294801+09:00","severity":"INFO","caller":"/Users/kentaro.ogino/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/rec_____benchmark_test.go:62","message":"benchmark","key0":"value0","key1":"value1","key2":"value2","key3":"value3","key4":"value4","key5":"value5","key6":"value6","key7":"value7","key8":"value8","key9":"value9"}

==> /tmp/zap_benchmark_str10fld.log <==
{"severity":"INFO","timestamp":"2021-12-16T03:40:24.399351+09:00","caller":"/Users/kentaro.ogino/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/zap_____benchmark_test.go:100","message":"benchmark","key0":"value0","key1":"value1","key2":"value2","key3":"value3","key4":"value4","key5":"value5","key6":"value6","key7":"value7","key8":"value8","key9":"value9"}

==> /tmp/zerolog_benchmark_str10fld.log <==
{"severity":"info","key0":"value0","key1":"value1","key2":"value2","key3":"value3","key4":"value4","key5":"value5","key6":"value6","key7":"value7","key8":"value8","key9":"value9","timestamp":"2021-12-16T03:42:19.375573+09:00","caller":"/Users/kentaro.ogino/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/zerolog_benchmark_test.go:105","message":"benchmark"}

==> /tmp/rec_benchmark_err01fld.log <==
{"timestamp":"2021-12-16T03:39:01.617593+09:00","severity":"INFO","caller":"/Users/kentaro.ogino/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/rec_____benchmark_test.go:95","message":"benchmark","error":"EOF"}

==> /tmp/zap_benchmark_err01fld.log <==
{"severity":"INFO","timestamp":"2021-12-16T03:40:48.101658+09:00","caller":"/Users/kentaro.ogino/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/zap_____benchmark_test.go:153","message":"benchmark","error":"EOF"}

==> /tmp/zerolog_benchmark_err01fld.log <==
{"severity":"info","error":"EOF","timestamp":"2021-12-16T03:42:49.346012+09:00","caller":"/Users/kentaro.ogino/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/zerolog_benchmark_test.go:144","message":"benchmark"}

==> /tmp/rec_benchmark_err10fld.log <==
{"timestamp":"2021-12-16T03:39:27.010308+09:00","severity":"INFO","caller":"/Users/kentaro.ogino/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/rec_____benchmark_test.go:119","message":"benchmark","err0":"EOF","err1":"EOF","err2":"EOF","err3":"EOF","err4":"EOF","err5":"EOF","err6":"EOF","err7":"EOF","err8":"EOF","err9":"EOF"}

==> /tmp/zap_benchmark_err10fld.log <==
{"severity":"INFO","timestamp":"2021-12-16T03:41:17.996088+09:00","caller":"/Users/kentaro.ogino/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/zap_____benchmark_test.go:197","message":"benchmark","err0":"EOF","err1":"EOF","err2":"EOF","err3":"EOF","err4":"EOF","err5":"EOF","err6":"EOF","err7":"EOF","err8":"EOF","err9":"EOF"}

==> /tmp/zerolog_benchmark_err10fld.log <==
{"severity":"info","err0":"EOF","err1":"EOF","err2":"EOF","err3":"EOF","err4":"EOF","err5":"EOF","err6":"EOF","err7":"EOF","err8":"EOF","err9":"EOF","timestamp":"2021-12-16T03:43:12.426927+09:00","caller":"/Users/kentaro.ogino/go/src/gist.github.com/rec-logger/rec_benchmark_test.go/zerolog_benchmark_test.go:192","message":"benchmark"}

2021-12-16T03:43:12+09:00 [     INFO] benchstat rec.go -> zap
2021-12-16T03:43:13+09:00 [     INFO] $ benchstat /tmp/rec_benchmark_result.log /tmp/zap_benchmark_result.log
name         old time/op    new time/op    delta
msgnofld-12    2.03µs ± 2%    7.71µs ± 7%  +279.07%  (p=0.008 n=5+5)
str10fld-12    3.50µs ±10%    8.77µs ±11%  +150.36%  (p=0.008 n=5+5)
err01fld-12    2.25µs ± 7%    8.24µs ±10%  +266.51%  (p=0.008 n=5+5)
err10fld-12    2.90µs ±10%    9.10µs ± 8%  +213.74%  (p=0.008 n=5+5)

name         old alloc/op   new alloc/op   delta
msgnofld-12      208B ± 0%      328B ± 0%   +57.69%  (p=0.008 n=5+5)
str10fld-12      208B ± 0%      970B ± 0%  +366.35%  (p=0.008 n=5+5)
err01fld-12      208B ± 0%      392B ± 0%   +88.65%  (p=0.008 n=5+5)
err10fld-12      208B ± 0%      970B ± 0%  +366.35%  (p=0.008 n=5+5)

name         old allocs/op  new allocs/op  delta
msgnofld-12      1.00 ± 0%      3.00 ± 0%  +200.00%  (p=0.008 n=5+5)
str10fld-12      1.00 ± 0%      4.00 ± 0%  +300.00%  (p=0.008 n=5+5)
err01fld-12      1.00 ± 0%      4.00 ± 0%  +300.00%  (p=0.008 n=5+5)
err10fld-12      1.00 ± 0%      4.00 ± 0%  +300.00%  (p=0.008 n=5+5)

2021-12-16T03:43:13+09:00 [     INFO] benchstat rec.go -> zerolog
2021-12-16T03:43:13+09:00 [     INFO] $ benchstat /tmp/rec_benchmark_result.log /tmp/zerolog_benchmark_result.log
name         old time/op    new time/op    delta
msgnofld-12    2.03µs ± 2%    2.13µs ±10%      ~     (p=0.690 n=5+5)
str10fld-12    3.50µs ±10%    2.60µs ± 1%   -25.87%  (p=0.008 n=5+5)
err01fld-12    2.25µs ± 7%    7.76µs ± 6%  +245.24%  (p=0.008 n=5+5)
err10fld-12    2.90µs ±10%    7.91µs ± 7%  +172.62%  (p=0.008 n=5+5)

name         old alloc/op   new alloc/op   delta
msgnofld-12      208B ± 0%      328B ± 0%   +57.69%  (p=0.008 n=5+5)
str10fld-12      208B ± 0%      336B ± 0%   +61.54%  (p=0.008 n=5+5)
err01fld-12      208B ± 0%      336B ± 0%   +61.54%  (p=0.008 n=5+5)
err10fld-12      208B ± 0%      336B ± 0%   +61.54%  (p=0.008 n=5+5)

name         old allocs/op  new allocs/op  delta
msgnofld-12      1.00 ± 0%      3.00 ± 0%  +200.00%  (p=0.008 n=5+5)
str10fld-12      1.00 ± 0%      4.00 ± 0%  +300.00%  (p=0.008 n=5+5)
err01fld-12      1.00 ± 0%      4.00 ± 0%  +300.00%  (p=0.008 n=5+5)
err10fld-12      1.00 ± 0%      4.00 ± 0%  +300.00%  (p=0.008 n=5+5)
Raw
benchmark.sh
#!/usr/bin/env bash
set -Eeou pipefail
# MIT License Copyright (c) 2021 newtstat https://github.com/rec-logger/rec.sh
# Common
_recRFC3339() { date "+%Y-%m-%dT%H:%M:%S%z" | sed "s/\(..\)$/:\1/"; }
_recCmd() { for a in "$@"; do if echo "${a:-}" | grep -Eq "[[:blank:]]"; then printf "'%s' " "${a:-}"; else printf "%s " "${a:-}"; fi; done | sed "s/ $//"; }
# Color
RecDefault() { test "${REC_SEVERITY:-0 }" -gt 000 2>/dev/null || echo "$*" | awk "{print \"$(_recRFC3339) [\\033[0;35m DEFAULT\\033[0m] \"\$0\"\"}" 1>&2; }
RecDebug() { test "${REC_SEVERITY:-0 }" -gt 100 2>/dev/null || echo "$*" | awk "{print \"$(_recRFC3339) [\\033[0;34m DEBUG\\033[0m] \"\$0\"\"}" 1>&2; }
RecInfo() { test "${REC_SEVERITY:-0 }" -gt 200 2>/dev/null || echo "$*" | awk "{print \"$(_recRFC3339) [\\033[0;32m INFO\\033[0m] \"\$0\"\"}" 1>&2; }
RecNotice() { test "${REC_SEVERITY:-0 }" -gt 300 2>/dev/null || echo "$*" | awk "{print \"$(_recRFC3339) [\\033[0;36m NOTICE\\033[0m] \"\$0\"\"}" 1>&2; }
RecWarning() { test "${REC_SEVERITY:-0 }" -gt 400 2>/dev/null || echo "$*" | awk "{print \"$(_recRFC3339) [\\033[0;33m WARNING\\033[0m] \"\$0\"\"}" 1>&2; }
RecError() { test "${REC_SEVERITY:-0 }" -gt 500 2>/dev/null || echo "$*" | awk "{print \"$(_recRFC3339) [\\033[0;31m ERROR\\033[0m] \"\$0\"\"}" 1>&2; }
RecCritical() { test "${REC_SEVERITY:-0 }" -gt 600 2>/dev/null || echo "$*" | awk "{print \"$(_recRFC3339) [\\033[0;1;31m CRITICAL\\033[0m] \"\$0\"\"}" 1>&2; }
RecAlert() { test "${REC_SEVERITY:-0 }" -gt 700 2>/dev/null || echo "$*" | awk "{print \"$(_recRFC3339) [\\033[0;41m ALERT\\033[0m] \"\$0\"\"}" 1>&2; }
RecEmergency() { test "${REC_SEVERITY:-0}" -gt 800 2>/dev/null || echo "$*" | awk "{print \"$(_recRFC3339) [\\033[0;1;41mEMERGENCY\\033[0m] \"\$0\"\"}" 1>&2; }
RecExec() { RecInfo "$ $(_recCmd "$@")" && "$@"; }
RecRun() { _dlm='####R#E#C#D#E#L#I#M#I#T#E#R####' _all=$({ _out=$("$@") && _rtn=$? || _rtn=$? && printf "\n%s" "${_dlm:?}${_out:-}" && return ${_rtn:-0}; } 2>&1) && _rtn=$? || _rtn=$? && _dlmno=$(echo "${_all:-}" | sed -n "/${_dlm:?}/=") && _cmd=$(_recCmd "$@") && _stdout=$(echo "${_all:-}" | tail -n +"${_dlmno:-1}" | sed "s/^${_dlm:?}//") && _stderr=$(echo "${_all:-}" | head -n "${_dlmno:-1}" | grep -v "^${_dlm:?}") && RecInfo "$ ${_cmd:-}" && RecInfo "${_stdout:-}" && { [ -z "${_stderr:-}" ] || RecWarning "${_stderr:-}"; } && return ${_rtn:-0}; }
logfiles=(
# msgnofld
/tmp/rec_benchmark_msgnofld.log
/tmp/zap_benchmark_msgnofld.log
/tmp/zerolog_benchmark_msgnofld.log
# str10fld
/tmp/rec_benchmark_str10fld.log
/tmp/zap_benchmark_str10fld.log
/tmp/zerolog_benchmark_str10fld.log
# err01fld
/tmp/rec_benchmark_err01fld.log
/tmp/zap_benchmark_err01fld.log
/tmp/zerolog_benchmark_err01fld.log
# err10fld
/tmp/rec_benchmark_err10fld.log
/tmp/zap_benchmark_err10fld.log
/tmp/zerolog_benchmark_err10fld.log
)
RecInfo "clean up"
RecExec rm -f "${logfiles[@]}"
echo
RecExec go test -v -o /tmp/rec.test -bench '^BenchmarkRec$' -benchmem -benchtime=3000ms -count=5 -cpuprofile=/tmp/rec.cpu.prof | tee /dev/stderr | sed 's@Rec@@g; s@/benchmark\.@@g' > /tmp/rec_benchmark_result.log
echo
RecExec go test -v -o /tmp/rec.test -bench '^BenchmarkZap$' -benchmem -benchtime=3000ms -count=5 -cpuprofile=/tmp/zap.cpu.prof | tee /dev/stderr | sed 's@Zap@@g; s@/benchmark\.@@g' > /tmp/zap_benchmark_result.log
echo
RecExec go test -v -o /tmp/rec.test -bench '^BenchmarkZerolog$' -benchmem -benchtime=3000ms -count=5 -cpuprofile=/tmp/zerolog.cpu.prof | tee /dev/stderr | sed 's@Zerolog@@g; s@/benchmark\.@@g' > /tmp/zerolog_benchmark_result.log
echo
RecInfo "show tail log"
RecExec tail -n 1 "${logfiles[@]}"
echo
RecInfo "benchstat rec.go -> zap"
RecExec benchstat /tmp/{rec,zap}_benchmark_result.log
echo
RecInfo "benchstat rec.go -> zerolog"
RecExec benchstat /tmp/{rec,zerolog}_benchmark_result.log
echo
Raw
common_test.go
package benchmark
import (
"fmt"
"io/fs"
"os"
)
func mustOpenFile(name string, flag int, perm fs.FileMode) *os.File {
f, err := os.OpenFile(name, flag, perm)
if err != nil {
panic(fmt.Errorf("%s: %w", name, err))
}
return f
}
Raw
go.mod
module benchmark
go 1.17
require (
github.com/rec-logger/rec.go v0.0.0-20220221012023-21669feacd49
github.com/rs/zerolog v1.26.0
go.uber.org/zap v1.19.1
golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1
)
require (
go.uber.org/atomic v1.7.0 // indirect
go.uber.org/multierr v1.6.0 // indirect
)
Raw
go.sum
github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLju8=
github.com/benbjohnson/clock v1.1.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZxNJlLklBHA=
github.com/coreos/go-systemd/v22 v22.3.2/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
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=
github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
github.com/rec-logger/rec.go v0.0.0-20220221012023-21669feacd49 h1:zt6IdKllAQelJChsVcJRMIiXKKTo8d6K3pggAt+rgr0=
github.com/rec-logger/rec.go v0.0.0-20220221012023-21669feacd49/go.mod h1:S4MXn5lMCYhIFPHQkNbqT2UjYT0i85eDAuF8Nv0c7+o=
github.com/rs/xid v1.3.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
github.com/rs/zerolog v1.26.0 h1:ORM4ibhEZeTeQlCojCK2kPz1ogAY4bGs4tD+SaAdGaE=
github.com/rs/zerolog v1.26.0/go.mod h1:yBiM87lvSqX8h0Ww4sdzNSkVYZ8dL2xjZJG1lAuGZEo=
github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY=
github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
github.com/yuin/goldmark v1.3.5/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k=
github.com/yuin/goldmark v1.4.0/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k=
go.uber.org/atomic v1.7.0 h1:ADUqmZGgLDDfbSL9ZmPxKTybcoEYHgpYfELNoN+7hsw=
go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
go.uber.org/goleak v1.1.11-0.20210813005559-691160354723 h1:sHOAIxRGBp443oHZIPB+HsUGaksVCXVQENPxwTfQdH4=
go.uber.org/goleak v1.1.11-0.20210813005559-691160354723/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ=
go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4=
go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU=
go.uber.org/zap v1.19.1 h1:ue41HOKd1vGURxrmeKIgELGb3jPW9DMUDGtsinblHwI=
go.uber.org/zap v1.19.1/go.mod h1:j3DNczoxDZroyBnOT1L/Q79cfUMGZxlv/9dzN7SM1rI=
golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
golang.org/x/lint v0.0.0-20190930215403-16217165b5de/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc=
golang.org/x/mod v0.4.2/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
golang.org/x/net v0.0.0-20210405180319-a5a99cb37ef4/go.mod h1:p54w0d4576C0XHj96bSt6lcn1PtDYWL6XObtHCRCNQM=
golang.org/x/net v0.0.0-20210805182204-aaa1db679c0d/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y=
golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
golang.org/x/sync v0.0.0-20210220032951-036812b2e83c/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20210330210617-4fbd30eecc44/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/sys v0.0.0-20210510120138-977fb7262007/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.0.0-20210809222454-d867a43fc93e/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
golang.org/x/tools v0.0.0-20190311212946-11955173bddd/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs=
golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
golang.org/x/tools v0.1.5/go.mod h1:o0xws9oXOQQZyjljx8fwUC0k7L1pTE6eaCbjGeHmOkk=
golang.org/x/tools v0.1.7/go.mod h1:LGqMHiF4EqQNHR1JncWGqT5BVaXmza+X+BDGol+dOxo=
golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 h1:go1bK/D/BFZV2I8cIQd1NKEZ+0owSTG1fDTci4IqFcE=
golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10=
gopkg.in/yaml.v2 v2.2.8/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b h1:h8qDotaEPuJATrMmW04NCwg7v22aHH28wwpauUhK9Oo=
gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
Raw
rec_____benchmark_test.go
package benchmark
import (
"bufio"
"io"
"os"
"path/filepath"
"runtime"
"testing"
"time"
"github.com/rec-logger/rec.go"
"golang.org/x/xerrors"
)
func BenchmarkRec(b *testing.B) {
msgnofldRec(b, mustOpenFile("/tmp/rec_benchmark_msgnofld.log", os.O_CREATE|os.O_RDWR, 0o600))
str10fldRec(b, mustOpenFile("/tmp/rec_benchmark_str10fld.log", os.O_CREATE|os.O_RDWR, 0o600))
err01fldRec(b, mustOpenFile("/tmp/rec_benchmark_err01fld.log", os.O_CREATE|os.O_RDWR, 0o600))
err10fldRec(b, mustOpenFile("/tmp/rec_benchmark_err10fld.log", os.O_CREATE|os.O_RDWR, 0o600))
}
func msgnofldRec(b *testing.B, writer io.Writer) {
pc, _, _, _ := runtime.Caller(0)
fn := runtime.FuncForPC(pc)
bufWriter := bufio.NewWriter(writer)
defer func() {
if err := bufWriter.Flush(); err != nil {
err = xerrors.Errorf("Flush: %w", err)
rec.L().Error(err.Error(), rec.Error(err), rec.ErrorStacktrace(err))
}
}()
l := rec.Must(rec.New(bufWriter, rec.WithUseTimestampField(true), rec.WithTimestampFieldFormat(time.RFC3339Nano), rec.WithUseSeverityField(true), rec.WithUseHostnameField(false), rec.WithUseCallerField(true), rec.WithUseShortCaller(false)))
b.Run(fn.Name(), func(b *testing.B) {
b.ResetTimer()
for i := 0; i < b.N; i++ {
l.Info("benchmark")
}
})
}
func str10fldRec(b *testing.B, writer io.Writer) {
pc, _, _, _ := runtime.Caller(0)
fn := runtime.FuncForPC(pc)
bufWriter := bufio.NewWriter(writer)
defer func() {
if err := bufWriter.Flush(); err != nil {
err = xerrors.Errorf("Flush: %w", err)
rec.L().Error(err.Error(), rec.Error(err), rec.ErrorStacktrace(err))
}
}()
l := rec.Must(rec.New(bufWriter, rec.WithUseTimestampField(true), rec.WithTimestampFieldFormat(time.RFC3339Nano), rec.WithUseSeverityField(true), rec.WithUseHostnameField(false), rec.WithUseCallerField(true), rec.WithUseShortCaller(false)))
b.Run(fn.Name(), func(b *testing.B) {
b.ResetTimer()
for i := 0; i < b.N; i++ {
l.Info("benchmark",
rec.String("key0", "value0"),
rec.String("key1", "value1"),
rec.String("key2", "value2"),
rec.String("key3", "value3"),
rec.String("key4", "value4"),
rec.String("key5", "value5"),
rec.String("key6", "value6"),
rec.String("key7", "value7"),
rec.String("key8", "value8"),
rec.String("key9", "value9"),
)
}
})
}
func err01fldRec(b *testing.B, writer io.Writer) {
pc, _, _, _ := runtime.Caller(0)
fn := runtime.FuncForPC(pc)
bufWriter := bufio.NewWriter(writer)
defer func() {
if err := bufWriter.Flush(); err != nil {
err = xerrors.Errorf("Flush: %w", err)
rec.L().Error(err.Error(), rec.Error(err), rec.ErrorStacktrace(err))
}
}()
l := rec.Must(rec.New(bufWriter, rec.WithUseTimestampField(true), rec.WithTimestampFieldFormat(time.RFC3339Nano), rec.WithUseSeverityField(true), rec.WithUseHostnameField(false), rec.WithUseCallerField(true), rec.WithUseShortCaller(false)))
b.Run(filepath.Base(fn.Name()), func(b *testing.B) {
b.ResetTimer()
for i := 0; i < b.N; i++ {
l.Info("benchmark",
rec.Error(io.EOF),
)
}
})
}
func err10fldRec(b *testing.B, writer io.Writer) {
pc, _, _, _ := runtime.Caller(0)
fn := runtime.FuncForPC(pc)
bufWriter := bufio.NewWriter(writer)
defer func() {
if err := bufWriter.Flush(); err != nil {
err = xerrors.Errorf("Flush: %w", err)
rec.L().Error(err.Error(), rec.Error(err), rec.ErrorStacktrace(err))
}
}()
l := rec.Must(rec.New(bufWriter, rec.WithUseTimestampField(true), rec.WithTimestampFieldFormat(time.RFC3339Nano), rec.WithUseSeverityField(true), rec.WithUseHostnameField(false), rec.WithUseCallerField(true), rec.WithUseShortCaller(false)))
b.Run(filepath.Base(fn.Name()), func(b *testing.B) {
b.ResetTimer()
for i := 0; i < b.N; i++ {
l.Info("benchmark",
rec.ErrorWithKey("err0", io.EOF),
rec.ErrorWithKey("err1", io.EOF),
rec.ErrorWithKey("err2", io.EOF),
rec.ErrorWithKey("err3", io.EOF),
rec.ErrorWithKey("err4", io.EOF),
rec.ErrorWithKey("err5", io.EOF),
rec.ErrorWithKey("err6", io.EOF),
rec.ErrorWithKey("err7", io.EOF),
rec.ErrorWithKey("err8", io.EOF),
rec.ErrorWithKey("err9", io.EOF),
)
}
})
}
Raw
zap_____benchmark_test.go
package benchmark
import (
"io"
"runtime"
"testing"
"github.com/rec-logger/rec.go"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"golang.org/x/xerrors"
)
func BenchmarkZap(b *testing.B) {
msgnofldZap(b, "/tmp/zap_benchmark_msgnofld.log")
str10fldZap(b, "/tmp/zap_benchmark_str10fld.log")
err01fldZap(b, "/tmp/zap_benchmark_err01fld.log")
err10fldZap(b, "/tmp/zap_benchmark_err10fld.log")
}
func msgnofldZap(b *testing.B, filePath string) {
pc, _, _, _ := runtime.Caller(0)
fn := runtime.FuncForPC(pc)
c := zap.Config{
Level: zap.NewAtomicLevelAt(zap.InfoLevel),
Development: false,
Encoding: "json",
EncoderConfig: zapcore.EncoderConfig{
TimeKey: "timestamp",
LevelKey: "severity",
NameKey: "logger",
CallerKey: "caller",
FunctionKey: zapcore.OmitKey,
MessageKey: "message",
StacktraceKey: zapcore.OmitKey,
LineEnding: zapcore.DefaultLineEnding,
EncodeLevel: zapcore.CapitalLevelEncoder,
EncodeTime: zapcore.RFC3339NanoTimeEncoder,
EncodeDuration: zapcore.SecondsDurationEncoder,
EncodeCaller: zapcore.FullCallerEncoder,
},
OutputPaths: []string{filePath},
ErrorOutputPaths: []string{filePath},
}
l, _ := c.Build()
defer func() {
if err := l.Sync(); err != nil {
err = xerrors.Errorf("Sync: %w", err)
rec.L().Error(err.Error(), rec.Error(err), rec.ErrorStacktrace(err))
}
}()
b.Run(fn.Name(), func(b *testing.B) {
b.ResetTimer()
for i := 0; i < b.N; i++ {
l.Info("benchmark")
}
})
}
func str10fldZap(b *testing.B, filePath string) {
pc, _, _, _ := runtime.Caller(0)
fn := runtime.FuncForPC(pc)
c := zap.Config{
Level: zap.NewAtomicLevelAt(zap.InfoLevel),
Development: false,
Encoding: "json",
EncoderConfig: zapcore.EncoderConfig{
TimeKey: "timestamp",
LevelKey: "severity",
NameKey: "logger",
CallerKey: "caller",
FunctionKey: zapcore.OmitKey,
MessageKey: "message",
StacktraceKey: zapcore.OmitKey,
LineEnding: zapcore.DefaultLineEnding,
EncodeLevel: zapcore.CapitalLevelEncoder,
EncodeTime: zapcore.RFC3339NanoTimeEncoder,
EncodeDuration: zapcore.SecondsDurationEncoder,
EncodeCaller: zapcore.FullCallerEncoder,
},
OutputPaths: []string{filePath},
ErrorOutputPaths: []string{filePath},
}
l, _ := c.Build()
defer func() {
if err := l.Sync(); err != nil {
err = xerrors.Errorf("Sync: %w", err)
rec.L().Error(err.Error(), rec.Error(err), rec.ErrorStacktrace(err))
}
}()
b.Run(fn.Name(), func(b *testing.B) {
b.ResetTimer()
for i := 0; i < b.N; i++ {
l.Info("benchmark",
zap.String("key0", "value0"),
zap.String("key1", "value1"),
zap.String("key2", "value2"),
zap.String("key3", "value3"),
zap.String("key4", "value4"),
zap.String("key5", "value5"),
zap.String("key6", "value6"),
zap.String("key7", "value7"),
zap.String("key8", "value8"),
zap.String("key9", "value9"),
)
}
})
}
func err01fldZap(b *testing.B, filePath string) {
pc, _, _, _ := runtime.Caller(0)
fn := runtime.FuncForPC(pc)
c := zap.Config{
Level: zap.NewAtomicLevelAt(zap.InfoLevel),
Development: false,
Encoding: "json",
EncoderConfig: zapcore.EncoderConfig{
TimeKey: "timestamp",
LevelKey: "severity",
NameKey: "logger",
CallerKey: "caller",
FunctionKey: zapcore.OmitKey,
MessageKey: "message",
StacktraceKey: zapcore.OmitKey,
LineEnding: zapcore.DefaultLineEnding,
EncodeLevel: zapcore.CapitalLevelEncoder,
EncodeTime: zapcore.RFC3339NanoTimeEncoder,
EncodeDuration: zapcore.SecondsDurationEncoder,
EncodeCaller: zapcore.FullCallerEncoder,
},
OutputPaths: []string{filePath},
ErrorOutputPaths: []string{filePath},
}
l, _ := c.Build()
defer func() {
if err := l.Sync(); err != nil {
err = xerrors.Errorf("Sync: %w", err)
rec.L().Error(err.Error(), rec.Error(err), rec.ErrorStacktrace(err))
}
}()
b.Run(fn.Name(), func(b *testing.B) {
b.ResetTimer()
for i := 0; i < b.N; i++ {
l.Info("benchmark",
zap.Error(io.EOF),
)
}
})
}
func err10fldZap(b *testing.B, filePath string) {
pc, _, _, _ := runtime.Caller(0)
fn := runtime.FuncForPC(pc)
c := zap.Config{
Level: zap.NewAtomicLevelAt(zap.InfoLevel),
Development: false,
Encoding: "json",
EncoderConfig: zapcore.EncoderConfig{
TimeKey: "timestamp",
LevelKey: "severity",
NameKey: "logger",
CallerKey: "caller",
FunctionKey: zapcore.OmitKey,
MessageKey: "message",
StacktraceKey: zapcore.OmitKey,
LineEnding: zapcore.DefaultLineEnding,
EncodeLevel: zapcore.CapitalLevelEncoder,
EncodeTime: zapcore.RFC3339NanoTimeEncoder,
EncodeDuration: zapcore.SecondsDurationEncoder,
EncodeCaller: zapcore.FullCallerEncoder,
},
OutputPaths: []string{filePath},
ErrorOutputPaths: []string{filePath},
}
l, _ := c.Build()
defer func() {
if err := l.Sync(); err != nil {
err = xerrors.Errorf("Sync: %w", err)
rec.L().Error(err.Error(), rec.Error(err), rec.ErrorStacktrace(err))
}
}()
b.Run(fn.Name(), func(b *testing.B) {
b.ResetTimer()
for i := 0; i < b.N; i++ {
l.Info("benchmark",
zap.NamedError("err0", io.EOF),
zap.NamedError("err1", io.EOF),
zap.NamedError("err2", io.EOF),
zap.NamedError("err3", io.EOF),
zap.NamedError("err4", io.EOF),
zap.NamedError("err5", io.EOF),
zap.NamedError("err6", io.EOF),
zap.NamedError("err7", io.EOF),
zap.NamedError("err8", io.EOF),
zap.NamedError("err9", io.EOF),
)
}
})
}
Raw
zerolog_benchmark_test.go
package benchmark
import (
"bufio"
"io"
"os"
"runtime"
"testing"
"time"
"github.com/rec-logger/rec.go"
"github.com/rs/zerolog"
"golang.org/x/xerrors"
)
func BenchmarkZerolog(b *testing.B) {
msgnofldZerolog(b, mustOpenFile("/tmp/zerolog_benchmark_msgnofld.log", os.O_CREATE|os.O_RDWR, 0o600))
str10fldZerolog(b, mustOpenFile("/tmp/zerolog_benchmark_str10fld.log", os.O_CREATE|os.O_RDWR, 0o600))
err01fldZerolog(b, mustOpenFile("/tmp/zerolog_benchmark_err01fld.log", os.O_CREATE|os.O_RDWR, 0o600))
err10fldZerolog(b, mustOpenFile("/tmp/zerolog_benchmark_err10fld.log", os.O_CREATE|os.O_RDWR, 0o600))
}
func msgnofldZerolog(b *testing.B, writer io.Writer) {
pc, _, _, _ := runtime.Caller(0)
fn := runtime.FuncForPC(pc)
bufWriter := bufio.NewWriter(writer)
defer func() {
if err := bufWriter.Flush(); err != nil {
err = xerrors.Errorf("Flush: %w", err)
rec.L().Error(err.Error(), rec.Error(err), rec.ErrorStacktrace(err))
}
}()
defer func(backup string) {
zerolog.LevelFieldName = backup
}(zerolog.LevelFieldName)
defer func(backup string) {
zerolog.TimestampFieldName = backup
}(zerolog.TimestampFieldName)
defer func(backup string) {
zerolog.TimeFieldFormat = backup
}(zerolog.TimeFieldFormat)
zerolog.TimestampFieldName = "timestamp"
zerolog.TimeFieldFormat = time.RFC3339Nano
zerolog.LevelFieldName = "severity"
l := zerolog.New(bufWriter).With().Timestamp().Caller().Logger()
b.Run(fn.Name(), func(b *testing.B) {
b.ResetTimer()
for i := 0; i < b.N; i++ {
l.Info().Msg("benchmark")
}
})
}
func str10fldZerolog(b *testing.B, writer io.Writer) {
pc, _, _, _ := runtime.Caller(0)
fn := runtime.FuncForPC(pc)
bufWriter := bufio.NewWriter(writer)
defer func() {
if err := bufWriter.Flush(); err != nil {
err = xerrors.Errorf("Flush: %w", err)
rec.L().Error(err.Error(), rec.Error(err), rec.ErrorStacktrace(err))
}
}()
defer func(backup string) {
zerolog.LevelFieldName = backup
}(zerolog.LevelFieldName)
defer func(backup string) {
zerolog.TimestampFieldName = backup
}(zerolog.TimestampFieldName)
defer func(backup string) {
zerolog.TimeFieldFormat = backup
}(zerolog.TimeFieldFormat)
zerolog.TimestampFieldName = "timestamp"
zerolog.TimeFieldFormat = time.RFC3339Nano
zerolog.LevelFieldName = "severity"
l := zerolog.New(bufWriter).With().Timestamp().Caller().Logger()
b.Run(fn.Name(), func(b *testing.B) {
b.ResetTimer()
for i := 0; i < b.N; i++ {
l.Info().
Str("key0", "value0").
Str("key1", "value1").
Str("key2", "value2").
Str("key3", "value3").
Str("key4", "value4").
Str("key5", "value5").
Str("key6", "value6").
Str("key7", "value7").
Str("key8", "value8").
Str("key9", "value9").
Msg("benchmark")
}
})
}
func err01fldZerolog(b *testing.B, writer io.Writer) {
pc, _, _, _ := runtime.Caller(0)
fn := runtime.FuncForPC(pc)
bufWriter := bufio.NewWriter(writer)
defer func() {
if err := bufWriter.Flush(); err != nil {
err = xerrors.Errorf("Flush: %w", err)
rec.L().Error(err.Error(), rec.Error(err), rec.ErrorStacktrace(err))
}
}()
b.Run(fn.Name(), func(b *testing.B) {
defer func(backup string) {
zerolog.LevelFieldName = backup
}(zerolog.LevelFieldName)
defer func(backup string) {
zerolog.TimestampFieldName = backup
}(zerolog.TimestampFieldName)
defer func(backup string) {
zerolog.TimeFieldFormat = backup
}(zerolog.TimeFieldFormat)
zerolog.TimestampFieldName = "timestamp"
zerolog.TimeFieldFormat = time.RFC3339Nano
zerolog.LevelFieldName = "severity"
l := zerolog.New(writer).With().Timestamp().Caller().Logger()
b.ResetTimer()
for i := 0; i < b.N; i++ {
l.Info().
Err(io.EOF).
Msg("benchmark")
}
})
}
func err10fldZerolog(b *testing.B, writer io.Writer) {
pc, _, _, _ := runtime.Caller(0)
fn := runtime.FuncForPC(pc)
bufWriter := bufio.NewWriter(writer)
defer func() {
if err := bufWriter.Flush(); err != nil {
err = xerrors.Errorf("Flush: %w", err)
rec.L().Error(err.Error(), rec.Error(err), rec.ErrorStacktrace(err))
}
}()
b.Run(fn.Name(), func(b *testing.B) {
defer func(backup string) {
zerolog.LevelFieldName = backup
}(zerolog.LevelFieldName)
defer func(backup string) {
zerolog.TimestampFieldName = backup
}(zerolog.TimestampFieldName)
defer func(backup string) {
zerolog.TimeFieldFormat = backup
}(zerolog.TimeFieldFormat)
zerolog.TimestampFieldName = "timestamp"
zerolog.TimeFieldFormat = time.RFC3339Nano
zerolog.LevelFieldName = "severity"
l := zerolog.New(writer).With().Timestamp().Caller().Logger()
b.ResetTimer()
for i := 0; i < b.N; i++ {
l.Info().
AnErr("err0", io.EOF).
AnErr("err1", io.EOF).
AnErr("err2", io.EOF).
AnErr("err3", io.EOF).
AnErr("err4", io.EOF).
AnErr("err5", io.EOF).
AnErr("err6", io.EOF).
AnErr("err7", io.EOF).
AnErr("err8", io.EOF).
AnErr("err9", io.EOF).
Msg("benchmark")
}
})
}
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment