Skip to content

Persistent coordination log storage#20585

Merged
alesapin merged 56 commits intomasterfrom
persistent_nukeeper_log_storage
Feb 25, 2021
Merged

Persistent coordination log storage#20585
alesapin merged 56 commits intomasterfrom
persistent_nukeeper_log_storage

Conversation

@alesapin
Copy link
Copy Markdown
Member

@alesapin alesapin commented Feb 16, 2021

I hereby agree to the terms of the CLA available at: https://yandex.ru/legal/cla/?lang=en

Changelog category (leave one):

  • Not for changelog (changelog entry is not required)

Just the most straightforward way.

@robot-clickhouse robot-clickhouse added the pr-not-for-changelog This PR should not be mentioned in the changelog label Feb 16, 2021
@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Feb 17, 2021 •
edited
Loading

No reconnects, no errors with ZK... why fast test fails https://gist.github.com/alesapin/6293fdb422961968c530cc34e8a9d926? https://clickhouse-test-reports.s3.yandex.net/20585/9396bae2e2051e2d50faa0d8c1005465171db481/fast_test.html#fail1

@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Feb 17, 2021

Seems like #20627 is the reason.

@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Feb 17, 2021

Ok, seems like disks in CI slightly slower than on my machine.

@alesapin alesapin added do not test disable testing on pull request and removed force tests labels Feb 18, 2021
@alesapin alesapin removed the do not test disable testing on pull request label Feb 18, 2021
@alesapin alesapin marked this pull request as ready for review February 20, 2021 16:42
@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Feb 21, 2021 •
edited
Loading

For some reason, it takes more than a minute to start from the log with 854461 entries.... A similar amount of records on my machine takes about 10-20 seconds even with address sanitizer...

Same with memory sanitizer:

2021.02.21 19:35:21.172708 [ 732768 ] {} <Information> RaftInstance: [PRIORITY] decay, target 1 -> 1, mine 1
2021.02.21 19:35:21.172807 [ 732768 ] {} <Information> RaftInstance: [ELECTION TIMEOUT] current role: follower, log last term 1, state term 0, target p 1, my p 1, hb dead, pre-vote NOT done
2021.02.21 19:35:21.172946 [ 732768 ] {} <Information> RaftInstance: [VOTE INIT] my id 1, my role candidate, term 1, log idx 372306, log term 1, priority (target 1 / mine 1)
2021.02.21 19:35:21.173017 [ 732768 ] {} <Information> RaftInstance: number of pending commit elements: 0
2021.02.21 19:35:21.173064 [ 732768 ] {} <Information> RaftInstance: state machine commit index 0, precommit index 372306, last log index 372306
2021.02.21 19:35:21.173145 [ 732768 ] {} <Information> RaftInstance: found uncommitted config at 1, size 55
2021.02.21 19:35:21.173239 [ 732768 ] {} <Information> RaftInstance: found uncommitted config at 12, size 55
2021.02.21 19:35:22.167186 [ 732768 ] {} <Information> RaftInstance: [BECOME LEADER] appended new config at 372307
2021.02.21 19:35:22.167967 [ 732769 ] {} <Information> RaftInstance: config at index 1 is committed, prev config log idx 0
2021.02.21 19:35:22.168104 [ 732769 ] {} <Information> RaftInstance: new config log idx 1, prev log idx 0, cur config log idx 0, prev log idx 0
2021.02.21 19:35:22.168186 [ 732769 ] {} <Information> RaftInstance: new configuration: log idx 1, prev log idx 0
peer 1, DC ID 0, localhost:44444, voting member, 1
my id: 1, leader: 1, term: 1
2021.02.21 19:35:22.168319 [ 732769 ] {} <Debug> NuRaftStateMachine: Session ID response 0 with timeout 30000
2021.02.21 19:35:22.168936 [ 732769 ] {} <Information> RaftInstance: config at index 12 is committed, prev config log idx 1
2021.02.21 19:35:22.168998 [ 732769 ] {} <Information> RaftInstance: new config log idx 12, prev log idx 1, cur config log idx 1, prev log idx 0
2021.02.21 19:35:22.169035 [ 732769 ] {} <Information> RaftInstance: new configuration: log idx 12, prev log idx 1
peer 1, DC ID 0, localhost:44444, voting member, 1
my id: 1, leader: 1, term: 1
2021.02.21 19:35:22.169078 [ 732769 ] {} <Debug> NuRaftStateMachine: Session ID response 1 with timeout 30000
2021.02.21 19:35:59.143188 [ 732769 ] {} <Information> RaftInstance: config at index 372307 is committed, prev config log idx 12

More than 30 seconds...

@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Feb 23, 2021 •
edited
Loading

Functional stateless tests (release, DatabaseReplicated)
Cannot allocate block number in ZooKeeper: Coordination::Exception: Connection loss :(

2021.02.23 13:04:56.479313 [ 158 ] {} <Trace> NuKeeperTCPHandler: Received heartbeat for session #0
2021.02.23 13:05:09.248701 [ 158 ] {} <Information> NuKeeperTCPHandler: Got exception processing session #0: Code: 159, e.displayText() = DB::Exception: Cannot push request to queue within operation timeout, Stack trace (when copying this message, always include the lines below):
0. DB::NuKeeperStorageDispatcher::putRequest(std::__1::shared_ptr<Coordination::ZooKeeperRequest> const&, long) @ 0xfb18545 in /usr/lib/debug/.build-id/6c/de5c16adfcf2fa544faefc4ca2517db28a3825.debug
1. DB::NuKeeperTCPHandler::receiveRequest() @ 0xf844132 in /usr/lib/debug/.build-id/6c/de5c16adfcf2fa544faefc4ca2517db28a3825.debug
2. DB::NuKeeperTCPHandler::runImpl() @ 0xf841783 in /usr/lib/debug/.build-id/6c/de5c16adfcf2fa544faefc4ca2517db28a3825.debug
2021.02.23 13:05:09.255689 [ 158 ] {} <Trace> NuKeeperTCPHandlerFactory: NuKeeper request. Address: [::1]:46298
2021.02.23 13:05:09.255832 [ 158 ] {} <Information> NuKeeperTCPHandler: Requesting session ID for the new client
2021.02.23 13:05:09.255937 [ 158 ] {} <Information> NuKeeperTCPHandler: Received session ID 1

@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Feb 24, 2021

Tests Ok, but I don't understand why we have extremely rare Connection loss. Will try to investigate.

@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Feb 24, 2021 •
edited
Loading

Just found that it's not a problem with StateMachine or LogStore. Very rarely for some reason commit inside nuraft requires several seconds:

2021.02.24 12:32:20.068311 [ 15934 ] {} <Debug> NuKeeperTCPHandler: Finished 785
2021.02.24 12:32:20.068445 [ 15991 ] {} <Debug> NuKeeperStateMachine: Processing request 787
2021.02.24 12:32:20.068485 [ 15991 ] {} <Debug> NuKeeperStateMachine: DONE Processing request 787
2021.02.24 12:32:20.068536 [ 15934 ] {} <Debug> NuKeeperTCPHandler: Received 789
2021.02.24 12:32:20.068549 [ 15934 ] {} <Debug> NuKeeperTCPHandler: Finished 786
2021.02.24 12:32:20.068597 [ 15991 ] {} <Debug> NuKeeperStateMachine: Processing request 788
2021.02.24 12:32:20.068632 [ 15991 ] {} <Debug> NuKeeperStateMachine: DONE Processing request 788
2021.02.24 12:32:20.068682 [ 15934 ] {} <Debug> NuKeeperTCPHandler: Received 790
2021.02.24 12:32:20.068696 [ 15934 ] {} <Debug> NuKeeperTCPHandler: Finished 787
2021.02.24 12:32:20.068731 [ 15991 ] {} <Debug> NuKeeperStateMachine: Processing request 789
2021.02.24 12:32:20.068762 [ 15991 ] {} <Debug> NuKeeperStateMachine: DONE Processing request 789
2021.02.24 12:32:20.068816 [ 15934 ] {} <Debug> NuKeeperTCPHandler: Received 791
2021.02.24 12:32:20.068830 [ 15934 ] {} <Debug> NuKeeperTCPHandler: Finished 788
2021.02.24 12:32:20.068854 [ 15991 ] {} <Debug> NuKeeperStateMachine: Processing request 790
2021.02.24 12:32:20.068890 [ 15991 ] {} <Debug> NuKeeperStateMachine: DONE Processing request 790
2021.02.24 12:32:20.068939 [ 15934 ] {} <Debug> NuKeeperTCPHandler: Received 792
2021.02.24 12:32:20.068951 [ 15934 ] {} <Debug> NuKeeperTCPHandler: Finished 789
<...>
??? What is going on here?
It's important that the timer (`7000107 us`) start after entry appended to the log store.
<...>
2021.02.24 12:32:27.069070 [ 15994 ] {} <Warning> RaftInstance: [NOT OK] commit_ret_cv 802 wake up (7000107 us), return value (nil), result code -2
2021.02.24 12:32:27.069160 [ 15994 ] {} <Information> RaftInstance: leadership is still valid
2021.02.24 12:32:27.069296 [ 15991 ] {} <Debug> NuKeeperStateMachine: Processing request 791
2021.02.24 12:32:27.069336 [ 15991 ] {} <Debug> NuKeeperStateMachine: DONE Processing request 791
2021.02.24 12:32:27.069356 [ 15991 ] {} <Debug> NuKeeperStateMachine: Processing request 792
2021.02.24 12:32:27.069514 [ 15991 ] {} <Debug> NuKeeperStateMachine: DONE Processing request 792
2021.02.24 12:32:27.089966 [ 15934 ] {} <Information> NuKeeperTCPHandler: Got exception processing session #2: Code: 159, e.displayText() = DB::Exception: Cannot push request to queue within operation timeout, Stack trace (when copying this message, always include the lines below):

Reproduced several times, timer always around 7000107 microseconds.... Cannot reproduce with debug logs.

@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Feb 24, 2021

Ahh 7 seconds is my operation timeout.

@alesapin alesapin mentioned this pull request Feb 24, 2021
Merged
@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Feb 25, 2021

third-party -- not related
ANTLR debug -- not related, broken in #20968

@alesapin
Copy link
Copy Markdown
Member Author

alesapin commented Feb 25, 2021

Ok, let's merge and see what will happen.

@alesapin alesapin merged commit 8f81dce into master Feb 25, 2021
@alesapin alesapin deleted the persistent_nukeeper_log_storage branch February 25, 2021 07:06
@alesapin alesapin mentioned this pull request Feb 25, 2021
Closed
@lddlww
Copy link
Copy Markdown

lddlww commented Mar 25, 2021

does this feature（NuRaft）can be used in the newest version？，if is，how can i config？

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

pr-not-for-changelog This PR should not be mentioned in the changelog submodule changed At least one submodule changed in this PR.

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

3 participants

@alesapin @lddlww @robot-clickhouse