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

kvserver: log progress during store initialization #115760

Merged
merged 3 commits into from Dec 8, 2023

Conversation

erikgrinaker
Copy link
Contributor

server: log store initialization duration and replica count

kvserver: log progress during store initialization

With large numbers of replicas, store initialization can take a long time. This patch adds progress logging every 10 seconds showing the current and total number of replicas initialized.

Here's an edited example of what it looks like (with injected delay):

I231207 12:21:16.799510 63 server/config.go:872 ⋮ [T1,Vsystem,n?] 16  1 storage engine initialized
I231207 12:21:17.387374 63 kv/kvserver/kvstorage/init.go:255 ⋮ [T1,Vsystem,n1,s1] 28  beginning range descriptor iteration
I231207 12:21:17.408276 63 kv/kvserver/kvstorage/init.go:316 ⋮ [T1,Vsystem,n1,s1] 31  range descriptor iteration done: 10125 keys, 8060 range descriptors (by suffix: map[qlpt:1938 rdsc:8060 txn-:127]); scan stats: stepped 65.158k times (115.088k internal); seeked 132 times (77 internal); block-bytes: (total 5.2 MiB, cached 581 KiB); points: (count 115.153k, key-bytes 2.8 MiB, value-bytes 4.2 MiB, tombstoned: 0) ranges: (count 0), (contained-points 0, skipped-points 0) evaluated requests: 0 gets, 11 scans, 0 reverse scans separated: (count: 50.573k, bytes: 3.9 MiB, bytes-fetched: 0 B)
I231207 12:21:17.578048 63 kv/kvserver/store.go:2126 ⋮ [T1,Vsystem,n1,s1] 32  loaded 8060 replicas, initializing
I231207 12:21:27.581307 63 kv/kvserver/store.go:2182 ⋮ [T1,Vsystem,n1,s1] 46  initialized 2876/8060 replicas
I231207 12:21:37.581983 63 kv/kvserver/store.go:2182 ⋮ [T1,Vsystem,n1,s1] 67  initialized 5740/8060 replicas
I231207 12:21:45.657393 63 kv/kvserver/store.go:2187 ⋮ [T1,Vsystem,n1,s1] 85  initialized 8060/8060 replicas
I231207 12:21:45.658419 63 server/node.go:663 ⋮ [T1,Vsystem,n1] 87  initialized store s1 in 28.272s (8060 replicas)

kvserver: reduce range descriptor iteration logging to 10 seconds

This harmonizes it with the replica initialization log interval during store initialization.

Resolves #115757.
Epic: none
Release note (ui change): store initialization now logs progress every 10 seconds.

@erikgrinaker erikgrinaker added backport-23.1.x Flags PRs that need to be backported to 23.1 backport-23.2.x Flags PRs that need to be backported to 23.2. labels Dec 7, 2023
@erikgrinaker erikgrinaker self-assigned this Dec 7, 2023
@erikgrinaker erikgrinaker requested review from a team as code owners December 7, 2023 12:27
Copy link

blathers-crl bot commented Dec 7, 2023

It looks like your PR touches production code but doesn't add or edit any test code. Did you consider adding tests to your PR?

🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.

@cockroach-teamcity
Copy link
Member

This change is Reviewable

@erikgrinaker erikgrinaker changed the title kvserver: log progress during replica initialization kvserver: log progress during store initialization Dec 7, 2023
Copy link
Collaborator

@stevendanna stevendanna left a comment

Choose a reason for hiding this comment

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

Nice. I like this kind of quality of life logging.

Copy link
Collaborator

@pav-kv pav-kv left a comment

Choose a reason for hiding this comment

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

Would we benefit from a corresponding metric too?

@erikgrinaker
Copy link
Contributor Author

We haven't started the HTTP server yet at this point, so we can't expose metrics.

With large numbers of replicas, store initialization can take a long
time. This patch adds progress logging every 10 seconds showing the
current and total number of replicas initialized.

Here's an edited example of what it looks like (with injected delay):

```
I231207 12:21:16.799510 63 server/config.go:872 ⋮ [T1,Vsystem,n?] 16  1 storage engine initialized
I231207 12:21:17.387374 63 kv/kvserver/kvstorage/init.go:255 ⋮ [T1,Vsystem,n1,s1] 28  beginning range descriptor iteration
I231207 12:21:17.408276 63 kv/kvserver/kvstorage/init.go:316 ⋮ [T1,Vsystem,n1,s1] 31  range descriptor iteration done: 10125 keys, 8060 range descriptors (by suffix: map[qlpt:1938 rdsc:8060 txn-:127]); scan stats: stepped 65.158k times (115.088k internal); seeked 132 times (77 internal); block-bytes: (total 5.2 MiB, cached 581 KiB); points: (count 115.153k, key-bytes 2.8 MiB, value-bytes 4.2 MiB, tombstoned: 0) ranges: (count 0), (contained-points 0, skipped-points 0) evaluated requests: 0 gets, 11 scans, 0 reverse scans separated: (count: 50.573k, bytes: 3.9 MiB, bytes-fetched: 0 B)
I231207 12:21:17.578048 63 kv/kvserver/store.go:2126 ⋮ [T1,Vsystem,n1,s1] 32  loaded 8060 replicas, initializing
I231207 12:21:27.581307 63 kv/kvserver/store.go:2182 ⋮ [T1,Vsystem,n1,s1] 46  initialized 2876/8060 replicas
I231207 12:21:37.581983 63 kv/kvserver/store.go:2182 ⋮ [T1,Vsystem,n1,s1] 67  initialized 5740/8060 replicas
I231207 12:21:45.657393 63 kv/kvserver/store.go:2187 ⋮ [T1,Vsystem,n1,s1] 85  initialized 8060/8060 replicas
I231207 12:21:45.658419 63 server/node.go:663 ⋮ [T1,Vsystem,n1] 87  initialized store s1 in 28.272s (8060 replicas)
```

Epic: none
Release note (ui change): store initialization now logs progress every
10 seconds.
This harmonizes it with the replica initialization log interval during
store initialization.

Epic: none
Release note: None
Copy link
Collaborator

@sean- sean- left a comment

Choose a reason for hiding this comment

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

Reviewed 1 of 1 files at r1, 1 of 1 files at r2, 1 of 1 files at r3, all commit messages.
Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @erikgrinaker)

@erikgrinaker
Copy link
Contributor Author

CI failures are unrelated.

bors r+

@craig
Copy link
Contributor

craig bot commented Dec 8, 2023

Build succeeded:

@craig craig bot merged commit 3150838 into cockroachdb:master Dec 8, 2023
7 of 9 checks passed
Copy link

blathers-crl bot commented Dec 8, 2023

Encountered an error creating backports. Some common things that can go wrong:

  1. The backport branch might have already existed.
  2. There was a merge conflict.
  3. The backport branch contained merge commits.

You might need to create your backport manually using the backport tool.


error creating merge commit from b145e49 to blathers/backport-release-23.1-115760: POST https://api.github.com/repos/cockroachdb/cockroach/merges: 409 Merge conflict []

you may need to manually resolve merge conflicts with the backport tool.

Backport to branch 23.1.x failed. See errors above.


error creating merge commit from b145e49 to blathers/backport-release-23.2-115760: POST https://api.github.com/repos/cockroachdb/cockroach/merges: 409 Merge conflict []

you may need to manually resolve merge conflicts with the backport tool.

Backport to branch 23.2.x failed. See errors above.


🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.

craig bot pushed a commit that referenced this pull request Dec 11, 2023
115871: kvserver: additional progress logging during store initialization r=erikgrinaker a=erikgrinaker

Follows #115760.
Epic: none
Release note: None

Co-authored-by: Erik Grinaker <grinaker@cockroachlabs.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
backport-23.1.x Flags PRs that need to be backported to 23.1 backport-23.2.x Flags PRs that need to be backported to 23.2.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

server: improve store initialization logging
5 participants