Structured logging with InfoS is formatted differently than traditional output,
so it's worthwhile to have an example that demostrates that.

The new example didn't compile initially because an older version of klog was
used. This gets avoids by always using the source from the current directory.

There is a mechanism for allocating smallish buffers (< 256 bytes) only once
and then reusing them. Doing that for the structured key/value pairs is an
improvement (measured with kubernetes/kubernetes#106594):

$ $GOPATH/bin/benchstat /tmp/original /tmp/reuse-buffer
name                               old time/op    new time/op    delta
Logging/container/structured-36      41.6µs ± 1%    41.6µs ± 1%     ~     (p=1.000 n=5+5)
Logging/error-value/structured-36    4.01µs ± 3%    3.37µs ± 3%  -16.01%  (p=0.008 n=5+5)
Logging/error/structured-36          3.91µs ± 1%    3.33µs ± 3%  -14.90%  (p=0.008 n=5+5)
Logging/simple/structured-36         3.54µs ± 3%    2.98µs ± 3%  -15.77%  (p=0.008 n=5+5)
Logging/values/structured-36         6.83µs ± 2%    5.31µs ± 5%  -22.34%  (p=0.008 n=5+5)

name                               old alloc/op   new alloc/op   delta
Logging/container/structured-36      10.4kB ± 0%    10.5kB ± 0%   +0.61%  (p=0.008 n=5+5)
Logging/error-value/structured-36      432B ± 0%      320B ± 0%  -25.93%  (p=0.008 n=5+5)
Logging/error/structured-36            448B ± 0%      336B ± 0%  -25.00%  (p=0.008 n=5+5)
Logging/simple/structured-36           408B ± 0%      296B ± 0%  -27.45%  (p=0.008 n=5+5)
Logging/values/structured-36           777B ± 0%      505B ± 0%  -35.01%  (p=0.008 n=5+5)

name                               old allocs/op  new allocs/op  delta
Logging/container/structured-36        64.0 ± 0%      64.0 ± 0%     ~     (all equal)
Logging/error-value/structured-36      9.00 ± 0%      7.00 ± 0%  -22.22%  (p=0.008 n=5+5)
Logging/error/structured-36            10.0 ± 0%       8.0 ± 0%  -20.00%  (p=0.008 n=5+5)
Logging/simple/structured-36           8.00 ± 0%      6.00 ± 0%  -25.00%  (p=0.008 n=5+5)
Logging/values/structured-36           16.0 ± 0%      13.0 ± 0%  -18.75%  (p=0.008 n=5+5)

We can avoid several allocations and use faster code (= strconv.Quote) by
relying less on Sprintf.

$ $GOPATH/bin/benchstat /tmp/reuse-buffer /tmp/strconv
name                               old time/op    new time/op    delta
Logging/container/structured-36      41.6µs ± 1%    39.5µs ± 2%   -5.05%  (p=0.008 n=5+5)
Logging/error-value/structured-36    3.37µs ± 3%    3.13µs ± 0%   -7.06%  (p=0.016 n=5+4)
Logging/error/structured-36          3.33µs ± 3%    3.09µs ± 2%   -7.10%  (p=0.008 n=5+5)
Logging/simple/structured-36         2.98µs ± 3%    2.86µs ± 4%     ~     (p=0.095 n=5+5)
Logging/values/structured-36         5.31µs ± 5%    4.77µs ± 4%  -10.17%  (p=0.008 n=5+5)

name                               old alloc/op   new alloc/op   delta
Logging/container/structured-36      10.5kB ± 0%     9.3kB ± 0%  -11.01%  (p=0.008 n=5+5)
Logging/error-value/structured-36      320B ± 0%      312B ± 0%   -2.50%  (p=0.008 n=5+5)
Logging/error/structured-36            336B ± 0%      312B ± 0%   -7.14%  (p=0.008 n=5+5)
Logging/simple/structured-36           296B ± 0%      288B ± 0%   -2.70%  (p=0.008 n=5+5)
Logging/values/structured-36           505B ± 0%      464B ± 0%   -8.12%  (p=0.008 n=5+5)

name                               old allocs/op  new allocs/op  delta
Logging/container/structured-36        64.0 ± 0%      62.0 ± 0%   -3.12%  (p=0.008 n=5+5)
Logging/error-value/structured-36      7.00 ± 0%      6.00 ± 0%  -14.29%  (p=0.008 n=5+5)
Logging/error/structured-36            8.00 ± 0%      6.00 ± 0%  -25.00%  (p=0.008 n=5+5)
Logging/simple/structured-36           6.00 ± 0%      5.00 ± 0%  -16.67%  (p=0.008 n=5+5)
Logging/values/structured-36           13.0 ± 0%      11.0 ± 0%  -15.38%  (p=0.008 n=5+5)

Checking common types first is slightly faster.

No difference for simple benchmarks:

$ $GOPATH/bin/benchstat /tmp/strconv /tmp/reorder
name                               old time/op    new time/op    delta
Logging/container/structured-36      39.5µs ± 2%    39.6µs ± 1%   ~     (p=1.000 n=5+5)
Logging/error-value/structured-36    3.13µs ± 0%    3.14µs ± 4%   ~     (p=0.730 n=4+5)
Logging/error/structured-36          3.09µs ± 2%    3.13µs ± 3%   ~     (p=0.548 n=5+5)
Logging/simple/structured-36         2.86µs ± 4%    2.91µs ± 2%   ~     (p=0.310 n=5+5)
Logging/values/structured-36         4.77µs ± 4%    4.77µs ± 5%   ~     (p=0.841 n=5+5)

name                               old alloc/op   new alloc/op   delta
Logging/container/structured-36      9.35kB ± 0%    9.35kB ± 0%   ~     (p=0.095 n=5+4)
Logging/error-value/structured-36      312B ± 0%      312B ± 0%   ~     (all equal)
Logging/error/structured-36            312B ± 0%      312B ± 0%   ~     (all equal)
Logging/simple/structured-36           288B ± 0%      288B ± 0%   ~     (all equal)
Logging/values/structured-36           464B ± 0%      464B ± 0%   ~     (all equal)

name                               old allocs/op  new allocs/op  delta
Logging/container/structured-36        62.0 ± 0%      62.0 ± 0%   ~     (all equal)
Logging/error-value/structured-36      6.00 ± 0%      6.00 ± 0%   ~     (all equal)
Logging/error/structured-36            6.00 ± 0%      6.00 ± 0%   ~     (all equal)
Logging/simple/structured-36           5.00 ± 0%      5.00 ± 0%   ~     (all equal)
Logging/values/structured-36           11.0 ± 0%      11.0 ± 0%   ~     (all equal)

It's a bigger win for a real kubelet log:

$ $GOPATH/bin/benchstat /tmp/strconv-kubelet /tmp/reorder-kubelet
name                              old time/op    new time/op    delta
Logging/v5/kubelet/structured-36     1.17s ± 2%     1.15s ± 1%  -1.37%  (p=0.016 n=5+5)

name                              old alloc/op   new alloc/op   delta
Logging/v5/kubelet/structured-36     525MB ± 0%     525MB ± 0%    ~     (p=0.548 n=5+5)

name                              old allocs/op  new allocs/op  delta
Logging/v5/kubelet/structured-36     3.86M ± 0%     3.86M ± 0%    ~     (p=0.079 n=5+5)

        Args:
         total: 310746
         strings: 106904 (34%)
           with line breaks: 11 (0% of all arguments)
           with API objects: 529 (0% of all arguments)
             types and their number of usage: Container:529
         numbers: 14563 (4%)
         ObjectRef: 169306 (54%)
         others: 19973 (6%)

The initial structured logging output (almost) always produced a single line
per log message, with quoting of strings to represent line breaks as \n.  This
made the output hard to read (see
kubernetes/kubernetes#104868).

It was still possible to get line breaks when formatting a value with `%+v` and
that ended up emitting line breaks; this was probably not intended.

Now string values are only quoted if they contain no line break. If they do,
start/end markers delimit the text which appears on its own lines, with
indention to ensure that those additional lines are not accidentally treated as
a new log message when they happen to contain the klog header. It also makes
the output more readable.

Tabs are used as indention for the value because it makes it stand out visually
and because it ensures that inline ">" characters are not mistaken for the
end-of-value delimiter.

The result of `fmt.Sprintf("%+v")` is printed verbatim without quoting when it
contains no line break, otherwise as multi-line value with delimiter and
indention.

Traditional output:

 I1112 14:06:35.783354  328441 structured_logging.go:42] someData printed using InfoF: {hello world 0}
 I1112 14:06:35.783472  328441 structured_logging.go:43] longData printed using InfoF: {long Multiple
 lines
 with quite a bit
 of text. 0}
 I1112 14:06:35.783483  328441 structured_logging.go:44] stringData printed using InfoF,
 with the message across multiple lines:
 long: Multiple
 lines
 with quite a bit
 of text.
 I1112 14:06:35.898176  142908 structured_logging.go:54] logData printed using InfoF:
 {log output from some program I0000 12:00:00.000000  123456 main.go:42] Starting
 E0000 12:00:01.000000  123456 main.go:43] Failed for some reason
  0}

Old InfoS output before this commit:

 I1112 14:06:35.783512  328441 structured_logging.go:50] "using InfoS" someData={Name:hello Data:world internal:0}
 I1112 14:06:35.783529  328441 structured_logging.go:51] "using InfoS" longData={Name:long Data:Multiple
 lines
 with quite a bit
 of text. internal:0}
 I1112 14:06:35.783549  328441 structured_logging.go:52] "using InfoS with\nthe message across multiple lines" int=1 stringData="long: Multiple\nlines\nwith quite a bit\nof text." str="another value"
 I1112 14:06:35.783565  328441 structured_logging.go:61] "Did something" item="foobar"
 I1112 14:06:35.783576  328441 structured_logging.go:63] "This is a full sentence." item="foobar"
 I1112 14:06:35.898278  142908 structured_logging.go:65] "using InfoS" logData={Name:log output from some program Data:I0000 12:00:00.000000  123456 main.go:42] Starting
 E0000 12:00:01.000000  123456 main.go:43] Failed for some reason
  internal:0}

New InfoS output:
I1126 10:31:50.378182  121736 structured_logging.go:58] "using InfoS" someData={Name:hello Data:world internal:0}
I1126 10:31:50.378204  121736 structured_logging.go:59] "using InfoS" longData=<
	{Name:long Data:Multiple
	lines
	with quite a bit
	of text. internal:0}
 >
I1126 10:31:50.378228  121736 structured_logging.go:60] "using InfoS with\nthe message across multiple lines" int=1 stringData=<
	long: Multiple
	lines
	with quite a bit
	of text.
 > str="another value"
I1126 10:31:50.378249  121736 structured_logging.go:65] "using InfoS" logData=<
	{Name:log output from some program Data:I0000 12:00:00.000000  123456 main.go:42] Starting
	E0000 12:00:01.000000  123456 main.go:43] Failed for some reason
	 internal:0}
 >

Performance is the same as before in most cases. Handling of a v1.Container
struct with line breaks in the output gets faster, probably because printing
each line individually is more efficient than quoting.

$ $GOPATH/bin/benchstat /tmp/reorder /tmp/multi-line
name                               old time/op    new time/op    delta
Logging/container/structured-36      39.6µs ± 1%    21.5µs ± 0%  -45.82%  (p=0.008 n=5+5)
Logging/error-value/structured-36    3.14µs ± 4%    3.11µs ± 2%     ~     (p=0.548 n=5+5)
Logging/error/structured-36          3.13µs ± 3%    3.13µs ± 3%     ~     (p=1.000 n=5+5)
Logging/simple/structured-36         2.91µs ± 2%    2.87µs ± 2%     ~     (p=0.310 n=5+5)
Logging/values/structured-36         4.77µs ± 5%    4.75µs ± 4%     ~     (p=1.000 n=5+5)

name                               old alloc/op   new alloc/op   delta
Logging/container/structured-36      9.35kB ± 0%    9.59kB ± 0%   +2.59%  (p=0.016 n=4+5)
Logging/error-value/structured-36      312B ± 0%      312B ± 0%     ~     (all equal)
Logging/error/structured-36            312B ± 0%      312B ± 0%     ~     (all equal)
Logging/simple/structured-36           288B ± 0%      288B ± 0%     ~     (all equal)
Logging/values/structured-36           464B ± 0%      464B ± 0%     ~     (all equal)

name                               old allocs/op  new allocs/op  delta
Logging/container/structured-36        62.0 ± 0%      63.0 ± 0%   +1.61%  (p=0.008 n=5+5)
Logging/error-value/structured-36      6.00 ± 0%      6.00 ± 0%     ~     (all equal)
Logging/error/structured-36            6.00 ± 0%      6.00 ± 0%     ~     (all equal)
Logging/simple/structured-36           5.00 ± 0%      5.00 ± 0%     ~     (all equal)
Logging/values/structured-36           11.0 ± 0%      11.0 ± 0%     ~     (all equal)