Skip to content

Commit 5787a3a

Browse files
gengliqiJaySon-Huang
gengliqi
and
JaySon-Huang
authored
proxy: Update proxy of 8.5 for adding a read index config and some related logs (#10515)
close #10495 proxy: Update proxy of 8.5 for adding a read index config and some related logs Signed-off-by: gengliqi <[email protected]> Signed-off-by: JaySon-Huang <[email protected]> Co-authored-by: JaySon-Huang <[email protected]>
1 parent 6a8b2c6 commit 5787a3a

File tree

13 files changed

+281
-101
lines changed

13 files changed

+281
-101
lines changed

‎contrib/tiflash-proxy‎

‎dbms/src/Common/TiFlashMetrics.h‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -580,6 +580,9 @@ static_assert(RAFT_REGION_BIG_WRITE_THRES * 4 < RAFT_REGION_BIG_WRITE_MAX, "Inva
580580
F(type_key_not_in_region, {{"type", "key_not_in_region"}}), \
581581
F(type_tikv_server_issue, {{"type", "tikv_server_issue"}}), \
582582
F(type_tikv_lock, {{"type", "tikv_lock"}}), \
583+
F(type_server_is_busy, {{"type", "server_is_busy"}}), \
584+
F(type_stale_command, {{"type", "stale_command"}}), \
585+
F(type_store_not_match, {{"type", "store_not_match"}}), \
583586
F(type_other, {{"type", "other"}})) \
584587
/* required by DBaaS */ \
585588
M(tiflash_server_info, \

‎dbms/src/Debug/ReadIndexStressTest.cpp‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -38,6 +38,7 @@ static const std::map<std::string, ReadIndexStressTest::TestType> TestName2Type
3838

3939
ReadIndexStressTest::ReadIndexStressTest(const TMTContext & tmt_)
4040
: tmt(tmt_)
41+
, logger(Logger::get("ReadIndexStressTest"))
4142
{
4243
MockStressTestCfg::enable = true;
4344
LOG_WARNING(logger, "enable MockStressTest");

‎dbms/src/Debug/ReadIndexStressTest.h‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -57,7 +57,7 @@ class ReadIndexStressTest
5757

5858
private:
5959
const TMTContext & tmt;
60-
Poco::Logger * logger{&Poco::Logger::get("ReadIndexStressTest")};
60+
LoggerPtr logger;
6161
};
6262

6363

‎dbms/src/Storages/KVStore/FFI/ProxyFFI.cpp‎

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -51,8 +51,6 @@ const std::string ColumnFamilyName::Lock = "lock";
5151
const std::string ColumnFamilyName::Default = "default";
5252
const std::string ColumnFamilyName::Write = "write";
5353

54-
extern const uint64_t DEFAULT_BATCH_READ_INDEX_TIMEOUT_MS;
55-
5654
ColumnFamilyType NameToCF(const std::string & cf)
5755
{
5856
if (cf.empty() || cf == ColumnFamilyName::Default)

‎dbms/src/Storages/KVStore/Read/LearnerReadWorker.cpp‎

Lines changed: 137 additions & 51 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@
2121
#include <Storages/KVStore/Types.h>
2222
#include <Storages/RegionQueryInfo.h>
2323
#include <common/likely.h>
24+
#include <common/logger_useful.h>
2425

2526
namespace DB
2627
{
@@ -37,8 +38,23 @@ void UnavailableRegions::tryThrowRegionException()
3738
if (!batch_cop && !region_locks.empty())
3839
throw LockException(std::move(region_locks));
3940

40-
if (!ids.empty())
41+
if (!unavailable_ids.empty())
42+
{
43+
RegionException::UnavailableRegions ids;
44+
RegionException::RegionReadStatus status = RegionException::RegionReadStatus::NOT_FOUND;
45+
String extra_msg;
46+
for (auto iter = unavailable_ids.begin(); iter != unavailable_ids.end(); ++iter)
47+
{
48+
const auto & [region_id, desc] = *iter;
49+
ids.emplace(region_id);
50+
if (iter == unavailable_ids.begin())
51+
{
52+
status = desc.s;
53+
extra_msg = desc.extra_msg;
54+
}
55+
}
4156
throw RegionException(std::move(ids), status, extra_msg.c_str());
57+
}
4258
}
4359

4460
void UnavailableRegions::addRegionWaitIndexTimeout(
@@ -48,7 +64,7 @@ void UnavailableRegions::addRegionWaitIndexTimeout(
4864
{
4965
if (!batch_cop)
5066
{
51-
// If server is being terminated / time-out, add the region_id into `unavailable_regions` to other store.
67+
// If server is being terminated or wait-index time-out, add the region_id into `unavailable_regions` to other store.
5268
addStatus(region_id, RegionException::RegionReadStatus::NOT_FOUND, "");
5369
return;
5470
}
@@ -64,6 +80,47 @@ void UnavailableRegions::addRegionWaitIndexTimeout(
6480
current_applied_index);
6581
}
6682

83+
String UnavailableRegions::toDebugString(size_t num_show) const
84+
{
85+
FmtBuffer buffer;
86+
buffer.append("{ids=[");
87+
{
88+
auto beg_it = unavailable_ids.begin();
89+
auto end_it = beg_it;
90+
if (num_show == 0) // show all
91+
end_it = unavailable_ids.end();
92+
else
93+
end_it = std::next(beg_it, std::min(num_show, unavailable_ids.size()));
94+
buffer.joinStr(
95+
beg_it,
96+
end_it,
97+
[](const auto & v, FmtBuffer & f) {
98+
f.fmtAppend(
99+
"{{region_id:{},s:{},msg:{}}}",
100+
v.first,
101+
magic_enum::enum_name(v.second.s),
102+
v.second.extra_msg);
103+
},
104+
"|");
105+
}
106+
buffer.append("] locks=[");
107+
{
108+
auto beg_it = region_locks.begin();
109+
auto end_it = beg_it;
110+
if (num_show == 0) // show all
111+
end_it = region_locks.end();
112+
else
113+
end_it = std::next(beg_it, std::min(num_show, region_locks.size()));
114+
buffer.joinStr(
115+
region_locks.begin(),
116+
region_locks.end(),
117+
[](const auto & v, FmtBuffer & f) { f.fmtAppend("{}({})", v.first, v.second->DebugString()); },
118+
"|");
119+
}
120+
buffer.append("]}");
121+
return buffer.toString();
122+
}
123+
67124
LearnerReadWorker::LearnerReadWorker(
68125
MvccQueryInfo & mvcc_query_info_,
69126
TMTContext & tmt_,
@@ -93,15 +150,16 @@ LearnerReadSnapshot LearnerReadWorker::buildRegionsSnapshot()
93150
LOG_WARNING(log, "region not found in KVStore, region_id={}", info.region_id);
94151
throw RegionException({info.region_id}, RegionException::RegionReadStatus::NOT_FOUND, nullptr);
95152
}
96-
regions_snapshot.emplace(info.region_id, std::move(region));
153+
auto ins_res = regions_snapshot.emplace(info.region_id, RegionLearnerReadSnapshot{std::move(region)});
154+
// make sure regions are not duplicated.
155+
if (unlikely(!ins_res.second))
156+
throw TiFlashException(
157+
Errors::Coprocessor::BadRequest,
158+
"Duplicate region_id, region_id={} n_request={} tracing_id={}",
159+
info.region_id,
160+
regions_info.size(),
161+
log->identifier());
97162
}
98-
// make sure regions are not duplicated.
99-
if (unlikely(regions_snapshot.size() != regions_info.size()))
100-
throw TiFlashException(
101-
Errors::Coprocessor::BadRequest,
102-
"Duplicate region id, n_request={} n_actual={}",
103-
regions_info.size(),
104-
regions_snapshot.size());
105163
return regions_snapshot;
106164
}
107165

@@ -176,6 +234,7 @@ void LearnerReadWorker::doBatchReadIndex(
176234
};
177235
kvstore->addReadIndexEvent(1);
178236
SCOPE_EXIT({ kvstore->addReadIndexEvent(-1); });
237+
// tiflash is just up or is shutting down, not ready for serving
179238
if (!tmt.checkRunning())
180239
{
181240
make_default_batch_read_index_result(true);
@@ -198,6 +257,7 @@ void LearnerReadWorker::doBatchReadIndex(
198257
}
199258
}
200259

260+
// Update `unavailable_regions` according to `read_index_result`.
201261
void LearnerReadWorker::recordReadIndexError(
202262
const LearnerReadSnapshot & regions_snapshot,
203263
RegionsReadIndexResult & read_index_result)
@@ -206,7 +266,7 @@ void LearnerReadWorker::recordReadIndexError(
206266
for (auto & [region_id, resp] : read_index_result)
207267
{
208268
std::string extra_msg;
209-
if (resp.has_region_error())
269+
if (resp.has_region_error()) // proto id = 5
210270
{
211271
const auto & region_error = resp.region_error();
212272
auto region_status = RegionException::RegionReadStatus::OTHER;
@@ -228,69 +288,91 @@ void LearnerReadWorker::recordReadIndexError(
228288
extra_msg = fmt::format("read_index_resp error, region_id={} not found in snapshot", region_id);
229289
}
230290
GET_METRIC(tiflash_raft_learner_read_failures_count, type_epoch_not_match).Increment();
291+
LOG_WARNING(
292+
log,
293+
"meet epoch not match region error {}, region_id={}",
294+
resp.ShortDebugString(),
295+
region_id);
231296
region_status = RegionException::RegionReadStatus::EPOCH_NOT_MATCH;
232297
}
233-
else if (region_error.has_not_leader())
298+
else if (region_error.has_not_leader()) // proto id = 2
234299
{
235300
GET_METRIC(tiflash_raft_learner_read_failures_count, type_not_leader).Increment();
301+
LOG_WARNING(log, "meet not leader region error {}, region_id={}", resp.ShortDebugString(), region_id);
236302
region_status = RegionException::RegionReadStatus::NOT_LEADER;
237303
}
238-
else if (region_error.has_region_not_found())
304+
else if (region_error.has_region_not_found()) // proto id = 3
239305
{
240306
// 1. From TiKV
241307
// 2. Can't send read index request
242-
// 3. Read index timeout
308+
// 3. Read index timeout in `ReadIndexWorkerManager::batchReadIndex`
243309
GET_METRIC(tiflash_raft_learner_read_failures_count, type_not_found_tikv).Increment();
310+
LOG_WARNING(log, "meet region not found error {}, region_id={}", resp.ShortDebugString(), region_id);
244311
region_status = RegionException::RegionReadStatus::NOT_FOUND_TIKV;
245312
}
246313
// Below errors seldomly happens in raftstore-v1, however, we are not sure if they will happen in v2.
247-
else if (region_error.has_flashbackinprogress() || region_error.has_flashbacknotprepared())
248-
{
249-
GET_METRIC(tiflash_raft_learner_read_failures_count, type_flashback).Increment();
250-
region_status = RegionException::RegionReadStatus::FLASHBACK;
251-
}
252-
else if (region_error.has_bucket_version_not_match())
253-
{
254-
GET_METRIC(tiflash_raft_learner_read_failures_count, type_bucket_epoch_not_match).Increment();
255-
LOG_DEBUG(
256-
log,
257-
"meet abnormal region error {}, [region_id={}]",
258-
resp.region_error().DebugString(),
259-
region_id);
260-
region_status = RegionException::RegionReadStatus::BUCKET_EPOCH_NOT_MATCH;
261-
}
262-
else if (region_error.has_key_not_in_region())
314+
else if (region_error.has_key_not_in_region()) // proto id = 4
263315
{
264316
GET_METRIC(tiflash_raft_learner_read_failures_count, type_key_not_in_region).Increment();
265-
LOG_DEBUG(
266-
log,
267-
"meet abnormal region error {}, [region_id={}]",
268-
resp.region_error().DebugString(),
269-
region_id);
317+
LOG_WARNING(log, "meet abnormal region error {}, region_id={}", resp.ShortDebugString(), region_id);
270318
region_status = RegionException::RegionReadStatus::KEY_NOT_IN_REGION;
271319
}
272-
else if (region_error.has_server_is_busy())
320+
else if (region_error.has_server_is_busy()) // proto id = 6
273321
{
274-
// 1. From TiKV
322+
// 1. From TiKV/TiFlash-Proxy
275323
// 2. Read index request timeout
276-
GET_METRIC(tiflash_raft_learner_read_failures_count, type_read_index_timeout).Increment();
277-
LOG_DEBUG(log, "meet abnormal region error {}, [region_id={}]", resp.ShortDebugString(), region_id);
324+
GET_METRIC(tiflash_raft_learner_read_failures_count, type_server_is_busy).Increment();
325+
LOG_WARNING(log, "meet abnormal region error {}, region_id={}", resp.ShortDebugString(), region_id);
278326
region_status = RegionException::RegionReadStatus::READ_INDEX_TIMEOUT;
279327
}
328+
else if (region_error.has_stale_command()) // proto id = 7
329+
{
330+
GET_METRIC(tiflash_raft_learner_read_failures_count, type_stale_command).Increment();
331+
LOG_WARNING(log, "meet abnormal region error {}, region_id={}", resp.ShortDebugString(), region_id);
332+
region_status = RegionException::RegionReadStatus::STALE_COMMAND;
333+
}
334+
else if (region_error.has_store_not_match()) // proto id = 8
335+
{
336+
GET_METRIC(tiflash_raft_learner_read_failures_count, type_store_not_match).Increment();
337+
LOG_WARNING(log, "meet abnormal region error {}, region_id={}", resp.ShortDebugString(), region_id);
338+
region_status = RegionException::RegionReadStatus::STORE_NOT_MATCH;
339+
}
280340
else if (
281-
region_error.has_raft_entry_too_large() || region_error.has_region_not_initialized()
282-
|| region_error.has_disk_full() || region_error.has_read_index_not_ready()
283-
|| region_error.has_proposal_in_merging_mode())
341+
region_error.has_raft_entry_too_large() // proto id = 9
342+
|| region_error.has_max_timestamp_not_synced() // proto id = 10
343+
|| region_error.has_read_index_not_ready() // proto id = 11
344+
|| region_error.has_proposal_in_merging_mode() // proto id = 12
345+
|| region_error.has_data_is_not_ready() // proto id = 13
346+
|| region_error.has_region_not_initialized() // proto id = 14
347+
|| region_error.has_disk_full() // proto id = 15
348+
|| region_error.has_recoveryinprogress() // proto id = 16
349+
|| region_error.has_is_witness() // proto id = 19
350+
|| region_error.has_mismatch_peer_id() // proto id = 20
351+
)
284352
{
285353
GET_METRIC(tiflash_raft_learner_read_failures_count, type_tikv_server_issue).Increment();
286-
LOG_DEBUG(log, "meet abnormal region error {}, [region_id={}]", resp.ShortDebugString(), region_id);
354+
LOG_WARNING(log, "meet abnormal region error {}, region_id={}", resp.ShortDebugString(), region_id);
287355
region_status = RegionException::RegionReadStatus::TIKV_SERVER_ISSUE;
288356
}
357+
else if (
358+
region_error.has_flashbackinprogress() || region_error.has_flashbacknotprepared()) // proto id = 17/18
359+
{
360+
GET_METRIC(tiflash_raft_learner_read_failures_count, type_flashback).Increment();
361+
LOG_WARNING(log, "meet flashback region error {}, region_id={}", resp.ShortDebugString(), region_id);
362+
region_status = RegionException::RegionReadStatus::FLASHBACK;
363+
}
364+
else if (region_error.has_bucket_version_not_match()) // proto id = 21
365+
{
366+
GET_METRIC(tiflash_raft_learner_read_failures_count, type_bucket_epoch_not_match).Increment();
367+
LOG_WARNING(log, "meet abnormal region error {}, region_id={}", resp.ShortDebugString(), region_id);
368+
region_status = RegionException::RegionReadStatus::BUCKET_EPOCH_NOT_MATCH;
369+
}
289370
else
290371
{
291372
GET_METRIC(tiflash_raft_learner_read_failures_count, type_other).Increment();
292-
LOG_DEBUG(log, "meet abnormal region error {}, [region_id={}]", resp.ShortDebugString(), region_id);
373+
LOG_WARNING(log, "meet abnormal region error {}, region_id={}", resp.ShortDebugString(), region_id);
293374
}
375+
// set `region_status`, `extra_msg` and mark the region_id as unavailable.
294376
unavailable_regions.addStatus(region_id, region_status, std::move(extra_msg));
295377
}
296378
else if (resp.has_locked())
@@ -338,14 +420,15 @@ RegionsReadIndexResult LearnerReadWorker::readIndex(
338420
log,
339421
log_lvl,
340422
"[Learner Read] Batch read index, num_regions={} num_requests={} num_stale_read={} num_cached_index={} "
341-
"num_unavailable={} cost={}ms, start_ts={}",
423+
"n_unavailable={} read_cost={}ms start_ts={} unavailable_regions={}",
342424
stats.num_regions,
343425
stats.num_read_index_request,
344426
stats.num_stale_read,
345427
stats.num_cached_read_index,
346428
unavailable_regions.size(),
347429
stats.read_index_elapsed_ms,
348-
mvcc_query_info.start_ts);
430+
mvcc_query_info.start_ts,
431+
unavailable_regions.toDebugString(5));
349432

350433
return batch_read_index_result;
351434
}
@@ -443,11 +526,14 @@ void LearnerReadWorker::waitIndex(
443526
LOG_IMPL(
444527
log,
445528
log_lvl,
446-
"[Learner Read] Finish wait index and resolve locks, wait_cost={}ms n_regions={} n_unavailable={}, start_ts={}",
529+
"[Learner Read] Finish wait index and resolve locks, wait_cost={}ms n_regions={} n_unavailable={} start_ts={} "
530+
"unavailable_regions={}",
447531
stats.wait_index_elapsed_ms,
448532
stats.num_regions,
449533
unavailable_regions.size(),
450-
mvcc_query_info.start_ts);
534+
mvcc_query_info.start_ts,
535+
unavailable_regions.toDebugString(5) // show first 5 details
536+
);
451537

452538
auto bypass_formatter = [](const RegionQueryInfo & query_info) -> String {
453539
if (query_info.bypass_lock_ts == nullptr)
@@ -483,9 +569,9 @@ void LearnerReadWorker::waitIndex(
483569

484570
LOG_DEBUG(
485571
log,
486-
"[Learner Read] Learner Read Summary, regions_info={}, unavailable_regions_info={}, start_ts={}",
572+
"[Learner Read] Learner Read Summary, regions_info={} unavailable_regions={} start_ts={}",
487573
region_info_formatter(),
488-
unavailable_regions.toDebugString(),
574+
unavailable_regions.toDebugString(0), // show all
489575
mvcc_query_info.start_ts);
490576
}
491577

@@ -525,7 +611,7 @@ LearnerReadWorker::waitUntilDataAvailable(
525611
log,
526612
log_lvl,
527613
"[Learner Read] batch read index | wait index"
528-
" total_cost={} read_cost={} wait_cost={} n_regions={} n_stale_read={} n_unavailable={}, start_ts={}",
614+
" total_cost={} read_cost={} wait_cost={} n_regions={} n_stale_read={} n_unavailable={} start_ts={}",
529615
time_elapsed_ms,
530616
stats.read_index_elapsed_ms,
531617
stats.wait_index_elapsed_ms,

0 commit comments

Comments
 (0)