Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

improve textlogger #362

Merged
merged 14 commits into from Jan 19, 2023
Merged

improve textlogger #362

merged 14 commits into from Jan 19, 2023

Commits on Jan 16, 2023

  1. klogr: avoid calling Info/Error/Enabled through auto-generated code

    These functions get called for a pointer because that is what we use to
    implement the LogSink interface. The variant of these functions which take a
    value instead of a pointer was never used, so providing directly what is needed
    instead of relying on the compiler to generate that is more efficient (less
    code, avoids one extra callstack entry at runtime).
    
    The With* functions must continue to take a value because they need to modify
    that copy.
    pohly committed Jan 16, 2023
    Configuration menu
    Copy the full SHA
    f6e8786 View commit details
    Browse the repository at this point in the history
  2. test: move InitKlog into tests

    This makes it possible to use test.Output inside packages
    that have other tests.
    pohly committed Jan 16, 2023
    Configuration menu
    Copy the full SHA
    e23e29e View commit details
    Browse the repository at this point in the history
  3. klogr: fix vmodule support

    When klogr called V(), it didn't pass the callstack offset, which broke
    evaluation of the -vmodule patterns. A new VWithOffset klog API is needed to
    fix this.
    
    A unit test for this will follow.
    pohly committed Jan 16, 2023
    Configuration menu
    Copy the full SHA
    50cdc4a View commit details
    Browse the repository at this point in the history
  4. klogr: use test.InitKlog

    Besides sharing code, it's also better in two regards:
    - restores state after test
    - avoids triple printing of errors
    pohly committed Jan 16, 2023
    Configuration menu
    Copy the full SHA
    676a553 View commit details
    Browse the repository at this point in the history

Commits on Jan 19, 2023

  1. textlogger: fix vmodule support

    When Logger.Info called Enabled, the wrong number of stack frames were skipped.
    
    A unit test for this will follow.
    pohly committed Jan 19, 2023
    Configuration menu
    Copy the full SHA
    c57c59c View commit details
    Browse the repository at this point in the history
  2. move output tests into packages

    Previously it was necessary to enter the "examples" module to run output tests
    for code in the main module. Now "go test ./..." at the root or in individual
    directories also runs these tests.
    pohly committed Jan 19, 2023
    Configuration menu
    Copy the full SHA
    723e7f4 View commit details
    Browse the repository at this point in the history
  3. use output test cases also for benchmarking

    So far, the output tests were only used for correctness checking. But they
    cover a variety of scenarios for which there were no benchmarks, therefore it
    makes sense to also use them for that.
    pohly committed Jan 19, 2023
    Configuration menu
    Copy the full SHA
    8c60010 View commit details
    Browse the repository at this point in the history
  4. test: unit tests for vmodule support

    Text logger and the two klogr implementations both got this wrong.
    pohly committed Jan 19, 2023
    Configuration menu
    Copy the full SHA
    4aa7aa6 View commit details
    Browse the repository at this point in the history
  5. buffer: use sync.Pool

    This simplifies the code. Instead of different instances, the package now
    maintains a global pool. This makes the text logger struct a bit smaller and
    thus cheaper to copy in the With* functions.
    
    Performance is about the same as before:
    
    name              old time/op    new time/op    delta
    Header-36           1.68µs ± 7%    1.62µs ± 6%   ~     (p=0.246 n=5+5)
    HeaderWithDir-36    1.63µs ± 6%    1.59µs ± 6%   ~     (p=0.690 n=5+5)
    
    name              old alloc/op   new alloc/op   delta
    Header-36             216B ± 0%      216B ± 0%   ~     (all equal)
    HeaderWithDir-36      216B ± 0%      216B ± 0%   ~     (all equal)
    
    name              old allocs/op  new allocs/op  delta
    Header-36             2.00 ± 0%      2.00 ± 0%   ~     (all equal)
    HeaderWithDir-36      2.00 ± 0%      2.00 ± 0%   ~     (all equal)
    
    The text logger didn't actually return the buffer. Now it does.
    pohly committed Jan 19, 2023
    Configuration menu
    Copy the full SHA
    718ea45 View commit details
    Browse the repository at this point in the history
  6. Configuration menu
    Copy the full SHA
    1c00d46 View commit details
    Browse the repository at this point in the history
  7. serialize: combine merging and formatting

    This avoids one memory allocation (for the intermediate slice), copying and
    loops.
    pohly committed Jan 19, 2023
    Configuration menu
    Copy the full SHA
    ab80bfc View commit details
    Browse the repository at this point in the history
  8. KObj: optimize string concatenation

    Using a strings.Builder reduces the number of allocations:
    
    name                               old time/op    new time/op    delta
    KlogOutput/KObjSlice_okay-36         15.2µs ± 5%    14.8µs ± 4%    ~     (p=0.151 n=5+5)
    KlogOutput/KObjSlice_nil_entry-36    14.4µs ± 5%    13.6µs ± 3%  -5.25%  (p=0.032 n=5+5)
    KlogOutput/KObj-36                   13.5µs ± 8%    13.5µs ± 6%    ~     (p=0.841 n=5+5)
    KlogOutput/KObjSlice_ints-36         15.3µs ± 5%    15.2µs ± 4%    ~     (p=0.841 n=5+5)
    KlogOutput/KObjSlice_nil_arg-36      12.8µs ± 2%    12.8µs ± 6%    ~     (p=0.841 n=5+5)
    KlogOutput/KObjSlice_int_arg-36      14.1µs ± 4%    13.8µs ± 3%    ~     (p=0.310 n=5+5)
    KlogOutput/KObjs-36                  14.1µs ± 8%    13.6µs ± 8%    ~     (p=0.690 n=5+5)
    
    name                               old alloc/op   new alloc/op   delta
    KlogOutput/KObjSlice_okay-36         2.89kB ± 0%    2.82kB ± 0%  -2.23%  (p=0.008 n=5+5)
    KlogOutput/KObjSlice_nil_entry-36    2.65kB ± 0%    2.62kB ± 0%    ~     (p=0.079 n=4+5)
    KlogOutput/KObj-36                   2.50kB ± 0%    2.47kB ± 0%  -1.30%  (p=0.000 n=4+5)
    KlogOutput/KObjSlice_ints-36         2.90kB ± 0%    2.90kB ± 0%    ~     (p=1.000 n=5+5)
    KlogOutput/KObjSlice_nil_arg-36      2.41kB ± 0%    2.41kB ± 0%    ~     (all equal)
    KlogOutput/KObjSlice_int_arg-36      2.67kB ± 0%    2.67kB ± 0%    ~     (all equal)
    KlogOutput/KObjs-36                  2.72kB ± 0%    2.65kB ± 0%  -2.38%  (p=0.008 n=5+5)
    
    name                               old allocs/op  new allocs/op  delta
    KlogOutput/KObjSlice_okay-36           46.0 ± 0%      42.0 ± 0%  -8.70%  (p=0.008 n=5+5)
    KlogOutput/KObjSlice_nil_entry-36      40.0 ± 0%      38.0 ± 0%  -5.00%  (p=0.008 n=5+5)
    KlogOutput/KObj-36                     36.0 ± 0%      34.0 ± 0%  -5.56%  (p=0.008 n=5+5)
    KlogOutput/KObjSlice_ints-36           39.0 ± 0%      39.0 ± 0%    ~     (all equal)
    KlogOutput/KObjSlice_nil_arg-36        35.0 ± 0%      35.0 ± 0%    ~     (all equal)
    KlogOutput/KObjSlice_int_arg-36        37.0 ± 0%      37.0 ± 0%    ~     (all equal)
    KlogOutput/KObjs-36                    42.0 ± 0%      38.0 ± 0%  -9.52%  (p=0.008 n=5+5)
    pohly committed Jan 19, 2023
    Configuration menu
    Copy the full SHA
    3d96ccc View commit details
    Browse the repository at this point in the history
  9. KObj, KObjSlice: format more efficiently as text

    The klog text format avoids some string allocation by calling WriteText instead
    of String when encountering such values.
    
    A positive side effect is that KObjSlice now gets logged like KObjs, i.e.
    
       pods=[namespace1/name1 namespace2/name2]
    
    Previously, it was written as a quoted string.
    
    To achieve the best performance, WriteText is passed a bytes.Buffer pointer
    instead of a io.Writer. This avoids an interface allocation for the parameter
    and provides access to the underlying methods.
    
    Benchmarks involving these types benefit while other are the same as before:
    
    name                               old time/op    new time/op    delta
    KlogOutput/KObj-36                   12.7µs ±10%    13.1µs ± 1%     ~     (p=0.151 n=5+5)
    KlogOutput/KObjs-36                  13.4µs ± 7%    14.0µs ± 5%     ~     (p=0.310 n=5+5)
    KlogOutput/KObjSlice_okay-36         14.8µs ± 4%    13.0µs ± 3%  -12.33%  (p=0.008 n=5+5)
    KlogOutput/KObjSlice_int_arg-36      14.0µs ± 6%    12.3µs ±10%  -12.60%  (p=0.008 n=5+5)
    KlogOutput/KObjSlice_ints-36         15.5µs ± 4%    12.8µs ± 6%  -17.85%  (p=0.008 n=5+5)
    KlogOutput/KObjSlice_nil_entry-36    14.2µs ±13%    12.6µs ± 3%  -11.39%  (p=0.008 n=5+5)
    KlogOutput/KObjSlice_nil_arg-36      12.6µs ± 6%    12.9µs ± 3%     ~     (p=0.690 n=5+5)
    
    name                               old alloc/op   new alloc/op   delta
    KlogOutput/KObj-36                   2.47kB ± 0%    2.41kB ± 0%   -2.29%  (p=0.008 n=5+5)
    KlogOutput/KObjs-36                  2.65kB ± 0%    2.65kB ± 0%     ~     (all equal)
    KlogOutput/KObjSlice_okay-36         2.82kB ± 0%    2.45kB ± 0%  -13.37%  (p=0.008 n=5+5)
    KlogOutput/KObjSlice_int_arg-36      2.67kB ± 0%    2.45kB ± 0%   -8.42%  (p=0.029 n=4+4)
    KlogOutput/KObjSlice_ints-36         2.90kB ± 0%    2.49kB ± 0%  -14.37%  (p=0.000 n=4+5)
    KlogOutput/KObjSlice_nil_entry-36    2.62kB ± 0%    2.43kB ± 0%   -7.34%  (p=0.000 n=4+5)
    KlogOutput/KObjSlice_nil_arg-36      2.41kB ± 0%    2.40kB ± 0%   -0.66%  (p=0.016 n=5+4)
    
    name                               old allocs/op  new allocs/op  delta
    KlogOutput/KObj-36                     34.0 ± 0%      32.0 ± 0%   -5.88%  (p=0.008 n=5+5)
    KlogOutput/KObjs-36                    38.0 ± 0%      38.0 ± 0%     ~     (all equal)
    KlogOutput/KObjSlice_okay-36           42.0 ± 0%      32.0 ± 0%  -23.81%  (p=0.008 n=5+5)
    KlogOutput/KObjSlice_int_arg-36        37.0 ± 0%      32.0 ± 0%  -13.51%  (p=0.008 n=5+5)
    KlogOutput/KObjSlice_ints-36           39.0 ± 0%      33.0 ± 0%  -15.38%  (p=0.008 n=5+5)
    KlogOutput/KObjSlice_nil_entry-36      38.0 ± 0%      32.0 ± 0%  -15.79%  (p=0.008 n=5+5)
    KlogOutput/KObjSlice_nil_arg-36        35.0 ± 0%      32.0 ± 0%   -8.57%  (p=0.008 n=5+5)
    pohly committed Jan 19, 2023
    Configuration menu
    Copy the full SHA
    64ee6cf View commit details
    Browse the repository at this point in the history
  10. github: bump golangci-lint image version

    It looks like golangci-lint comes with a fixed version of Go, one which is too
    old for the code:
    
    level=error msg="Running error: gofmt: analysis skipped: errors in package: [/go/src/k8s.io/klog/test/output.go:846:22: Discard not declared by package io /go/src/k8s.io/klog/test/output.go:864:40: Discard not declared by package io /go/src/k8s.io/klog/test/output.go:876:35: Discard not declared by package io]"
    
    io.Discard was introduced in Go 1.16, using it should be fine and is reflected
    in our Go version test matrix (>= 1.17).
    pohly committed Jan 19, 2023
    Configuration menu
    Copy the full SHA
    a9dc48e View commit details
    Browse the repository at this point in the history