Repository: mesos Updated Branches: refs/heads/master 58a1bd139 -> 74e959848
Reduced logging verbosity for replicated log operations. Logging the duration required for each storage operation at `INFO` level is overkill for most people consuming the log. Review: https://reviews.apache.org/r/50301/ Project: http://git-wip-us.apache.org/repos/asf/mesos/repo Commit: http://git-wip-us.apache.org/repos/asf/mesos/commit/9eea27c5 Tree: http://git-wip-us.apache.org/repos/asf/mesos/tree/9eea27c5 Diff: http://git-wip-us.apache.org/repos/asf/mesos/diff/9eea27c5 Branch: refs/heads/master Commit: 9eea27c56db736d2409380f0eaeaecbd1eb1784d Parents: 58a1bd1 Author: Neil Conway <neil.con...@gmail.com> Authored: Tue Aug 2 09:36:02 2016 -0700 Committer: Anand Mazumdar <an...@apache.org> Committed: Tue Aug 2 09:36:02 2016 -0700 ---------------------------------------------------------------------- src/log/leveldb.cpp | 26 +++++++++++++------------- src/log/log.cpp | 4 ++-- src/log/recover.cpp | 2 +- src/log/replica.cpp | 9 +++------ src/master/registrar.cpp | 6 +++--- 5 files changed, 22 insertions(+), 25 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/mesos/blob/9eea27c5/src/log/leveldb.cpp ---------------------------------------------------------------------- diff --git a/src/log/leveldb.cpp b/src/log/leveldb.cpp index f389d74..5310a12 100644 --- a/src/log/leveldb.cpp +++ b/src/log/leveldb.cpp @@ -171,14 +171,14 @@ Try<Storage::State> LevelDBStorage::restore(const string& path) return Error(status.ToString()); } - LOG(INFO) << "Opened db in " << stopwatch.elapsed(); + VLOG(1) << "Opened db in " << stopwatch.elapsed(); stopwatch.start(); // Restart the stopwatch. // TODO(benh): Conditionally compact to avoid long recovery times? db->CompactRange(nullptr, nullptr); - LOG(INFO) << "Compacted db in " << stopwatch.elapsed(); + VLOG(1) << "Compacted db in " << stopwatch.elapsed(); State state; state.begin = 0; @@ -193,13 +193,13 @@ Try<Storage::State> LevelDBStorage::restore(const string& path) leveldb::Iterator* iterator = db->NewIterator(leveldb::ReadOptions()); - LOG(INFO) << "Created db iterator in " << stopwatch.elapsed(); + VLOG(1) << "Created db iterator in " << stopwatch.elapsed(); stopwatch.start(); // Restart the stopwatch. iterator->SeekToFirst(); - LOG(INFO) << "Seeked to beginning of db in " << stopwatch.elapsed(); + VLOG(1) << "Seeked to beginning of db in " << stopwatch.elapsed(); stopwatch.start(); // Restart the stopwatch. @@ -268,8 +268,8 @@ Try<Storage::State> LevelDBStorage::restore(const string& path) iterator->Next(); } - LOG(INFO) << "Iterated through " << keys - << " keys in the db in " << stopwatch.elapsed(); + VLOG(1) << "Iterated through " << keys + << " keys in the db in " << stopwatch.elapsed(); delete iterator; @@ -301,8 +301,8 @@ Try<Nothing> LevelDBStorage::persist(const Metadata& metadata) return Error(status.ToString()); } - LOG(INFO) << "Persisting metadata (" << value.size() - << " bytes) to leveldb took " << stopwatch.elapsed(); + VLOG(1) << "Persisting metadata (" << value.size() + << " bytes) to leveldb took " << stopwatch.elapsed(); return Nothing(); } @@ -338,8 +338,8 @@ Try<Nothing> LevelDBStorage::persist(const Action& action) // catch-up policy is used). first = min(first, action.position()); - LOG(INFO) << "Persisting action (" << value.size() - << " bytes) to leveldb took " << stopwatch.elapsed(); + VLOG(1) << "Persisting action (" << value.size() + << " bytes) to leveldb took " << stopwatch.elapsed(); // Delete positions if a truncate action has been *learned*. Note // that we do this in a best-effort fashion (i.e., we ignore any @@ -396,8 +396,8 @@ Try<Nothing> LevelDBStorage::persist(const Action& action) CHECK_LT(first.get(), action.truncate().to()); first = action.truncate().to(); - LOG(INFO) << "Deleting ~" << index - << " keys from leveldb took " << stopwatch.elapsed(); + VLOG(1) << "Deleting ~" << index + << " keys from leveldb took " << stopwatch.elapsed(); } } } @@ -433,7 +433,7 @@ Try<Action> LevelDBStorage::read(uint64_t position) return Error("Bad record"); } - LOG(INFO) << "Reading position from leveldb took " << stopwatch.elapsed(); + VLOG(1) << "Reading position from leveldb took " << stopwatch.elapsed(); return record.action(); } http://git-wip-us.apache.org/repos/asf/mesos/blob/9eea27c5/src/log/log.cpp ---------------------------------------------------------------------- diff --git a/src/log/log.cpp b/src/log/log.cpp index f8e439f..0940f92 100644 --- a/src/log/log.cpp +++ b/src/log/log.cpp @@ -574,7 +574,7 @@ Option<Log::Position> LogWriterProcess::__start( Future<Option<Log::Position> > LogWriterProcess::append(const string& bytes) { - LOG(INFO) << "Attempting to append " << bytes.size() << " bytes to the log"; + VLOG(1) << "Attempting to append " << bytes.size() << " bytes to the log"; if (coordinator == nullptr) { return Failure("No election has been performed"); @@ -593,7 +593,7 @@ Future<Option<Log::Position> > LogWriterProcess::append(const string& bytes) Future<Option<Log::Position> > LogWriterProcess::truncate( const Log::Position& to) { - LOG(INFO) << "Attempting to truncate the log to " << to.value; + VLOG(1) << "Attempting to truncate the log to " << to.value; if (coordinator == nullptr) { return Failure("No election has been performed"); http://git-wip-us.apache.org/repos/asf/mesos/blob/9eea27c5/src/log/recover.cpp ---------------------------------------------------------------------- diff --git a/src/log/recover.cpp b/src/log/recover.cpp index 69b5b28..eaf3fd3 100644 --- a/src/log/recover.cpp +++ b/src/log/recover.cpp @@ -463,7 +463,7 @@ protected: virtual void finalize() { - LOG(INFO) << "Recover process terminated"; + VLOG(1) << "Recover process terminated"; } private: http://git-wip-us.apache.org/repos/asf/mesos/blob/9eea27c5/src/log/replica.cpp ---------------------------------------------------------------------- diff --git a/src/log/replica.cpp b/src/log/replica.cpp index 45b7717..5ab7b3d 100644 --- a/src/log/replica.cpp +++ b/src/log/replica.cpp @@ -692,11 +692,7 @@ void ReplicaProcess::learned(const UPID& from, const Action& action) << action.position() << " from " << from; CHECK(action.learned()); - - if (persist(action)) { - LOG(INFO) << "Replica learned " << action.type() - << " action at position " << action.position(); - } + persist(action); } @@ -709,7 +705,8 @@ bool ReplicaProcess::persist(const Action& action) return false; } - LOG(INFO) << "Persisted action at " << action.position(); + VLOG(1) << "Persisted action " << action.type() + << " at position " << action.position(); // No longer a hole here (if there even was one). holes -= action.position(); http://git-wip-us.apache.org/repos/asf/mesos/blob/9eea27c5/src/master/registrar.cpp ---------------------------------------------------------------------- diff --git a/src/master/registrar.cpp b/src/master/registrar.cpp index 9d2f558..4589d2f 100644 --- a/src/master/registrar.cpp +++ b/src/master/registrar.cpp @@ -462,7 +462,7 @@ void RegistrarProcess::update() } LOG(INFO) << "Applied " << operations.size() << " operations in " - << stopwatch.elapsed() << "; attempting to update the 'registry'"; + << stopwatch.elapsed() << "; attempting to update the registry"; // Perform the store, and time the operation. metrics.state_store.start(); @@ -488,7 +488,7 @@ void RegistrarProcess::_update( // Abort if the storage operation did not succeed. if (!store.isReady() || store.get().isNone()) { - string message = "Failed to update 'registry': "; + string message = "Failed to update registry: "; if (store.isFailed()) { message += store.failure(); @@ -506,7 +506,7 @@ void RegistrarProcess::_update( Duration elapsed = metrics.state_store.stop(); - LOG(INFO) << "Successfully updated the 'registry' in " << elapsed; + LOG(INFO) << "Successfully updated the registry in " << elapsed; variable = store.get().get();
