From 136ceaa65a238c6f527b764a6cc9609bbebca415 Mon Sep 17 00:00:00 2001 From: Doodle <13706157+critical27@users.noreply.github.com> Date: Wed, 27 Nov 2019 20:05:49 +0800 Subject: [PATCH 1/4] fix raft case test --- src/kvstore/raftex/RaftPart.cpp | 7 +++---- src/kvstore/raftex/test/RaftexTestBase.cpp | 2 +- 2 files changed, 4 insertions(+), 5 deletions(-) diff --git a/src/kvstore/raftex/RaftPart.cpp b/src/kvstore/raftex/RaftPart.cpp index e71cca44dad..39bd5f1e351 100644 --- a/src/kvstore/raftex/RaftPart.cpp +++ b/src/kvstore/raftex/RaftPart.cpp @@ -952,7 +952,7 @@ bool RaftPart::needToStartElection() { std::lock_guard g(raftLock_); if (status_ == Status::RUNNING && role_ == Role::FOLLOWER && - (lastMsgRecvDur_.elapsedInSec() >= weight_ * FLAGS_raft_heartbeat_interval_secs || + (lastMsgRecvDur_.elapsedInMSec() >= weight_ * FLAGS_raft_heartbeat_interval_secs * 1000 || term_ == 0)) { LOG(INFO) << idStr_ << "Start leader election, reason: lastMsgDur " << lastMsgRecvDur_.elapsedInSec() @@ -1083,10 +1083,9 @@ bool RaftPart::leaderElection() { // Result evaluator [hosts, this](size_t idx, cpp2::AskForVoteResponse& resp) { if (resp.get_error_code() == cpp2::ErrorCode::E_LOG_STALE) { - LOG(INFO) << idStr_ << "My last log id is less than " << hosts[idx] + LOG(INFO) << idStr_ << "My last log id is less than " << hosts[idx]->address() << ", double my election interval."; - uint64_t curWeight = weight_.load(); - weight_.store(curWeight * 2); + weight_.fetch_add(1); } return resp.get_error_code() == cpp2::ErrorCode::SUCCEEDED; }); diff --git a/src/kvstore/raftex/test/RaftexTestBase.cpp b/src/kvstore/raftex/test/RaftexTestBase.cpp index a923cc6dde9..8cf0a9e8e7e 100644 --- a/src/kvstore/raftex/test/RaftexTestBase.cpp +++ b/src/kvstore/raftex/test/RaftexTestBase.cpp @@ -98,7 +98,7 @@ void waitUntilLeaderElected( }); // Sleep some time to wait until resp of heartbeat has come back when elected as leader - usleep(30000); + usleep(50000); bool sameLeader = true; int32_t index = 0; From 23084a95c305d29956ee4b38f2bd02c7450d64c7 Mon Sep 17 00:00:00 2001 From: Doodle <13706157+critical27@users.noreply.github.com> Date: Thu, 28 Nov 2019 13:51:28 +0800 Subject: [PATCH 2/4] modify some log level --- src/kvstore/NebulaStore.cpp | 4 ++-- src/kvstore/Part.cpp | 2 +- src/kvstore/raftex/Host.cpp | 3 ++- src/kvstore/raftex/RaftPart.cpp | 12 ++++-------- src/kvstore/raftex/RaftexService.cpp | 4 ++-- src/kvstore/wal/FileBasedWal.cpp | 4 ++-- src/meta/client/MetaClient.cpp | 12 ++++++------ 7 files changed, 19 insertions(+), 22 deletions(-) diff --git a/src/kvstore/NebulaStore.cpp b/src/kvstore/NebulaStore.cpp index 15d88c8aa3b..429dd321415 100644 --- a/src/kvstore/NebulaStore.cpp +++ b/src/kvstore/NebulaStore.cpp @@ -164,7 +164,7 @@ ErrorOr NebulaStore::partLeader(GraphSpaceID spaceId, Part void NebulaStore::addSpace(GraphSpaceID spaceId) { folly::RWSpinLock::WriteHolder wh(&lock_); if (this->spaces_.find(spaceId) != this->spaces_.end()) { - LOG(INFO) << "Space " << spaceId << " has existed!"; + VLOG(1) << "Space " << spaceId << " has existed!"; return; } LOG(INFO) << "Create space " << spaceId; @@ -180,7 +180,7 @@ void NebulaStore::addPart(GraphSpaceID spaceId, PartitionID partId, bool asLearn auto spaceIt = this->spaces_.find(spaceId); CHECK(spaceIt != this->spaces_.end()) << "Space should exist!"; if (spaceIt->second->parts_.find(partId) != spaceIt->second->parts_.end()) { - LOG(INFO) << "[" << spaceId << "," << partId << "] has existed!"; + VLOG(1) << "[" << spaceId << "," << partId << "] has existed!"; return; } diff --git a/src/kvstore/Part.cpp b/src/kvstore/Part.cpp index 7a492d15294..e1f82757914 100644 --- a/src/kvstore/Part.cpp +++ b/src/kvstore/Part.cpp @@ -60,7 +60,7 @@ std::pair Part::lastCommittedLogId() { std::string val; ResultCode res = engine_->get(NebulaKeyUtils::systemCommitKey(partId_), &val); if (res != ResultCode::SUCCEEDED) { - LOG(ERROR) << "Cannot fetch the last committed log id from the storage engine"; + LOG(INFO) << idStr_ << "Cannot fetch the last committed log id from the storage engine"; return std::make_pair(0, 0); } CHECK_EQ(val.size(), sizeof(LogID) + sizeof(TermID)); diff --git a/src/kvstore/raftex/Host.cpp b/src/kvstore/raftex/Host.cpp index c1d2bc67e20..cdebf3f84c9 100644 --- a/src/kvstore/raftex/Host.cpp +++ b/src/kvstore/raftex/Host.cpp @@ -417,7 +417,8 @@ Host::prepareAppendLogRequest() { self->sendingSnapshot_ = false; }); } else { - LOG(INFO) << idStr_ << "The snapshot req is in queue, please wait for a moment"; + PLOG_EVERY_N(INFO, 30) << idStr_ + << "The snapshot req is in queue, please wait for a moment"; } } diff --git a/src/kvstore/raftex/RaftPart.cpp b/src/kvstore/raftex/RaftPart.cpp index 39bd5f1e351..5a7b54183f6 100644 --- a/src/kvstore/raftex/RaftPart.cpp +++ b/src/kvstore/raftex/RaftPart.cpp @@ -350,7 +350,7 @@ AppendLogResult RaftPart::canAppendLogs() { return AppendLogResult::E_STOPPED; } if (role_ != Role::LEADER) { - LOG(ERROR) << idStr_ << "The partition is not a leader"; + PLOG_EVERY_N(ERROR, 100) << idStr_ << "The partition is not a leader"; return AppendLogResult::E_NOT_A_LEADER; } @@ -613,8 +613,8 @@ folly::Future RaftPart::appendLogAsync(ClusterID source, } if (!checkAppendLogResult(res)) { - LOG(ERROR) << idStr_ - << "Cannot append logs, clean the buffer"; + // Mosy likely failed because the parttion is not leader + PLOG_EVERY_N(ERROR, 100) << idStr_ << "Cannot append logs, clean the buffer"; return res; } // Replicate buffered logs to all followers @@ -955,13 +955,10 @@ bool RaftPart::needToStartElection() { (lastMsgRecvDur_.elapsedInMSec() >= weight_ * FLAGS_raft_heartbeat_interval_secs * 1000 || term_ == 0)) { LOG(INFO) << idStr_ << "Start leader election, reason: lastMsgDur " - << lastMsgRecvDur_.elapsedInSec() + << lastMsgRecvDur_.elapsedInMSec() << ", term " << term_; role_ = Role::CANDIDATE; leader_ = HostAddr(0, 0); - LOG(INFO) << idStr_ - << "needToStartElection: lastMsgRecvDur " << lastMsgRecvDur_.elapsedInSec() - << ", term_ " << term_; } return role_ == Role::CANDIDATE; @@ -1147,7 +1144,6 @@ bool RaftPart::leaderElection() { void RaftPart::statusPolling() { size_t delay = FLAGS_raft_heartbeat_interval_secs * 1000 / 3; if (needToStartElection()) { - LOG(INFO) << idStr_ << "Need to start leader election"; if (leaderElection()) { VLOG(2) << idStr_ << "Stop the election"; } else { diff --git a/src/kvstore/raftex/RaftexService.cpp b/src/kvstore/raftex/RaftexService.cpp index a7d67f62e45..4564819e50c 100644 --- a/src/kvstore/raftex/RaftexService.cpp +++ b/src/kvstore/raftex/RaftexService.cpp @@ -177,8 +177,8 @@ std::shared_ptr RaftexService::findPart( auto it = parts_.find(std::make_pair(spaceId, partId)); if (it == parts_.end()) { // Part not found - LOG(ERROR) << "Cannot find the part " << partId - << " in the graph space " << spaceId; + LOG(WARNING) << "Cannot find the part " << partId + << " in the graph space " << spaceId; return std::shared_ptr(); } diff --git a/src/kvstore/wal/FileBasedWal.cpp b/src/kvstore/wal/FileBasedWal.cpp index 0d25ed834b5..03c14073f09 100644 --- a/src/kvstore/wal/FileBasedWal.cpp +++ b/src/kvstore/wal/FileBasedWal.cpp @@ -54,7 +54,8 @@ FileBasedWal::FileBasedWal(const folly::StringPiece dir, lastLogId_ = info->lastId(); lastLogTerm_ = info->lastTerm(); LOG(INFO) << idStr_ << "lastLogId in wal is " << lastLogId_ - << ", lastLogTerm is " << lastLogTerm_; + << ", lastLogTerm is " << lastLogTerm_ + << ", path is " << info->path(); currFd_ = open(info->path(), O_WRONLY | O_APPEND); currInfo_ = info; CHECK_GE(currFd_, 0); @@ -456,7 +457,6 @@ void FileBasedWal::scanLastWal(WalFileInfoPtr info, LogID firstId) { ++curLogId; } - LOG(INFO) << idStr_ << "Scan last wal " << path << ", last wal id is " << id; if (0 < pos && pos < FileUtils::fileSize(path)) { LOG(WARNING) << "Invalid wal " << path << ", truncate from offset " << pos; diff --git a/src/meta/client/MetaClient.cpp b/src/meta/client/MetaClient.cpp index 4540db2aee1..3d71c0c0ee8 100644 --- a/src/meta/client/MetaClient.cpp +++ b/src/meta/client/MetaClient.cpp @@ -183,13 +183,13 @@ bool MetaClient::loadData() { } diff(oldCache, localCache_); ready_ = true; - LOG(INFO) << "Load data completed!"; return true; } void MetaClient::addLoadDataTask() { size_t delayMS = FLAGS_load_data_interval_secs * 1000 + folly::Random::rand32(900); bgThread_->addDelayTask(delayMS, &MetaClient::loadDataThreadFunc, this); + LOG(INFO) << "Load data completed, call after " << delayMS << " ms"; } @@ -309,9 +309,9 @@ void MetaClient::getResponse(Request req, respGen = std::move(respGen), pro = std::move(pro), toLeader, retry, retryLimit, this] () mutable { auto client = clientsMan_->client(host, evb); - LOG(INFO) << "Send request to meta " << host; + VLOG(1) << "Send request to meta " << host; remoteFunc(client, req).via(evb) - .then([req = std::move(req), remoteFunc = std::move(remoteFunc), + .then([host, req = std::move(req), remoteFunc = std::move(remoteFunc), respGen = std::move(respGen), pro = std::move(pro), toLeader, retry, retryLimit, evb, this] (folly::Try&& t) mutable { // exception occurred during RPC @@ -335,7 +335,7 @@ void MetaClient::getResponse(Request req, }, FLAGS_meta_client_retry_interval_secs * 1000); return; } else { - LOG(INFO) << "Exceed retry limit"; + LOG(ERROR) << "Send request to " << host << ", exceed retry limit"; pro.setValue(Status::Error(folly::stringPrintf("RPC failure in MetaClient: %s", t.exception().what().c_str()))); } @@ -1137,7 +1137,7 @@ folly::Future> MetaClient::heartbeat() { req.set_cluster_id(clusterId_.load()); folly::Promise> promise; auto future = promise.getFuture(); - LOG(INFO) << "Send heartbeat to " << leader_ << ", clusterId " << req.get_cluster_id(); + VLOG(1) << "Send heartbeat to " << leader_ << ", clusterId " << req.get_cluster_id(); getResponse(std::move(req), [] (auto client, auto request) { return client->future_heartBeat(request); }, [this] (cpp2::HBResp&& resp) -> bool { @@ -1318,7 +1318,7 @@ void MetaClient::loadCfg() { } } } else { - LOG(INFO) << "Load configs failed: " << ret.status(); + LOG(ERROR) << "Load configs failed: " << ret.status(); return; } } From 5f09c8d688b51b644941bab66c2d17540e748abc Mon Sep 17 00:00:00 2001 From: Doodle <13706157+critical27@users.noreply.github.com> Date: Fri, 29 Nov 2019 14:28:55 +0800 Subject: [PATCH 3/4] address @dangleptr's comments --- src/kvstore/NebulaStore.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/kvstore/NebulaStore.cpp b/src/kvstore/NebulaStore.cpp index 429dd321415..15d88c8aa3b 100644 --- a/src/kvstore/NebulaStore.cpp +++ b/src/kvstore/NebulaStore.cpp @@ -164,7 +164,7 @@ ErrorOr NebulaStore::partLeader(GraphSpaceID spaceId, Part void NebulaStore::addSpace(GraphSpaceID spaceId) { folly::RWSpinLock::WriteHolder wh(&lock_); if (this->spaces_.find(spaceId) != this->spaces_.end()) { - VLOG(1) << "Space " << spaceId << " has existed!"; + LOG(INFO) << "Space " << spaceId << " has existed!"; return; } LOG(INFO) << "Create space " << spaceId; @@ -180,7 +180,7 @@ void NebulaStore::addPart(GraphSpaceID spaceId, PartitionID partId, bool asLearn auto spaceIt = this->spaces_.find(spaceId); CHECK(spaceIt != this->spaces_.end()) << "Space should exist!"; if (spaceIt->second->parts_.find(partId) != spaceIt->second->parts_.end()) { - VLOG(1) << "[" << spaceId << "," << partId << "] has existed!"; + LOG(INFO) << "[" << spaceId << "," << partId << "] has existed!"; return; } From 1320ac3aef1e50f4af8817bceefc0920733d3c51 Mon Sep 17 00:00:00 2001 From: Doodle <13706157+critical27@users.noreply.github.com> Date: Mon, 2 Dec 2019 13:43:47 +0800 Subject: [PATCH 4/4] address @dangleptr's comments --- src/kvstore/raftex/RaftPart.cpp | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/kvstore/raftex/RaftPart.cpp b/src/kvstore/raftex/RaftPart.cpp index 5a7b54183f6..602fb390683 100644 --- a/src/kvstore/raftex/RaftPart.cpp +++ b/src/kvstore/raftex/RaftPart.cpp @@ -1082,7 +1082,8 @@ bool RaftPart::leaderElection() { if (resp.get_error_code() == cpp2::ErrorCode::E_LOG_STALE) { LOG(INFO) << idStr_ << "My last log id is less than " << hosts[idx]->address() << ", double my election interval."; - weight_.fetch_add(1); + uint64_t curWeight = weight_.load(); + weight_.store(curWeight * 2); } return resp.get_error_code() == cpp2::ErrorCode::SUCCEEDED; });