Skip to content

Object GET/HEAD/RANGE logger improvements#3408

Merged
roman-khimov merged 2 commits intomasterfrom
get-logger
Jun 20, 2025
Merged

Object GET/HEAD/RANGE logger improvements#3408
roman-khimov merged 2 commits intomasterfrom
get-logger

Conversation

@cthulhu-rider
Copy link
Contributor

No description provided.

@codecov
Copy link

codecov bot commented Jun 20, 2025

Codecov Report

Attention: Patch coverage is 50.00000% with 4 lines in your changes missing coverage. Please review.

Project coverage is 21.16%. Comparing base (247e7df) to head (efd8bc2).
Report is 3 commits behind head on master.

Files with missing lines Patch % Lines
pkg/services/object/acl/v2/classifier.go 0.00% 4 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##           master    #3408      +/-   ##
==========================================
- Coverage   21.19%   21.16%   -0.03%     
==========================================
  Files         708      708              
  Lines       52883    52887       +4     
==========================================
- Hits        11208    11194      -14     
- Misses      40879    40898      +19     
+ Partials      796      795       -1     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

@cthulhu-rider cthulhu-rider requested a review from End-rey June 20, 2025 12:39
@cthulhu-rider cthulhu-rider marked this pull request as ready for review June 20, 2025 12:39
Copy link
Member

@roman-khimov roman-khimov left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Changelog?

Previously, SN could waste memory in these ops' processing by cloning
zap logger:
 1. there is only one conditional case when message can be written at
   non-debug level;
 2. debug level is never enabled in production.

This could be observed when applying a high read load. For example, when
reading same object with a 4K payload in 100 threads from SN, its local
allocation profile showed the following:
```
      flat  flat%   sum%        cum   cum%
    7.05GB  9.45%  9.45%     8.12GB 10.89%  github.com/nspcc-dev/neofs-sdk-go/crypto.encodeMessage
    6.64GB  8.90% 18.35%     6.64GB  8.90%  google.golang.org/protobuf/internal/impl.consumeBytesNoZero
    6.25GB  8.38% 26.73%     6.25GB  8.38%  github.com/nspcc-dev/neofs-node/pkg/local_object_storage/blobstor/fstree.extractCombinedObject
    4.51GB  6.05% 32.78%     4.64GB  6.21%  crypto/cipher.NewCTR
    3.85GB  5.16% 37.94%     3.85GB  5.16%  crypto/aes.newCipher
    3.40GB  4.56% 42.50%     5.05GB  6.77%  vendor/golang.org/x/crypto/cryptobyte.(*Builder).addLengthPrefixed
    2.99GB  4.01% 46.51%     2.99GB  4.01%  reflect.New
    2.72GB  3.65% 50.16%     2.72GB  3.65%  go.uber.org/zap/internal/bufferpool.init.NewPool.func1
    2.18GB  2.92% 53.08%     2.18GB  2.92%  crypto/internal/bigmod.NewNat
    1.87GB  2.51% 55.58%     1.87GB  2.51%  crypto/internal/nistec.NewP256Point
```

As you can see, a decent amount of memory is used up for zap needs. At
the same time, not a single entry appeared in the log regarding the
submitted load.

This disables logger cloning for non-debug mode. Profile is now like:
```
      flat  flat%   sum%        cum   cum%
    6.66GB  9.92%  9.92%     7.66GB 11.41%  github.com/nspcc-dev/neofs-sdk-go/crypto.encodeMessage
    6.13GB  9.13% 19.05%     6.13GB  9.13%  google.golang.org/protobuf/internal/impl.consumeBytesNoZero
    5.84GB  8.70% 27.75%     5.84GB  8.70%  github.com/nspcc-dev/neofs-node/pkg/local_object_storage/blobstor/fstree.extractCombinedObject
    4.25GB  6.33% 34.08%     4.37GB  6.51%  crypto/cipher.NewCTR
    3.67GB  5.47% 39.54%     3.67GB  5.47%  crypto/aes.newCipher
    3.21GB  4.78% 44.32%     4.80GB  7.16%  vendor/golang.org/x/crypto/cryptobyte.(*Builder).addLengthPrefixed
    2.84GB  4.23% 48.56%     2.84GB  4.23%  reflect.New
    2.01GB  3.00% 51.55%     2.01GB  3.00%  crypto/internal/bigmod.NewNat
    1.73GB  2.57% 54.13%     1.73GB  2.57%  crypto/internal/nistec.NewP256Point
    1.68GB  2.50% 56.62%     1.68GB  2.50%  vendor/golang.org/x/crypto/cryptobyte.(*Builder).add (inline)
```

The only functional change is the error message when decoding some SN's
network address written at error level. Now the message does not contain
information about the request during which an error occurred. Since the
error is not related to a specific request, this change is considered
appropriate.

The optimization is also reflected in the test benchmarks:
```
goos: linux
goarch: amd64
pkg: github.com/nspcc-dev/neofs-node/pkg/services/object/get
cpu: Intel(R) Core(TM) i5-10210U CPU @ 1.60GHz
                             │    old.txt    │               new.txt               │
                             │    sec/op     │   sec/op     vs base                │
ExecCtxSetLoggerProduction-8   1721.00n ± 3%   19.43n ± 6%  -98.87% (p=0.000 n=10)

                             │   old.txt    │                new.txt                │
                             │     B/op     │     B/op      vs base                 │
ExecCtxSetLoggerProduction-8   2.627Ki ± 0%   0.000Ki ± 0%  -100.00% (p=0.000 n=10)

                             │  old.txt   │              new.txt               │
                             │ allocs/op  │ allocs/op  vs base                 │
ExecCtxSetLoggerProduction-8   14.00 ± 0%   0.00 ± 0%  -100.00% (p=0.000 n=10)
```

Refs #3409.

Signed-off-by: Leonard Lyubich <leonard@morphbits.io>
Follow 91bb4e2.

Same test showed following alloc objects
```
1299856  0.19% 88.10%    5310102  0.76%  go.uber.org/zap/zapcore.(*ioCore).clone (inline)
```
and space
```
1.27GB  1.90% 64.69%     1.27GB  1.90%  go.uber.org/zap/internal/bufferpool.init.NewPool.func1
```
profiles.

This replaces logger cloning with explicit field parameterization. The
behavior is kept the same. Allocations mentioned above are no longer
visible.

Go benchmark test:
```
goos: linux
goarch: amd64
pkg: github.com/nspcc-dev/neofs-node/pkg/services/object/acl/v2
cpu: Intel(R) Core(TM) i5-10210U CPU @ 1.60GHz
                             │   old.txt    │               new.txt               │
                             │    sec/op    │   sec/op     vs base                │
ClassifierLoggerProduction-8   3855.0n ± 2%   661.1n ± 8%  -82.85% (p=0.000 n=10)

                             │   old.txt    │                new.txt                │
                             │     B/op     │     B/op      vs base                 │
ClassifierLoggerProduction-8   1.704Ki ± 0%   0.000Ki ± 0%  -100.00% (p=0.000 n=10)

                             │  old.txt   │              new.txt               │
                             │ allocs/op  │ allocs/op  vs base                 │
ClassifierLoggerProduction-8   13.00 ± 0%   0.00 ± 0%  -100.00% (p=0.000 n=10)
```

Refs #3409.

Signed-off-by: Leonard Lyubich <leonard@morphbits.io>
@roman-khimov roman-khimov merged commit 1094f6c into master Jun 20, 2025
17 of 20 checks passed
@roman-khimov roman-khimov deleted the get-logger branch June 20, 2025 19:03
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants