[DNM] Wal debug 6.29.tikv

db/db_impl/db_impl.cc

@@ -1487,12 +1487,15 @@ void DBImpl::MarkLogsSynced(uint64_t up_to, bool synced_dir,
  for (auto it = logs_.begin(); it != logs_.end() && it->number <= up_to;) {
  auto& wal = *it;
  assert(wal.IsSyncing());
-
+ ROCKS_LOG_INFO(immutable_db_options_.info_log,
+ "Synced log %" PRIu64 " from logs_\n", wal.number);
  if (logs_.size() > 1) {
  if (immutable_db_options_.track_and_verify_wals_in_manifest &&
  wal.GetPreSyncSize() > 0) {
  synced_wals->AddWal(wal.number, WalMetadata(wal.GetPreSyncSize()));
  }
+ ROCKS_LOG_INFO(immutable_db_options_.info_log,
+ "deleting log %" PRIu64 " from logs_\n", wal.number);
  logs_to_free_.push_back(wal.ReleaseWriter());
  it = logs_.erase(it);
  } else {
@@ -1507,12 +1510,18 @@ void DBImpl::MarkLogsSynced(uint64_t up_to, bool synced_dir,
 
 void DBImpl::MarkLogsNotSynced(uint64_t up_to) {
  log_write_mutex_.AssertHeld();
+ uint64_t min_wal = 0;
  for (auto it = logs_.begin(); it != logs_.end() && it->number <= up_to;
  ++it) {
  auto& wal = *it;
+ if (min_wal == 0) {
+ min_wal = it->number;
+ }
  wal.FinishSync();
  }
  log_sync_cv_.SignalAll();
+ ROCKS_LOG_INFO(immutable_db_options_.info_log,
+ "MarkLogsNotSynced from %" PRIu64 " to %" PRIu64 "\n", min_wal, up_to); 
 }
 
 SequenceNumber DBImpl::GetLatestSequenceNumber() const {

db/db_impl/db_impl_files.cc

@@ -293,6 +293,9 @@ void DBImpl::FindObsoleteFiles(JobContext* job_context, bool force,
  earliest.number);
  log_recycle_files_.push_back(earliest.number);
  } else {
+ ROCKS_LOG_INFO(immutable_db_options_.info_log,
+ "deleting WAL log %" PRIu64 "\n",
+ earliest.number);
  job_context->log_delete_files.push_back(earliest.number);
  }
  if (job_context->size_log_to_delete == 0) {
@@ -317,6 +320,8 @@ void DBImpl::FindObsoleteFiles(JobContext* job_context, bool force,
  // logs_ could have changed while we were waiting.
  continue;
  }
+ ROCKS_LOG_INFO(immutable_db_options_.info_log,
+ "deleting log %" PRIu64 " from logs_\n", log.number);
  logs_to_free_.push_back(log.ReleaseWriter());
  logs_.pop_front();
  }
@@ -491,6 +496,8 @@ void DBImpl::PurgeObsoleteFiles(JobContext& state, bool schedule_only) {
  // Close WALs before trying to delete them.
  for (const auto w : state.logs_to_free) {
  // TODO: maybe check the return value of Close.
+ ROCKS_LOG_INFO(immutable_db_options_.info_log,
+ "Close log %" PRIu64 " from logs_\n", w->get_log_number());
  auto s = w->Close();
  s.PermitUncheckedError();
  }

db/db_impl/db_impl_write.cc

@@ -1550,6 +1550,13 @@ IOStatus DBImpl::WriteToWAL(const WriteThread::WriteGroup& write_group,
  stats->AddDBStats(InternalStats::kIntStatsWriteWithWal, write_with_wal);
  RecordTick(stats_, WRITE_WITH_WAL, write_with_wal);
  }
+
+ if (log_writer->get_log_number() != logs_.back().number) {
+ ROCKS_LOG_INFO(immutable_db_options_.info_log,
+ "Not writing to latest WAL: [%" PRIu64 ", %" PRIu64 "]",
+ log_writer->get_log_number(), logs_.back().number);
+ }
+
  return io_s;
 }