You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@kudu.apache.org by to...@apache.org on 2017/05/18 16:53:47 UTC
kudu git commit: Improve logging during server startup
Repository: kudu
Updated Branches:
refs/heads/master 4347174d7 -> 733afeb82
Improve logging during server startup
This makes a few improvements to the log output during startup,
particularly helpful when there are lots of tablets:
- Only show progress reports of loading tablet metadata once a second,
with an indication of progress, rather than logging one line per
tablet.
- In the common case of reading a log which ends on a log entry
boundary, with all following data being preallocated space (all 0
bytes), don't log anything with the word "corruption" in it, to avoid
scaring users.
- Only log timing of Tablet::Open() when slow (>100ms)
- Bump various fine-grained details about tablet startup to VLOG(1)
level instead of LOG(INFO)
Change-Id: Ia5e597dfd08d5cf0cbbfe2c5ef532ffba9d113d7
Reviewed-on: http://gerrit.cloudera.org:8080/6913
Tested-by: Kudu Jenkins
Reviewed-by: Will Berkeley <wd...@gmail.com>
Project: http://git-wip-us.apache.org/repos/asf/kudu/repo
Commit: http://git-wip-us.apache.org/repos/asf/kudu/commit/733afeb8
Tree: http://git-wip-us.apache.org/repos/asf/kudu/tree/733afeb8
Diff: http://git-wip-us.apache.org/repos/asf/kudu/diff/733afeb8
Branch: refs/heads/master
Commit: 733afeb82d2c38332ee8e03ded4d93fb26a55517
Parents: 4347174
Author: Todd Lipcon <to...@cloudera.com>
Authored: Wed May 17 13:42:38 2017 -0700
Committer: Todd Lipcon <to...@apache.org>
Committed: Thu May 18 16:46:57 2017 +0000
----------------------------------------------------------------------
src/kudu/consensus/log_reader.cc | 8 ++-
src/kudu/consensus/log_util.cc | 86 +++++++++++++++++++--------
src/kudu/consensus/log_util.h | 39 +++++++++---
src/kudu/tablet/tablet.cc | 2 +-
src/kudu/tablet/tablet_bootstrap-test.cc | 13 +++-
src/kudu/tablet/tablet_bootstrap.cc | 23 +++----
src/kudu/tserver/ts_tablet_manager.cc | 5 ++
7 files changed, 126 insertions(+), 50 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/kudu/blob/733afeb8/src/kudu/consensus/log_reader.cc
----------------------------------------------------------------------
diff --git a/src/kudu/consensus/log_reader.cc b/src/kudu/consensus/log_reader.cc
index a9fe6de..e8262d4 100644
--- a/src/kudu/consensus/log_reader.cc
+++ b/src/kudu/consensus/log_reader.cc
@@ -157,8 +157,8 @@ Status LogReader::Init(const string& tablet_wal_path) {
CHECK(segment->IsInitialized()) << "Uninitialized segment at: " << segment->path();
if (!segment->HasFooter()) {
- LOG(INFO) << "Log segment " << fqp << " was likely left in-progress "
- "after a previous crash. Will try to rebuild footer by scanning data.";
+ VLOG(1) << "Log segment " << fqp << " was likely left in-progress "
+ << "after a previous crash. Will try to rebuild footer by scanning data.";
RETURN_NOT_OK(segment->RebuildFooterByScanning());
}
@@ -251,7 +251,9 @@ Status LogReader::ReadBatchUsingIndexEntry(const LogIndexEntry& index_entry,
CHECK_GT(index_entry.offset_in_segment, 0);
int64_t offset = index_entry.offset_in_segment;
ScopedLatencyMetric scoped(read_batch_latency_.get());
- RETURN_NOT_OK_PREPEND(segment->ReadEntryHeaderAndBatch(&offset, tmp_buf, batch),
+ EntryHeaderStatus unused_status_detail;
+ RETURN_NOT_OK_PREPEND(segment->ReadEntryHeaderAndBatch(&offset, tmp_buf, batch,
+ &unused_status_detail),
Substitute("Failed to read LogEntry for index $0 from log segment "
"$1 offset $2",
index,
http://git-wip-us.apache.org/repos/asf/kudu/blob/733afeb8/src/kudu/consensus/log_util.cc
----------------------------------------------------------------------
diff --git a/src/kudu/consensus/log_util.cc b/src/kudu/consensus/log_util.cc
index 30d68b1..8ef177c 100644
--- a/src/kudu/consensus/log_util.cc
+++ b/src/kudu/consensus/log_util.cc
@@ -148,14 +148,15 @@ Status LogEntryReader::ReadNextEntry(LogEntryPB* entry) {
// Read and validate the entry header first.
Status s;
+ EntryHeaderStatus s_detail = EntryHeaderStatus::OTHER_ERROR;
if (offset_ + seg_->entry_header_size() < read_up_to_) {
- s = seg_->ReadEntryHeaderAndBatch(&offset_, &tmp_buf_, ¤t_batch);
+ s = seg_->ReadEntryHeaderAndBatch(&offset_, &tmp_buf_, ¤t_batch, &s_detail);
} else {
s = Status::Corruption(Substitute("Truncated log entry at offset $0", offset_));
}
if (PREDICT_FALSE(!s.ok())) {
- return HandleReadError(s);
+ return HandleReadError(s, s_detail);
}
// Add the entries from this batch to our pending queue.
@@ -185,12 +186,11 @@ Status LogEntryReader::ReadNextEntry(LogEntryPB* entry) {
return Status::OK();
}
-Status LogEntryReader::HandleReadError(const Status& s) const {
+Status LogEntryReader::HandleReadError(const Status& s, EntryHeaderStatus status_detail) const {
if (!s.IsCorruption()) {
// IO errors should always propagate back
return s.CloneAndPrepend(Substitute("error reading from log $0", seg_->path_));
}
-
Status corruption_status = MakeCorruptionStatus(s);
// If we have a valid footer in the segment, then the segment was correctly
@@ -216,11 +216,20 @@ Status LogEntryReader::HandleReadError(const Status& s) const {
return corruption_status;
}
- LOG(INFO) << "Ignoring log segment corruption in " << seg_->path_ << " because "
- << "there are no log entries following the corrupted one. "
- << "The server probably crashed in the middle of writing an entry "
- << "to the write-ahead log or downloaded an active log via tablet copy. "
- << "Error detail: " << corruption_status.ToString();
+ CHECK(status_detail != EntryHeaderStatus::OK);
+ if (status_detail == EntryHeaderStatus::ALL_ZEROS) {
+ // In the common case of hitting the end of valid entries, we'll read a header which
+ // is all zero bytes, and find no more entries following it. This isn't really a
+ // "Corruption" so much as an expected EOF-type condition, so we'll just log
+ // at VLOG(1) instead of INFO.
+ VLOG(1) << "Reached preallocated space while reading log segment " << seg_->path_;
+ } else {
+ LOG(INFO) << "Ignoring log segment corruption in " << seg_->path_ << " because "
+ << "there are no log entries following the corrupted one. "
+ << "The server probably crashed in the middle of writing an entry "
+ << "to the write-ahead log or downloaded an active log via tablet copy. "
+ << "Error detail: " << corruption_status.ToString();
+ }
return Status::EndOfFile("");
}
@@ -318,8 +327,8 @@ Status ReadableLogSegment::Init() {
Status s = ReadFooter();
if (!s.ok()) {
if (s.IsNotFound()) {
- LOG(INFO) << "Log segment " << path_ << " has no footer. This segment was likely "
- << "being written when the server previously shut down.";
+ VLOG(1) << "Log segment " << path_ << " has no footer. This segment was likely "
+ << "being written when the server previously shut down.";
} else {
LOG(WARNING) << "Could not read footer for segment: " << path_
<< ": " << s.ToString();
@@ -380,8 +389,8 @@ Status ReadableLogSegment::RebuildFooterByScanning() {
footer_was_rebuilt_ = true;
readable_to_offset_.Store(reader.offset());
- LOG(INFO) << "Successfully rebuilt footer for segment: " << path_
- << " (valid entries through byte offset " << reader.offset() << ")";
+ VLOG(1) << "Successfully rebuilt footer for segment: " << path_
+ << " (valid entries through byte offset " << reader.offset() << ")";
return Status::OK();
}
@@ -586,8 +595,8 @@ size_t ReadableLogSegment::entry_header_size() const {
Status ReadableLogSegment::ScanForValidEntryHeaders(int64_t offset, bool* has_valid_entries) {
TRACE_EVENT1("log", "ReadableLogSegment::ScanForValidEntryHeaders",
"path", path_);
- LOG(INFO) << "Scanning " << path_ << " for valid entry headers "
- << "following offset " << offset << "...";
+ VLOG(1) << "Scanning " << path_ << " for valid entry headers "
+ << "following offset " << offset << "...";
*has_valid_entries = false;
const int kChunkSize = 1024 * 1024;
@@ -615,43 +624,62 @@ Status ReadableLogSegment::ScanForValidEntryHeaders(int64_t offset, bool* has_va
Slice potential_header = Slice(&chunk[off_in_chunk], entry_header_size());
EntryHeader header;
- if (DecodeEntryHeader(potential_header, &header)) {
- LOG(INFO) << "Found a valid entry header at offset " << (offset + off_in_chunk);
+ if (DecodeEntryHeader(potential_header, &header) == EntryHeaderStatus::OK) {
+ VLOG(1) << "Found a valid entry header at offset " << (offset + off_in_chunk);
*has_valid_entries = true;
return Status::OK();
}
}
}
- LOG(INFO) << "Found no log entry headers";
+ VLOG(1) << "Found no log entry headers";
return Status::OK();
}
Status ReadableLogSegment::ReadEntryHeaderAndBatch(int64_t* offset, faststring* tmp_buf,
- gscoped_ptr<LogEntryBatchPB>* batch) {
+ gscoped_ptr<LogEntryBatchPB>* batch,
+ EntryHeaderStatus* status_detail) {
int64_t cur_offset = *offset;
EntryHeader header;
- RETURN_NOT_OK(ReadEntryHeader(&cur_offset, &header));
- RETURN_NOT_OK(ReadEntryBatch(&cur_offset, header, tmp_buf, batch));
+ RETURN_NOT_OK(ReadEntryHeader(&cur_offset, &header, status_detail));
+ Status s = ReadEntryBatch(&cur_offset, header, tmp_buf, batch);
+ if (PREDICT_FALSE(!s.ok())) {
+ // If we failed to actually decode the batch, make sure to set status_detail to
+ // non-OK.
+ *status_detail = EntryHeaderStatus::OTHER_ERROR;
+ return s;
+ }
*offset = cur_offset;
return Status::OK();
}
-Status ReadableLogSegment::ReadEntryHeader(int64_t *offset, EntryHeader* header) {
+Status ReadableLogSegment::ReadEntryHeader(int64_t *offset, EntryHeader* header,
+ EntryHeaderStatus* status_detail) {
const size_t header_size = entry_header_size();
uint8_t scratch[header_size];
Slice slice(scratch, header_size);
RETURN_NOT_OK_PREPEND(readable_file()->Read(*offset, &slice),
"Could not read log entry header");
- if (PREDICT_FALSE(!DecodeEntryHeader(slice, header))) {
- return Status::Corruption("CRC mismatch in log entry header");
+ *status_detail = DecodeEntryHeader(slice, header);
+ switch (*status_detail) {
+ case EntryHeaderStatus::CRC_MISMATCH:
+ return Status::Corruption("CRC mismatch in log entry header");
+ case EntryHeaderStatus::ALL_ZEROS:
+ return Status::Corruption("preallocated space found");
+ case EntryHeaderStatus::OK:
+ break;
+ default:
+ LOG(FATAL) << "unexpected result from decoding";
+ return Status::Corruption("unexpected result from decoded");
}
+
*offset += slice.size();
return Status::OK();
}
-bool ReadableLogSegment::DecodeEntryHeader(const Slice& data, EntryHeader* header) {
+EntryHeaderStatus ReadableLogSegment::DecodeEntryHeader(
+ const Slice& data, EntryHeader* header) {
uint32_t computed_header_crc;
if (entry_header_size() == kEntryHeaderSizeV2) {
header->msg_length_compressed = DecodeFixed32(&data[0]);
@@ -669,7 +697,13 @@ bool ReadableLogSegment::DecodeEntryHeader(const Slice& data, EntryHeader* heade
}
// Verify the header.
- return computed_header_crc == header->header_crc;
+ if (computed_header_crc == header->header_crc) {
+ return EntryHeaderStatus::OK;
+ }
+ if (IsAllZeros(data)) {
+ return EntryHeaderStatus::ALL_ZEROS;
+ }
+ return EntryHeaderStatus::CRC_MISMATCH;
}
http://git-wip-us.apache.org/repos/asf/kudu/blob/733afeb8/src/kudu/consensus/log_util.h
----------------------------------------------------------------------
diff --git a/src/kudu/consensus/log_util.h b/src/kudu/consensus/log_util.h
index c52e89b..eb254a8 100644
--- a/src/kudu/consensus/log_util.h
+++ b/src/kudu/consensus/log_util.h
@@ -72,10 +72,25 @@ struct LogOptions {
LogOptions();
};
-
// A sequence of segments, ordered by increasing sequence number.
typedef std::vector<scoped_refptr<ReadableLogSegment> > SegmentSequence;
+// Detailed error codes when decoding entry headers. Used for more fine-grained
+// error-handling.
+enum class EntryHeaderStatus {
+ OK,
+
+ // The entry was just a run of zeros. It's likely we are trying to
+ // read from pre-allocated space.
+ ALL_ZEROS,
+
+ // The entry checksum didn't match the expected value.
+ CRC_MISMATCH,
+
+ // Some other error occurred (eg an IO error while reading)
+ OTHER_ERROR
+};
+
// LogEntryReader provides iterator-style access to read the entries
// from an open log segment.
class LogEntryReader {
@@ -106,7 +121,7 @@ class LogEntryReader {
friend class ReadableLogSegment;
// Handle an error reading an entry.
- Status HandleReadError(const Status& s) const;
+ Status HandleReadError(const Status& s, EntryHeaderStatus status_detail) const;
// Format a nice error message to report on a corruption in a log file.
Status MakeCorruptionStatus(const Status& status) const;
@@ -314,22 +329,28 @@ class ReadableLogSegment : public RefCountedThreadSafe<ReadableLogSegment> {
// Read an entry header and its associated batch at the given offset.
// If successful, updates '*offset' to point to the next batch
- // in the file. If unsuccessful, '*offset' is not updated.
+ // in the file.
+ //
+ // If unsuccessful, '*offset' is not updated, and *status_detail will be updated
+ // to indicate the cause of the error.
Status ReadEntryHeaderAndBatch(int64_t* offset, faststring* tmp_buf,
- gscoped_ptr<LogEntryBatchPB>* batch);
+ gscoped_ptr<LogEntryBatchPB>* batch,
+ EntryHeaderStatus* status_detail);
// Reads a log entry header from the segment.
- // Also increments the passed offset* by the length of the entry.
- Status ReadEntryHeader(int64_t *offset, EntryHeader* header);
+ //
+ // Also increments the passed offset* by the length of the entry on successful
+ // read.
+ Status ReadEntryHeader(int64_t *offset, EntryHeader* header,
+ EntryHeaderStatus* status_detail);
// Decode a log entry header from the given slice. The header length is
// determined by 'entry_header_size()'.
// Returns true if successful, false if corrupt.
//
// NOTE: this is performance-critical since it is used by ScanForValidEntryHeaders
- // and thus returns bool instead of Status.
- bool DecodeEntryHeader(const Slice& data, EntryHeader* header);
-
+ // and thus returns an enum instead of Status.
+ EntryHeaderStatus DecodeEntryHeader(const Slice& data, EntryHeader* header);
// Reads a log entry batch from the provided readable segment, which gets decoded
// into 'entry_batch' and increments 'offset' by the batch's length.
http://git-wip-us.apache.org/repos/asf/kudu/blob/733afeb8/src/kudu/tablet/tablet.cc
----------------------------------------------------------------------
diff --git a/src/kudu/tablet/tablet.cc b/src/kudu/tablet/tablet.cc
index ee173fd..f5c1fb1 100644
--- a/src/kudu/tablet/tablet.cc
+++ b/src/kudu/tablet/tablet.cc
@@ -1116,7 +1116,7 @@ Status Tablet::RewindSchemaForBootstrap(const Schema& new_schema,
// rewind the schema before replaying any operations. So, we just
// swap in a new one with the correct schema, rather than attempting
// to flush.
- LOG_WITH_PREFIX(INFO) << "Rewinding schema during bootstrap to " << new_schema.ToString();
+ VLOG_WITH_PREFIX(1) << "Rewinding schema during bootstrap to " << new_schema.ToString();
metadata_->SetSchema(new_schema, schema_version);
{
http://git-wip-us.apache.org/repos/asf/kudu/blob/733afeb8/src/kudu/tablet/tablet_bootstrap-test.cc
----------------------------------------------------------------------
diff --git a/src/kudu/tablet/tablet_bootstrap-test.cc b/src/kudu/tablet/tablet_bootstrap-test.cc
index 0d9e508..49c3c04 100644
--- a/src/kudu/tablet/tablet_bootstrap-test.cc
+++ b/src/kudu/tablet/tablet_bootstrap-test.cc
@@ -28,6 +28,7 @@
#include "kudu/consensus/metadata.pb.h"
#include "kudu/consensus/opid_util.h"
#include "kudu/server/logical_clock.h"
+#include "kudu/util/logging_test_util.h"
#include "kudu/tablet/tablet_bootstrap.h"
#include "kudu/tablet/tablet-test-util.h"
#include "kudu/tablet/tablet_metadata.h"
@@ -164,7 +165,17 @@ TEST_F(BootstrapTest, TestBootstrap) {
shared_ptr<Tablet> tablet;
ConsensusBootstrapInfo boot_info;
- ASSERT_OK(BootstrapTestTablet(-1, -1, &tablet, &boot_info));
+ StringVectorSink capture_logs;
+ {
+ // Capture the log messages during bootstrap.
+ ScopedRegisterSink reg(&capture_logs);
+ ASSERT_OK(BootstrapTestTablet(-1, -1, &tablet, &boot_info));
+ }
+
+ // Make sure we don't see anything in the logs that would make a user scared.
+ for (const string& s : capture_logs.logged_msgs()) {
+ ASSERT_STR_NOT_MATCHES(s, "[cC]orrupt");
+ }
vector<string> results;
IterateTabletRows(tablet.get(), &results);
http://git-wip-us.apache.org/repos/asf/kudu/blob/733afeb8/src/kudu/tablet/tablet_bootstrap.cc
----------------------------------------------------------------------
diff --git a/src/kudu/tablet/tablet_bootstrap.cc b/src/kudu/tablet/tablet_bootstrap.cc
index c9150d2..c5b8bd1 100644
--- a/src/kudu/tablet/tablet_bootstrap.cc
+++ b/src/kudu/tablet/tablet_bootstrap.cc
@@ -584,7 +584,8 @@ Status TabletBootstrap::OpenTablet(bool* has_blocks) {
metric_registry_,
log_anchor_registry_));
// doing nothing for now except opening a tablet locally.
- LOG_TIMING_PREFIX(INFO, LogPrefix(), "opening tablet") {
+ {
+ SCOPED_LOG_SLOW_EXECUTION_PREFIX(INFO, 100, LogPrefix(), "opening tablet");
RETURN_NOT_OK(tablet->Open());
}
*has_blocks = tablet->num_rowsets() != 0;
@@ -640,16 +641,16 @@ Status TabletBootstrap::PrepareRecoveryDir(bool* needs_recovery) {
string source_path = JoinPathSegments(log_dir, child);
string dest_path = JoinPathSegments(recovery_path, child);
- LOG_WITH_PREFIX(INFO) << "Will attempt to recover log segment " << source_path
- << " to " << dest_path;
+ VLOG_WITH_PREFIX(1) << "Will attempt to recover log segment " << source_path
+ << " to " << dest_path;
*needs_recovery = true;
}
if (*needs_recovery) {
// Atomically rename the log directory to the recovery directory
// and then re-create the log directory.
- LOG_WITH_PREFIX(INFO) << "Moving log directory " << log_dir << " to recovery directory "
- << recovery_path << " in preparation for log replay";
+ VLOG_WITH_PREFIX(1) << "Moving log directory " << log_dir << " to recovery directory "
+ << recovery_path << " in preparation for log replay";
RETURN_NOT_OK_PREPEND(fs_manager->env()->RenameFile(log_dir, recovery_path),
Substitute("Could not move log directory $0 to recovery dir $1",
log_dir, recovery_path));
@@ -677,10 +678,10 @@ Status TabletBootstrap::RemoveRecoveryDir() {
CHECK(fs_manager->Exists(recovery_path))
<< "Tablet WAL recovery dir " << recovery_path << " does not exist.";
- LOG_WITH_PREFIX(INFO) << "Preparing to delete log recovery files and directory " << recovery_path;
+ VLOG_WITH_PREFIX(1) << "Preparing to delete log recovery files and directory " << recovery_path;
string tmp_path = Substitute("$0-$1", recovery_path, GetCurrentTimeMicros());
- LOG_WITH_PREFIX(INFO) << "Renaming log recovery dir from " << recovery_path
+ VLOG_WITH_PREFIX(1) << "Renaming log recovery dir from " << recovery_path
<< " to " << tmp_path;
RETURN_NOT_OK_PREPEND(fs_manager->env()->RenameFile(recovery_path, tmp_path),
Substitute("Could not rename old recovery dir from: $0 to: $1",
@@ -690,10 +691,10 @@ Status TabletBootstrap::RemoveRecoveryDir() {
LOG_WITH_PREFIX(INFO) << "--skip_remove_old_recovery_dir enabled. NOT deleting " << tmp_path;
return Status::OK();
}
- LOG_WITH_PREFIX(INFO) << "Deleting all files from renamed log recovery directory " << tmp_path;
+ VLOG_WITH_PREFIX(1) << "Deleting all files from renamed log recovery directory " << tmp_path;
RETURN_NOT_OK_PREPEND(fs_manager->env()->DeleteRecursively(tmp_path),
"Could not remove renamed recovery dir " + tmp_path);
- LOG_WITH_PREFIX(INFO) << "Completed deletion of old log recovery files and directory "
+ VLOG_WITH_PREFIX(1) << "Completed deletion of old log recovery files and directory "
<< tmp_path;
return Status::OK();
}
@@ -1236,7 +1237,9 @@ Status TabletBootstrap::PlaySegments(ConsensusBootstrapInfo* consensus_info) {
// no later committed replicate message (with index > Y) is visible across reboots
// in the tablet data.
- DumpReplayStateToLog(state);
+ if (VLOG_IS_ON(1)) {
+ DumpReplayStateToLog(state);
+ }
// Set up the ConsensusBootstrapInfo structure for the caller.
for (OpIndexToEntryMap::value_type& e : state.pending_replicates) {
http://git-wip-us.apache.org/repos/asf/kudu/blob/733afeb8/src/kudu/tserver/ts_tablet_manager.cc
----------------------------------------------------------------------
diff --git a/src/kudu/tserver/ts_tablet_manager.cc b/src/kudu/tserver/ts_tablet_manager.cc
index 861cd8a..e6931eb 100644
--- a/src/kudu/tserver/ts_tablet_manager.cc
+++ b/src/kudu/tserver/ts_tablet_manager.cc
@@ -206,16 +206,21 @@ Status TSTabletManager::Init() {
// First, load all of the tablet metadata. We do this before we start
// submitting the actual OpenTablet() tasks so that we don't have to compete
// for disk resources, etc, with bootstrap processes and running tablets.
+ int loaded_count = 0;
for (const string& tablet_id : tablet_ids) {
+ KLOG_EVERY_N_SECS(INFO, 1) << Substitute("Loading tablet metadata ($0/$1 complete)",
+ loaded_count, tablet_ids.size());
scoped_refptr<TabletMetadata> meta;
RETURN_NOT_OK_PREPEND(OpenTabletMeta(tablet_id, &meta),
"Failed to open tablet metadata for tablet: " + tablet_id);
+ loaded_count++;
if (PREDICT_FALSE(meta->tablet_data_state() != TABLET_DATA_READY)) {
RETURN_NOT_OK(HandleNonReadyTabletOnStartup(meta));
continue;
}
metas.push_back(meta);
}
+ LOG(INFO) << Substitute("Loaded tablet metadata ($0 live tablets)", metas.size());
// Now submit the "Open" task for each.
for (const scoped_refptr<TabletMetadata>& meta : metas) {