Skip to content

Commit 407b7bf

Browse files
committed
[yugabyte#30307] DocDB: Convert spammy logs to DETAIL level
Summary: Introduces a new `DETAIL_LEVEL` to the RocksDB `InfoLogLevel` enum, providing a way to tag high-frequency informational logs with a "DETAIL: " prefix while keeping them visible at the default INFO log level. This enables downstream log filtering/grep without changing log visibility semantics. Summary of changes: - Added DETAIL_LEVEL to InfoLogLevel enum and GetFilterLogLevel() helper so DETAIL and INFO share the same visibility threshold - Added per-entry log level to LogBuffer so buffered DETAIL entries flush with the correct level - Added log-level support to EventLogger/EventLoggerStream so individual event log call sites can opt into DETAIL - Unified the "DETAIL: " string literal into the shared YB_DETAIL_LOG_PREFIX macro - Using all of the above for log level migrations (INFO/DEBUG -> DETAIL) Jira: DB-20188 Test Plan: Jenkins: all tests Added some unit tests to: `yb_rocksdb_logger-test.cc`, `auto_roll_logger_test.cc` and `env_test.cc` Verification through logs of local test runs: `ybd release --cxx-test flush-test --gtest_filter '*.TestFlushPicksOldestInactiveTabletAfterCompaction'` Some DETAIL log lines: ``` [ts-1] I0212 22:54:26.167357 86911 memtable_list.cc:410] DETAIL: T 08a2e6c27d134601876040adbd3c012a P 51dea67900734de7b314d7687b3ad0ea [R]: [default] Level-0 commit table #14 started [ts-1] I0212 22:54:26.167373 86911 memtable_list.cc:426] DETAIL: T 08a2e6c27d134601876040adbd3c012a P 51dea67900734de7b314d7687b3ad0ea [R]: [default] Level-0 commit table #14: memtable #1 done [ts-1] I0212 22:54:26.167378 86911 event_logger.cc:89] DETAIL: T 08a2e6c27d134601876040adbd3c012a P 51dea67900734de7b314d7687b3ad0ea [R]: EVENT_LOG_v1 {"time_micros": 1770936866166824, "job": 5, "event": "flush_finished", "lsm_state": [4]} [ts-1] I0212 22:54:26.169718 87257 tablet_retention_policy.cc:203] DETAIL: T 08a2e6c27d134601876040adbd3c012a P 51dea67900734de7b314d7687b3ad0ea: SanitizeHistoryCutoff, cutoff from the provider { cotables_cutoff_ht: <invalid> primary_cutoff_ht: <max> } ``` Reviewers: hsunder, mlillibridge, sergei, arybochkin Reviewed By: mlillibridge, arybochkin Subscribers: sanketh, ybase Differential Revision: https://phorge.dev.yugabyte.com/D50302
1 parent 387a3f2 commit 407b7bf

24 files changed

Lines changed: 277 additions & 73 deletions

src/yb/consensus/log.cc

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -838,7 +838,7 @@ Status Log::RollOver() {
838838

839839
DCHECK_EQ(allocation_state(), SegmentAllocationState::kAllocationFinished);
840840

841-
LOG_WITH_PREFIX(INFO) << Format(
841+
LOG_WITH_PREFIX_DETAIL << Format(
842842
"Last appended OpId in segment $0: $1", active_segment_->path(),
843843
last_appended_entry_op_id_.ToString());
844844

@@ -847,7 +847,7 @@ Status Log::RollOver() {
847847

848848
RETURN_NOT_OK(SwitchToAllocatedSegment());
849849

850-
LOG_WITH_PREFIX(INFO) << "Rolled over to a new segment: " << active_segment_->path();
850+
LOG_WITH_PREFIX_DETAIL << "Rolled over to a new segment: " << active_segment_->path();
851851
}
852852
return Status::OK();
853853
}
@@ -1599,7 +1599,7 @@ OpId Log::WaitForSafeOpIdToApply(const OpId& min_allowed, MonoDelta duration) {
15991599
Status Log::GC(int64_t min_op_idx, int32_t* num_gced) {
16001600
CHECK_GE(min_op_idx, 0);
16011601

1602-
LOG_WITH_PREFIX(INFO) << "Running Log GC on " << wal_dir_ << ": retaining ops >= " << min_op_idx
1602+
LOG_WITH_PREFIX_DETAIL << "Running Log GC on " << wal_dir_ << ": retaining ops >= " << min_op_idx
16031603
<< ", log segment size = " << options_.segment_size_bytes;
16041604
VLOG_TIMING(1, "Log GC") {
16051605
SegmentSequence segments_to_delete;
@@ -1625,9 +1625,10 @@ Status Log::GC(int64_t min_op_idx, int32_t* num_gced) {
16251625
// Now that they are no longer referenced by the Log, delete the files.
16261626
*num_gced = 0;
16271627
for (const scoped_refptr<ReadableLogSegment>& segment : segments_to_delete) {
1628-
LOG_WITH_PREFIX(INFO) << "Deleting log segment in path: " << segment->path()
1629-
<< " (GCed ops < " << segment->footer().max_replicate_index() + 1
1630-
<< ")";
1628+
LOG_WITH_PREFIX_DETAIL
1629+
<< "Deleting log segment in path: " << segment->path()
1630+
<< " (GCed ops < " << segment->footer().max_replicate_index() + 1
1631+
<< ")";
16311632
RETURN_NOT_OK(get_env()->DeleteFile(segment->path()));
16321633
(*num_gced)++;
16331634

src/yb/consensus/log_reader.cc

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -510,7 +510,7 @@ Status LogReader::TrimSegmentsUpToAndIncluding(const int64_t segment_sequence_nu
510510
RETURN_NOT_OK(segments_.pop_front());
511511
deleted_segments.push_back(current_seq_no);
512512
}
513-
LOG_WITH_PREFIX(INFO) << "Removed log segment sequence numbers from log reader: "
513+
LOG_WITH_PREFIX_DETAIL << "Removed log segment sequence numbers from log reader: "
514514
<< yb::ToString(deleted_segments);
515515
return Status::OK();
516516
}

src/yb/docdb/docdb_rocksdb_util.cc

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -933,7 +933,7 @@ class RocksDBPatcher::Impl {
933933
auto& consensus_frontier = down_cast<ConsensusFrontier&>(*file.largest.user_frontier);
934934
// If all the data in the file is already as of old time, no need to set any filter.
935935
if (consensus_frontier.hybrid_time() <= value) {
936-
LOG(INFO) << "No need to set hybrid time filter since the largest frontier is already"
936+
LOG_DETAIL << "No need to set hybrid time filter since the largest frontier is already"
937937
<< " older. Largest frontier HT " << consensus_frontier.hybrid_time()
938938
<< ", filter HT " << value;
939939
return;

src/yb/rocksdb/db/auto_roll_logger_test.cc

Lines changed: 33 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -363,23 +363,37 @@ TEST_F(AutoRollLoggerTest, InfoLogLevel) {
363363
for (int log_type = InfoLogLevel::DEBUG_LEVEL;
364364
log_type <= InfoLogLevel::HEADER_LEVEL; log_type++) {
365365
// log messages with log level smaller than log_level will not be
366-
// logged.
366+
// logged, except that DETAIL_LEVEL messages are treated as equivalent
367+
// to INFO_LEVEL for filtering (via ShouldLog): if log_level is
368+
// INFO_LEVEL, DETAIL messages will also be logged alongside INFO.
367369
LogMessage((InfoLogLevel)log_type, &logger, kSampleMessage.c_str());
368370
}
369371
log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
372+
// DETAIL_LEVEL is treated as equivalent to INFO_LEVEL for filtering
373+
// (via ShouldLog), so at INFO_LEVEL the DETAIL message also passes.
374+
if (log_level == InfoLogLevel::INFO_LEVEL) {
375+
log_lines++;
376+
}
370377
}
371378
for (int log_level = InfoLogLevel::HEADER_LEVEL;
372379
log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
373380
logger.SetInfoLogLevel((InfoLogLevel)log_level);
374381

375-
// again, messages with level smaller than log_level will not be logged.
382+
// again, messages with level smaller than log_level will not be logged,
383+
// with the exception of DETAIL_LEVEL messages and an INFO_LEVEL logger.
376384
RLOG(InfoLogLevel::HEADER_LEVEL, &logger, "%s", kSampleMessage.c_str());
377385
RDEBUG(&logger, "%s", kSampleMessage.c_str());
386+
RLOG(InfoLogLevel::DETAIL_LEVEL, &logger, "%s", kSampleMessage.c_str());
378387
RINFO(&logger, "%s", kSampleMessage.c_str());
379388
RWARN(&logger, "%s", kSampleMessage.c_str());
380389
RERROR(&logger, "%s", kSampleMessage.c_str());
381390
RFATAL(&logger, "%s", kSampleMessage.c_str());
382391
log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
392+
// DETAIL_LEVEL is treated as equivalent to INFO_LEVEL for filtering
393+
// (via ShouldLog), so at INFO_LEVEL the DETAIL message also passes.
394+
if (log_level == InfoLogLevel::INFO_LEVEL) {
395+
log_lines++;
396+
}
383397
}
384398
}
385399
std::ifstream inFile(AutoRollLoggerTest::kLogFile.c_str());
@@ -485,6 +499,23 @@ TEST_F(AutoRollLoggerTest, LogHeaderTest) {
485499
}
486500
}
487501

502+
TEST_F(AutoRollLoggerTest, DetailLevelFiltering) {
503+
InitTestDb();
504+
505+
size_t log_size = 8192;
506+
{
507+
AutoRollLogger logger(Env::Default(), kTestDir, "", log_size, 0);
508+
logger.SetInfoLogLevel(InfoLogLevel::INFO_LEVEL);
509+
510+
RLOG(InfoLogLevel::DETAIL_LEVEL, &logger, "test_detail");
511+
RLOG(InfoLogLevel::INFO_LEVEL, &logger, "test_info");
512+
}
513+
514+
// DETAIL messages pass at INFO level (ShouldLog treats DETAIL as equivalent to INFO).
515+
ASSERT_EQ(1u, GetLinesCount(kLogFile, "test_detail"));
516+
ASSERT_EQ(1u, GetLinesCount(kLogFile, "test_info"));
517+
}
518+
488519
TEST_F(AutoRollLoggerTest, LogFileExistence) {
489520
rocksdb::DB* db;
490521
rocksdb::Options options;

src/yb/rocksdb/db/compaction_job.cc

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1053,7 +1053,7 @@ Status CompactionJob::InstallCompactionResults(
10531053

10541054
{
10551055
Compaction::InputLevelSummaryBuffer inputs_summary;
1056-
RLOG(InfoLogLevel::INFO_LEVEL, db_options_.info_log,
1056+
RLOG(InfoLogLevel::DETAIL_LEVEL, db_options_.info_log,
10571057
"[%s] [JOB %d] Compacted %s => %" PRIu64 " bytes",
10581058
compaction->column_family_data()->GetName().c_str(), job_id_,
10591059
compaction->InputLevelSummary(&inputs_summary), compact_->total_bytes);
@@ -1068,7 +1068,7 @@ Status CompactionJob::InstallCompactionResults(
10681068
}
10691069
}
10701070
if (largest_user_frontier_) {
1071-
LOG_WITH_PREFIX(INFO) << "Updating flushed frontier to " << largest_user_frontier_->ToString();
1071+
LOG_WITH_PREFIX_DETAIL << "Updating flushed frontier to " << largest_user_frontier_->ToString();
10721072
compaction->edit()->UpdateFlushedFrontier(largest_user_frontier_);
10731073
}
10741074
return versions_->LogAndApply(compaction->column_family_data(),
@@ -1333,14 +1333,14 @@ void CompactionJob::LogCompaction() {
13331333
}
13341334
}
13351335
Compaction::InputLevelSummaryBuffer inputs_summary;
1336-
RLOG(InfoLogLevel::INFO_LEVEL, db_options_.info_log,
1336+
RLOG(InfoLogLevel::DETAIL_LEVEL, db_options_.info_log,
13371337
"[%s] [JOB %d] Compacting %s, score %.2f", cfd->GetName().c_str(),
13381338
job_id_, compaction->InputLevelSummary(&inputs_summary),
13391339
compaction->score());
13401340
char scratch[2345];
13411341
compaction->Summary(scratch, sizeof(scratch));
13421342
RLOG(
1343-
InfoLogLevel::INFO_LEVEL, db_options_.info_log, "[%s] Compaction start summary: %s%s\n",
1343+
InfoLogLevel::DETAIL_LEVEL, db_options_.info_log, "[%s] Compaction start summary: %s%s\n",
13441344
cfd->GetName().c_str(), scratch,
13451345
compaction->skip_corrupt_data_blocks_unsafe()
13461346
? " WILL DELETE ANY CORRUPT DATA BLOCKS IF FOUND"

src/yb/rocksdb/db/compaction_picker.cc

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -1571,7 +1571,7 @@ std::unique_ptr<Compaction> UniversalCompactionPicker::DoPickCompaction(
15711571
cf_name, mutable_cf_options, vstorage, score, sorted_runs, log_buffer);
15721572
}
15731573
if (c) {
1574-
LOG_TO_BUFFER(log_buffer, "[%s] Universal: compacting for direct deletion\n",
1574+
LOG_TO_BUFFER_DETAIL(log_buffer, "[%s] Universal: compacting for direct deletion\n",
15751575
cf_name.c_str());
15761576
} else {
15771577
// Check if the number of files to compact is greater than or equal to
@@ -1587,7 +1587,7 @@ std::unique_ptr<Compaction> UniversalCompactionPicker::DoPickCompaction(
15871587
c = PickCompactionUniversalSizeAmp(cf_name, mutable_cf_options, vstorage,
15881588
score, sorted_runs, log_buffer);
15891589
if (c) {
1590-
LOG_TO_BUFFER(log_buffer, "[%s] Universal: compacting for size amp\n",
1590+
LOG_TO_BUFFER_DETAIL(log_buffer, "[%s] Universal: compacting for size amp\n",
15911591
cf_name.c_str());
15921592
} else {
15931593
// Size amplification is within limits. Try reducing read
@@ -1599,7 +1599,7 @@ std::unique_ptr<Compaction> UniversalCompactionPicker::DoPickCompaction(
15991599
ioptions_.compaction_options_universal.always_include_size_threshold,
16001600
sorted_runs, log_buffer);
16011601
if (c) {
1602-
LOG_TO_BUFFER(log_buffer, "[%s] Universal: compacting for size ratio\n",
1602+
LOG_TO_BUFFER_DETAIL(log_buffer, "[%s] Universal: compacting for size ratio\n",
16031603
cf_name.c_str());
16041604
} else {
16051605
// ENG-1401: We trigger compaction logic when num files exceeds
@@ -1628,7 +1628,7 @@ std::unique_ptr<Compaction> UniversalCompactionPicker::DoPickCompaction(
16281628
cf_name, mutable_cf_options, vstorage, score, UINT_MAX, num_files,
16291629
ioptions_.compaction_options_universal.always_include_size_threshold,
16301630
sorted_runs, log_buffer)) != nullptr) {
1631-
LOG_TO_BUFFER(log_buffer,
1631+
LOG_TO_BUFFER_DETAIL(log_buffer,
16321632
"[%s] Universal: compacting for file num -- %u\n",
16331633
cf_name.c_str(), num_files);
16341634
}
@@ -1896,8 +1896,8 @@ std::unique_ptr<Compaction> UniversalCompactionPicker::PickCompactionUniversalRe
18961896
}
18971897
char file_num_buf[kFormatFileSizeInfoBufSize];
18981898
picking_sr.DumpSizeInfo(file_num_buf, sizeof(file_num_buf), i);
1899-
LOG_TO_BUFFER(log_buffer, "[%s] Universal: Picking %s", cf_name.c_str(),
1900-
file_num_buf);
1899+
LOG_TO_BUFFER_DETAIL(
1900+
log_buffer, "[%s] Universal: Picking %s", cf_name.c_str(), file_num_buf);
19011901
}
19021902

19031903
CompactionReason compaction_reason;

src/yb/rocksdb/db/db_filesnapshot.cc

Lines changed: 2 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -48,8 +48,7 @@ Status DBImpl::DisableFileDeletions() {
4848
InstrumentedMutexLock l(&mutex_);
4949
++disable_delete_obsolete_files_;
5050
if (disable_delete_obsolete_files_ == 1) {
51-
RLOG(InfoLogLevel::INFO_LEVEL, db_options_.info_log,
52-
"File Deletions Disabled");
51+
RLOG(InfoLogLevel::DETAIL_LEVEL, db_options_.info_log, "File Deletions Disabled");
5352
} else {
5453
RLOG(InfoLogLevel::WARN_LEVEL, db_options_.info_log,
5554
"File Deletions Disabled, but already disabled. Counter: %d",
@@ -72,7 +71,7 @@ Status DBImpl::EnableFileDeletions(bool force) {
7271
--disable_delete_obsolete_files_;
7372
}
7473
if (disable_delete_obsolete_files_ == 0) {
75-
RLOG(InfoLogLevel::INFO_LEVEL, db_options_.info_log,
74+
RLOG(InfoLogLevel::DETAIL_LEVEL, db_options_.info_log,
7675
"File Deletions Enabled");
7776
should_purge_files = true;
7877
FindObsoleteFiles(&job_context, true);

src/yb/rocksdb/db/flush_job.cc

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -227,7 +227,7 @@ Result<FileNumbersHolder> FlushJob::Run(FileMetaData* file_meta) {
227227
// This includes both SST and MANIFEST files IO.
228228
RecordFlushIOStats();
229229

230-
auto stream = event_logger_->LogToBuffer(log_buffer_);
230+
auto stream = event_logger_->LogToBuffer(log_buffer_, InfoLogLevel::DETAIL_LEVEL);
231231
stream << "job" << job_context_->job_id << "event"
232232
<< "flush_finished";
233233
stream << "lsm_state";
@@ -263,7 +263,7 @@ Result<FileNumbersHolder> FlushJob::WriteLevel0Table(
263263
uint64_t total_num_entries = 0, total_num_deletes = 0;
264264
size_t total_memory_usage = 0;
265265
for (MemTable* m : mems) {
266-
RLOG(InfoLogLevel::INFO_LEVEL, db_options_.info_log,
266+
RLOG(InfoLogLevel::DETAIL_LEVEL, db_options_.info_log,
267267
"[%s] [JOB %d] Flushing memtable with next log file: %" PRIu64 "\n",
268268
cfd_->GetName().c_str(), job_context_->job_id, m->GetNextLogNumber());
269269
memtables.push_back(m->NewIterator(ro, &arena));
@@ -293,7 +293,7 @@ Result<FileNumbersHolder> FlushJob::WriteLevel0Table(
293293
ScopedArenaIterator iter(
294294
NewMergingIterator(cfd_->internal_comparator().get(), &memtables[0],
295295
static_cast<int>(memtables.size()), &arena));
296-
RLOG(InfoLogLevel::INFO_LEVEL, db_options_.info_log,
296+
RLOG(InfoLogLevel::DETAIL_LEVEL, db_options_.info_log,
297297
"[%s] [JOB %d] Level-0 flush table #%" PRIu64 ": started",
298298
cfd_->GetName().c_str(), job_context_->job_id, meta->fd.GetNumber());
299299

@@ -320,7 +320,7 @@ Result<FileNumbersHolder> FlushJob::WriteLevel0Table(
320320
info.table_properties = table_properties_;
321321
LogFlush(db_options_.info_log);
322322
}
323-
RLOG(InfoLogLevel::INFO_LEVEL, db_options_.info_log,
323+
RLOG(InfoLogLevel::DETAIL_LEVEL, db_options_.info_log,
324324
"[%s] [JOB %d] Level-0 flush table #%" PRIu64 ": %" PRIu64
325325
" bytes %s%s %s",
326326
cfd_->GetName().c_str(), job_context_->job_id, meta->fd.GetNumber(),

src/yb/rocksdb/db/memtable_list.cc

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -407,8 +407,8 @@ Status MemTableList::InstallMemtableFlushResults(
407407
break;
408408
}
409409

410-
LOG_TO_BUFFER(log_buffer, "[%s] Level-0 commit table #%" PRIu64 " started",
411-
cfd->GetName().c_str(), m->file_number_);
410+
LOG_TO_BUFFER_DETAIL(log_buffer, "[%s] Level-0 commit table #%" PRIu64 " started",
411+
cfd->GetName().c_str(), m->file_number_);
412412

413413
// this can release and reacquire the mutex.
414414
s = vset->LogAndApply(cfd, mutable_cf_options, &m->edit_, mu, db_directory);
@@ -422,9 +422,9 @@ Status MemTableList::InstallMemtableFlushResults(
422422
uint64_t mem_id = 1; // how many memtables have been flushed.
423423
do {
424424
if (s.ok()) { // commit new state
425-
LOG_TO_BUFFER(log_buffer, "[%s] Level-0 commit table #%" PRIu64
426-
": memtable #%" PRIu64 " done",
427-
cfd->GetName().c_str(), m->file_number_, mem_id);
425+
LOG_TO_BUFFER_DETAIL(log_buffer, "[%s] Level-0 commit table #%" PRIu64
426+
": memtable #%" PRIu64 " done",
427+
cfd->GetName().c_str(), m->file_number_, mem_id);
428428
assert(m->file_number_ > 0);
429429
current_->Remove(m, to_delete);
430430
} else {

src/yb/rocksdb/env.h

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -454,6 +454,7 @@ class Directory {
454454

455455
enum InfoLogLevel : unsigned char {
456456
DEBUG_LEVEL = 0,
457+
DETAIL_LEVEL,
457458
INFO_LEVEL,
458459
WARN_LEVEL,
459460
ERROR_LEVEL,
@@ -462,6 +463,24 @@ enum InfoLogLevel : unsigned char {
462463
NUM_INFO_LOG_LEVELS,
463464
};
464465

466+
// Returns true if a message at `message_level` should be logged given a logger
467+
// configured at `logger_level`. DETAIL_LEVEL is treated as equivalent to
468+
// INFO_LEVEL for filtering: a logger at INFO will show DETAIL messages and
469+
// vice versa.
470+
inline bool ShouldLog(InfoLogLevel message_level, InfoLogLevel logger_level) {
471+
if (message_level >= logger_level) {
472+
return true;
473+
}
474+
475+
// Special handling for DETAIL_LEVEL.
476+
if (message_level == InfoLogLevel::DETAIL_LEVEL && logger_level == InfoLogLevel::INFO_LEVEL) {
477+
return true;
478+
}
479+
480+
// Nothing to log in accordance with log levels.
481+
return false;
482+
}
483+
465484
// An interface for writing log messages.
466485
class Logger {
467486
public:

0 commit comments

Comments
 (0)