Skip to content

Commit

Permalink
FAP: Add some logs (#9095)
Browse files Browse the repository at this point in the history 
close #9091, ref #9098

Signed-off-by: CalvinNeo <[email protected]>
  • Loading branch information
@CalvinNeo
CalvinNeo authored May 31, 2024
1 parent 52f47a9 commit 640f856
Show file tree
Hide file tree
Showing 11 changed files with 214 additions and 128 deletions.
27 changes: 17 additions & 10 deletions dbms/src/Debug/MockKVStore/MockRaftStoreProxy.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -167,16 +167,23 @@ void MockRaftStoreProxy::debugAddRegions(
{
UNUSED(tmt);
int n = ranges.size();
auto _ = genLockGuard();
auto task_lock = kvs.genTaskLock();
auto lock = kvs.genRegionMgrWriteLock(task_lock);
for (int i = 0; i < n; ++i)
{
regions.emplace(region_ids[i], std::make_shared<MockProxyRegion>(region_ids[i]));
auto region = tests::makeRegion(region_ids[i], ranges[i].first, ranges[i].second, kvs.getProxyHelper());
lock.regions.emplace(region_ids[i], region);
lock.index.add(region);
tmt.getRegionTable().updateRegion(*region);
{
auto _ = genLockGuard();
for (int i = 0; i < n; ++i)
{
regions.emplace(region_ids[i], std::make_shared<MockProxyRegion>(region_ids[i]));
}
}
{
auto task_lock = kvs.genTaskLock(); // No region events
auto lock = kvs.genRegionMgrWriteLock(task_lock); // Region mgr lock
for (int i = 0; i < n; ++i)
{
auto region = tests::makeRegion(region_ids[i], ranges[i].first, ranges[i].second, kvs.getProxyHelper());
lock.regions.emplace(region_ids[i], region);
lock.index.add(region);
tmt.getRegionTable().updateRegion(*region);
}
}
}

Expand Down
28 changes: 28 additions & 0 deletions dbms/src/Storages/KVStore/tests/gtest_new_kvstore.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1078,6 +1078,17 @@ try
delete[] a;
});
t2.join();

std::thread t3([&]() {
// Will not cover mmap memory.
auto [allocated, deallocated] = JointThreadInfoJeallocMap::getPtrs();
char * a = new char[120];
void * buf = mmap(nullptr, 6000, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANONYMOUS, -1, 0);
ASSERT_LT(*allocated, 6000);
munmap(buf, 0);
delete[] a;
});
t3.join();
}
CATCH

Expand Down Expand Up @@ -1131,4 +1142,21 @@ try
}
CATCH

TEST_F(RegionKVStoreTest, ParseUniPage)
try
{
String origin = "0101020000000000000835010000000000021AE8";
auto decode = Redact::hexStringToKey(origin.data(), origin.size());
const char * data = decode.data();
size_t len = decode.size();
ASSERT_EQ(RecordKVFormat::readUInt8(data, len), UniversalPageIdFormat::RAFT_PREFIX);
ASSERT_EQ(RecordKVFormat::readUInt8(data, len), 0x01);
ASSERT_EQ(RecordKVFormat::readUInt8(data, len), 0x02);
// RAFT_PREFIX LOCAL_PREFIX REGION_RAFT_PREFIX region_id RAFT_LOG_SUFFIX
LOG_INFO(DB::Logger::get(), "region_id={}", RecordKVFormat::readUInt64(data, len));
ASSERT_EQ(RecordKVFormat::readUInt8(data, len), 0x01);
LOG_INFO(DB::Logger::get(), "index={}", RecordKVFormat::readUInt64(data, len));
}
CATCH

} // namespace DB::tests
7 changes: 4 additions & 3 deletions dbms/src/Storages/Page/V3/Blob/GCInfo.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,7 @@ struct fmt::formatter<DB::PS::V3::BlobFileGCInfo>
template <typename FormatContext>
auto format(const DB::PS::V3::BlobFileGCInfo & i, FormatContext & ctx) const
{
return fmt::format_to(ctx.out(), "<id:{} rate:{:.2f}>", i.blob_id, i.valid_rate);
return fmt::format_to(ctx.out(), "<blob_id={} rate={:.2f}>", i.blob_id, i.valid_rate);
}
};
template <>
Expand All @@ -53,7 +53,7 @@ struct fmt::formatter<DB::PS::V3::BlobFileTruncateInfo>
{
return fmt::format_to(
ctx.out(),
"<id:{} origin:{} truncate:{} rate:{:.2f}>",
"<blob_id={} origin={} truncate={} rate={:.2f}>",
i.blob_id,
i.origin_size,
i.truncated_size,
Expand Down Expand Up @@ -86,7 +86,7 @@ String BlobStoreGCInfo::toTypeString(const Type type_index) const
if (blob_gc_info[type_index].empty())
return fmt::format("{{{}: [null]}}", magic_enum::enum_name(type_index));

// e.g. {FullGC: [<id:4 rate:0.16>]}}
// e.g. {FullGC: [<blob_id=4 rate=0.16>]}
FmtBuffer fmt_buf;
fmt_buf.fmtAppend("{{{}: [", magic_enum::enum_name(type_index))
.joinStr(
Expand All @@ -103,6 +103,7 @@ String BlobStoreGCInfo::toTypeTruncateString(const Type type_index) const
if (blob_gc_truncate_info.empty())
return fmt::format("{{{}: [null]}}", magic_enum::enum_name(type_index));

// e.g. {Truncated: [<blob_id=221 origin=0 truncate=0 rate=0.00>]}
FmtBuffer fmt_buf;
fmt_buf.fmtAppend("{{{}: [", magic_enum::enum_name(type_index))
.joinStr(
Expand Down
102 changes: 55 additions & 47 deletions dbms/src/Storages/Page/V3/BlobStore.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -128,7 +128,7 @@ void BlobStore<Trait>::registerPaths() NO_THREAD_SAFETY_ANALYSIS
}
else
{
LOG_INFO(log, "Ignore not blob file [dir={}] [file={}] [err_msg={}]", path, blob_name, err_msg);
LOG_INFO(log, "Ignore not blob file, dir={} file={} err_msg={}", path, blob_name, err_msg);
}
}
}
Expand Down Expand Up @@ -627,8 +627,8 @@ typename BlobStore<Trait>::PageEntriesEdit BlobStore<Trait>::write(
removePosFromStats(blob_id, offset_in_file, actually_allocated_size);
throw Exception(
ErrorCodes::LOGICAL_ERROR,
"write batch have a invalid total size, or something wrong in parse write batch "
"[expect_offset={}] [actual_offset={}] [actually_allocated_size={}]",
"write batch have a invalid total size, or something wrong in parse write batch"
", expect_offset={} actual_offset={} actually_allocated_size={}",
all_page_data_size,
(buffer_pos - buffer),
actually_allocated_size);
Expand Down Expand Up @@ -667,7 +667,7 @@ void BlobStore<Trait>::freezeBlobFiles()
}

template <typename Trait>
void BlobStore<Trait>::remove(const PageEntries & del_entries) NO_THREAD_SAFETY_ANALYSIS
void BlobStore<Trait>::removeEntries(const PageEntries & del_entries) NO_THREAD_SAFETY_ANALYSIS
{
std::set<BlobFileId> blob_updated;
for (const auto & entry : del_entries)
Expand All @@ -690,7 +690,7 @@ void BlobStore<Trait>::remove(const PageEntries & del_entries) NO_THREAD_SAFETY_
}
catch (DB::Exception & e)
{
e.addMessage(fmt::format("while removing entry [entry={}]", entry));
e.addMessage(fmt::format("while removing entry, entry={}", entry));
e.rethrow();
}
}
Expand All @@ -712,8 +712,8 @@ void BlobStore<Trait>::remove(const PageEntries & del_entries) NO_THREAD_SAFETY_
}
LOG_TRACE(
log,
"Blob recalculated capability [blob_id={}] [max_cap={}] "
"[total_size={}] [valid_size={}] [valid_rate={}]",
"Blob recalculated capability blob_id={} max_cap={} "
"total_size={} valid_size={} valid_rate={}",
blob_id,
stat->sm_max_caps,
stat->sm_total_size,
Expand Down Expand Up @@ -770,8 +770,8 @@ std::pair<BlobFileId, BlobFileOffset> BlobStore<Trait>::getPosFromStats(size_t s
LOG_ERROR(Logger::get(), stat->smap->toDebugString());
throw Exception(
ErrorCodes::LOGICAL_ERROR,
"Get postion from BlobStat failed, it may caused by `sm_max_caps` is no correct. [size={}] "
"[old_max_caps={}] [max_caps={}] [blob_id={}]",
"Get postion from BlobStat failed, it may caused by `sm_max_caps` is no correct. size={} "
"old_max_caps={} max_caps={} blob_id={}",
size,
old_max_cap,
stat->sm_max_caps,
Expand Down Expand Up @@ -801,7 +801,13 @@ void BlobStore<Trait>::removePosFromStats(BlobFileId blob_id, BlobFileOffset off
// Note that we must release the lock on blob_stat before removing it
// from all blob_stats, or deadlocks could happen.
// As the blob_stat has been became read-only, it is safe to release the lock.
LOG_INFO(log, "Removing BlobFile [blob_id={}]", blob_id);
LOG_INFO(
log,
"Removing BlobFile, blob_id={} read_only={} offset={} size={}",
blob_id,
stat->isReadOnly(),
offset,
size);

{
// Remove the stat from memory
Expand Down Expand Up @@ -877,8 +883,9 @@ typename BlobStore<Trait>::PageMap BlobStore<Trait>::read(FieldReadInfos & to_re
#ifndef NDEBUG
// throw an exception under debug mode so we should change the upper layer logic
throw Exception(
fmt::format("Reading with fields but entry size is 0, read_info=[{}]", buf.toString()),
ErrorCodes::LOGICAL_ERROR);
ErrorCodes::LOGICAL_ERROR,
"Reading with fields but entry size is 0, read_info=[{}]",
buf.toString());
#endif
// Log a warning under production release
LOG_WARNING(log, "Reading with fields but entry size is 0, read_info=[{}]", buf.toString());
Expand Down Expand Up @@ -926,9 +933,9 @@ typename BlobStore<Trait>::PageMap BlobStore<Trait>::read(FieldReadInfos & to_re
throw Exception(
ErrorCodes::CHECKSUM_DOESNT_MATCH,
"Reading with fields meet checksum not match "
"[page_id={}] [expected=0x{:X}] [actual=0x{:X}] "
"[field_index={}] [field_offset={}] [field_size={}] "
"[entry={}] [file={}]",
"page_id={} expected=0x{:X} actual=0x{:X} "
"field_index={} field_offset={} field_size={} "
"entry={} file={}",
page_id_v3,
expect_checksum,
field_checksum,
Expand Down Expand Up @@ -966,12 +973,11 @@ typename BlobStore<Trait>::PageMap BlobStore<Trait>::read(FieldReadInfos & to_re
},
",");
throw Exception(
fmt::format(
"unexpected read size, end_pos={} current_pos={} read_info=[{}]",
shared_data_buf + buf_size,
pos,
buf.toString()),
ErrorCodes::LOGICAL_ERROR);
ErrorCodes::LOGICAL_ERROR,
"unexpected read size, end_pos={} current_pos={} read_info=[{}]",
shared_data_buf + buf_size,
pos,
buf.toString());
}
return page_map;
}
Expand Down Expand Up @@ -1032,15 +1038,14 @@ typename BlobStore<Trait>::PageMap BlobStore<Trait>::read(
if (unlikely(entry.size != 0 && checksum != entry.checksum))
{
throw Exception(
fmt::format(
"Reading with entries meet checksum not match [page_id={}] [expected=0x{:X}] [actual=0x{:X}] "
"[entry={}] [file={}]",
page_id_v3,
entry.checksum,
checksum,
entry,
blob_file->getPath()),
ErrorCodes::CHECKSUM_DOESNT_MATCH);
ErrorCodes::CHECKSUM_DOESNT_MATCH,
"Reading with entries meet checksum not match page_id={} expected=0x{:X} actual=0x{:X} "
"entry={} file={}",
page_id_v3,
entry.checksum,
checksum,
entry,
blob_file->getPath());
}
}

Expand Down Expand Up @@ -1071,12 +1076,11 @@ typename BlobStore<Trait>::PageMap BlobStore<Trait>::read(
},
",");
throw Exception(
fmt::format(
"unexpected read size, end_pos={} current_pos={} read_info=[{}]",
data_buf + buf_size,
pos,
buf.toString()),
ErrorCodes::LOGICAL_ERROR);
ErrorCodes::LOGICAL_ERROR,
"unexpected read size, end_pos={} current_pos={} read_info=[{}]",
data_buf + buf_size,
pos,
buf.toString());
}

return page_map;
Expand Down Expand Up @@ -1211,7 +1215,7 @@ typename BlobStore<Trait>::PageTypeAndBlobIds BlobStore<Trait>::getGCStats() NO_
if (stat->isReadOnly())
{
blobstore_gc_info.appendToReadOnlyBlob(stat->id, stat->sm_valid_rate);
LOG_TRACE(log, "Current [blob_id={}] is read-only", stat->id);
LOG_TRACE(log, "Current blob is read-only, blob_id={}", stat->id);
continue;
}

Expand All @@ -1226,7 +1230,7 @@ typename BlobStore<Trait>::PageTypeAndBlobIds BlobStore<Trait>::getGCStats() NO_
// TODO: avoid always truncate on empty BlobFile
RUNTIME_CHECK_MSG(
stat->sm_valid_size == 0,
"Current blob is empty, but valid size is not 0. [blob_id={}] [valid_size={}] [valid_rate={}]",
"Current blob is empty, but valid size is not 0, blob_id={} valid_size={} valid_rate={}",
stat->id,
stat->sm_valid_size,
stat->sm_valid_rate);
Expand All @@ -1236,7 +1240,7 @@ typename BlobStore<Trait>::PageTypeAndBlobIds BlobStore<Trait>::getGCStats() NO_
auto blobfile = getBlobFile(stat->id);
LOG_INFO(
log,
"Current blob file is empty, truncated to zero [blob_id={}] [total_size={}] [valid_rate={}]",
"Current blob file is empty, truncated to zero, blob_id={} total_size={} valid_rate={}",
stat->id,
stat->sm_total_size,
stat->sm_valid_rate);
Expand All @@ -1254,8 +1258,7 @@ typename BlobStore<Trait>::PageTypeAndBlobIds BlobStore<Trait>::getGCStats() NO_
{
LOG_ERROR(
log,
"Current blob got an invalid rate {:.2f}, total size is {}, valid size is {}, right boundary is {} "
"[blob_id={}]",
"Current blob got an invalid rate {:.2f}, total_size={} valid_size={} right_boundary={} blob_id={}",
stat->sm_valid_rate,
stat->sm_total_size,
stat->sm_valid_size,
Expand All @@ -1279,7 +1282,11 @@ typename BlobStore<Trait>::PageTypeAndBlobIds BlobStore<Trait>::getGCStats() NO_
bool do_full_gc = stat->sm_valid_rate <= heavy_gc_threhold;
if (do_full_gc)
{
LOG_TRACE(log, "Current [blob_id={}] valid rate is {:.2f}, full GC", stat->id, stat->sm_valid_rate);
LOG_TRACE(
log,
"Current blob will run full GC, blob_id={} valid_rate={:.2f}",
stat->id,
stat->sm_valid_rate);
if (blob_need_gc.find(page_type) == blob_need_gc.end())
{
blob_need_gc.emplace(page_type, std::vector<BlobFileId>());
Expand All @@ -1293,15 +1300,15 @@ typename BlobStore<Trait>::PageTypeAndBlobIds BlobStore<Trait>::getGCStats() NO_
else
{
blobstore_gc_info.appendToNoNeedGCBlob(stat->id, stat->sm_valid_rate);
LOG_TRACE(log, "Current [blob_id={}] valid rate is {:.2f}, unchange", stat->id, stat->sm_valid_rate);
LOG_TRACE(log, "Current blob unchange, blob_id={} valid_rate={:.2f}", stat->id, stat->sm_valid_rate);
}

if (right_boundary != stat->sm_total_size)
{
auto blobfile = getBlobFile(stat->id);
LOG_TRACE(
log,
"Truncate blob file [blob_id={}] [origin size={}] [truncated size={}]",
"Truncate blob file, blob_id={} origin_size={} truncated_size={}",
stat->id,
stat->sm_total_size,
right_boundary);
Expand All @@ -1318,7 +1325,7 @@ typename BlobStore<Trait>::PageTypeAndBlobIds BlobStore<Trait>::getGCStats() NO_
LOG_IMPL(
log,
blobstore_gc_info.getLoggingLevel(),
"BlobStore gc get status done. blob_ids details {}",
"BlobStore gc get status done. details {}",
blobstore_gc_info.toString());

return blob_need_gc;
Expand Down Expand Up @@ -1359,7 +1366,7 @@ void BlobStore<Trait>::gc(
written_blobs.emplace_back(file_id, file_offset, data_size);
LOG_INFO(
log,
"BlobStore gc write (partially) done [blob_id={}] [file_offset={}] [size={}] [total_size={}]",
"BlobStore gc write (partially) done, blob_id={} file_offset={} size={} total_size={}",
file_id,
file_offset,
data_size,
Expand All @@ -1370,7 +1377,7 @@ void BlobStore<Trait>::gc(
{
LOG_ERROR(
log,
"BlobStore gc write failed [blob_id={}] [offset={}] [size={}] [total_size={}]",
"BlobStore gc write failed, blob_id={} offset={} size={} total_size={}",
file_id,
file_offset,
data_size,
Expand Down Expand Up @@ -1479,6 +1486,7 @@ void BlobStore<Trait>::gc(
{
write_blob(blobfile_id, data_buf, file_offset_begin, offset_in_data);
}
LOG_INFO(log, "BlobStore gc write done, blob_id={} type={}", blobfile_id, magic_enum::enum_name(page_type));
}

template <typename Trait>
Expand Down
2 changes: 1 addition & 1 deletion dbms/src/Storages/Page/V3/BlobStore.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -96,7 +96,7 @@ class BlobStore : private Allocator<false>
// New writes will be written to new BlobFiles.
void freezeBlobFiles();

void remove(const PageEntries & del_entries);
void removeEntries(const PageEntries & del_entries);

PageMap read(PageIdAndEntries & entries, const ReadLimiterPtr & read_limiter = nullptr);

Expand Down
2 changes: 1 addition & 1 deletion dbms/src/Storages/Page/V3/GCDefines.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -271,7 +271,7 @@ GCTimeStatistics ExternalPageCallbacksManager<Trait>::doGC(
// 2. Remove the expired entries in BlobStore.
// It won't delete the data on the disk.
// It will only update the SpaceMap which in memory.
blob_store.remove(del_entries);
blob_store.removeEntries(del_entries);
statistics.compact_spacemap_ms = gc_watch.elapsedMillisecondsFromLastTime();
GET_METRIC(tiflash_storage_page_gc_duration_seconds, type_compact_spacemap)
.Observe(statistics.compact_spacemap_ms / 1000.0);
Expand Down
Loading

0 comments on commit 640f856

Please sign in to comment.