[tablet] Improve logging of maintenance ops MRS flushes and rowset compactions =================================
MRS flush and rowset compaction logging now includes the number of new rowsets flushed. Before: I0830 14:54:24.353442 2830984064 tablet.cc:1651] T test_tablet_id P 78c16245dcd84048bf66debf1958c169: Flush successful on 100 rows (9272 bytes) I0830 14:58:23.309068 2830984064 tablet.cc:1651] T test_tablet_id P 15853c32ec1d4f70b82aef90da2108a6: Compaction successful on 30 rows (4957 bytes) After: I0830 14:54:24.353442 2830984064 tablet.cc:1651] T test_tablet_id P 78c16245dcd84048bf66debf1958c169: Flush successful on 100 rows (1 rowsets, 9272 bytes) I0830 14:58:23.309068 2830984064 tablet.cc:1651] T test_tablet_id P 15853c32ec1d4f70b82aef90da2108a6: Compaction successful on 30 rows (1 rowsets, 4957 bytes) Major delta compactions ======================= Major delta compaction had logging that was a little too verbose- for each delta store compacted, it printed out a separate log message with mutation counts. Instead, this patch makes the old more detailed output appear only when verbose logging is on and at INFO level substitutes a total count of each mutation type and a count of delta files compacted, as part of the "Finished" message. Before: I0830 15:22:05.918965 2830984064 delta_compaction.cc:296] Starting major delta compaction for columns val1[int32 NOT NULL] val3[int32 NOT NULL] val4[string NOT NULL] I0830 15:22:05.919018 2830984064 delta_compaction.cc:300] Preparing to major compact delta file: 0145461451762035 (ts range=[101, 150], delete_count=[0], reinsert_count=[0], update_counts_by_col_id=[11:50,13:50,14:50]) I0830 15:22:05.919056 2830984064 delta_compaction.cc:300] Preparing to major compact delta file: 0145461451762036 (ts range=[151, 200], delete_count=[0], reinsert_count=[0], update_counts_by_col_id=[11:50,13:50,14:50]) I0830 15:22:05.921931 2830984064 delta_compaction.cc:306] Finished major delta compaction of columns val1[int32 NOT NULL] val3[int32 NOT NULL] val4[string NOT NULL] After: I0830 15:28:02.737797 2830984064 delta_compaction.cc:326] Starting major delta compaction for columns val1[int32 NOT NULL], val3[int32 NOT NULL], val4[string NOT NULL] I0830 15:28:02.740360 2830984064 delta_compaction.cc:341] Finished major delta compaction of columns val1[int32 NOT NULL], val3[int32 NOT NULL], val4[string NOT NULL]. Compacted 2 delta files. Overall stats: delete_count=0, reinsert_count=0, update_count=300 Minor delta compaction ====================== Now includes the number of stores compacted. I didn't see a test that does minor delta compaction that I could pull bafe/after examples from. Change-Id: I43883001c5a1c72ff1ca0c1bc84d24a8533e3891 Reviewed-on: http://gerrit.cloudera.org:8080/11367 Reviewed-by: Alexey Serbin <aser...@cloudera.com> Tested-by: Kudu Jenkins Project: http://git-wip-us.apache.org/repos/asf/kudu/repo Commit: http://git-wip-us.apache.org/repos/asf/kudu/commit/1da6501e Tree: http://git-wip-us.apache.org/repos/asf/kudu/tree/1da6501e Diff: http://git-wip-us.apache.org/repos/asf/kudu/diff/1da6501e Branch: refs/heads/master Commit: 1da6501e4d1686c2a96e119094aa419d3aecc8db Parents: 4e7f0da Author: Will Berkeley <wdberke...@gmail.org> Authored: Thu Aug 30 11:59:14 2018 -0700 Committer: Will Berkeley <wdberke...@gmail.com> Committed: Fri Aug 31 18:44:49 2018 +0000 ---------------------------------------------------------------------- src/kudu/tablet/delta_compaction.cc | 44 ++++++++++++++++++++++++++------ src/kudu/tablet/delta_stats.cc | 8 ++++++ src/kudu/tablet/delta_stats.h | 3 +++ src/kudu/tablet/delta_tracker.cc | 8 +++--- src/kudu/tablet/diskrowset.h | 4 ++- src/kudu/tablet/tablet.cc | 15 ++++++----- 6 files changed, 64 insertions(+), 18 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/kudu/blob/1da6501e/src/kudu/tablet/delta_compaction.cc ---------------------------------------------------------------------- diff --git a/src/kudu/tablet/delta_compaction.cc b/src/kudu/tablet/delta_compaction.cc index d41f565..ff2e071 100644 --- a/src/kudu/tablet/delta_compaction.cc +++ b/src/kudu/tablet/delta_compaction.cc @@ -17,6 +17,7 @@ #include "kudu/tablet/delta_compaction.h" +#include <cstdint> #include <map> #include <ostream> #include <string> @@ -36,6 +37,7 @@ #include "kudu/fs/fs_manager.h" #include "kudu/gutil/casts.h" #include "kudu/gutil/map-util.h" +#include "kudu/gutil/strings/join.h" #include "kudu/gutil/strings/substitute.h" #include "kudu/tablet/cfile_set.h" #include "kudu/tablet/compaction.h" @@ -98,16 +100,17 @@ MajorDeltaCompaction::~MajorDeltaCompaction() { } string MajorDeltaCompaction::ColumnNamesToString() const { - std::string result; + vector<string> col_names; + col_names.reserve(column_ids_.size()); for (ColumnId col_id : column_ids_) { int col_idx = base_schema_.find_column_by_id(col_id); if (col_idx != Schema::kColumnNotFound) { - result += base_schema_.column_by_id(col_id).ToString() + " "; + col_names.push_back(base_schema_.column_by_id(col_id).ToString()); } else { - result += Substitute("[deleted column id $0] ", col_id); + col_names.push_back(Substitute("[deleted column id $0]", col_id)); } } - return result; + return JoinStrings(col_names, ", "); } Status MajorDeltaCompaction::FlushRowSetAndDeltas(const IOContext* io_context) { @@ -290,21 +293,46 @@ Status MajorDeltaCompaction::OpenUndoDeltaFileWriter() { return new_undo_delta_writer_->Start(); } +namespace { +string DeltaStoreStatsToString(const vector<shared_ptr<DeltaStore>>& stores) { + uint64_t delete_count = 0; + uint64_t reinsert_count = 0; + uint64_t update_count = 0; + for (const auto& store : stores) { + if (!store->Initted()) { + continue; + } + const auto& stats = store->delta_stats(); + delete_count += stats.delete_count(); + reinsert_count += stats.reinsert_count(); + update_count += stats.UpdateCount(); + } + return Substitute("delete_count=$0, reinsert_count=$1, update_count=$2", + delete_count, reinsert_count, update_count); +} +} // anonymous namespace + Status MajorDeltaCompaction::Compact(const IOContext* io_context) { CHECK_EQ(state_, kInitialized); LOG(INFO) << "Starting major delta compaction for columns " << ColumnNamesToString(); RETURN_NOT_OK(base_schema_.CreateProjectionByIdsIgnoreMissing(column_ids_, &partial_schema_)); - for (const shared_ptr<DeltaStore>& ds : included_stores_) { - LOG(INFO) << "Preparing to major compact delta file: " << ds->ToString(); + if (VLOG_IS_ON(1)) { + for (const auto& ds : included_stores_) { + VLOG(1) << "Preparing to major compact delta file: " << ds->ToString(); + } } // We defer calling OpenRedoDeltaFileWriter() since we might not need to flush. RETURN_NOT_OK(OpenBaseDataWriter()); RETURN_NOT_OK(FlushRowSetAndDeltas(io_context)); - LOG(INFO) << "Finished major delta compaction of columns " << - ColumnNamesToString(); + + LOG(INFO) << Substitute("Finished major delta compaction of columns $0. " + "Compacted $1 delta files. Overall stats: $2", + ColumnNamesToString(), + included_stores_.size(), + DeltaStoreStatsToString(included_stores_)); return Status::OK(); } http://git-wip-us.apache.org/repos/asf/kudu/blob/1da6501e/src/kudu/tablet/delta_stats.cc ---------------------------------------------------------------------- diff --git a/src/kudu/tablet/delta_stats.cc b/src/kudu/tablet/delta_stats.cc index 9436dd7..3a21dc9 100644 --- a/src/kudu/tablet/delta_stats.cc +++ b/src/kudu/tablet/delta_stats.cc @@ -94,6 +94,14 @@ Status DeltaStats::UpdateStats(const Timestamp& timestamp, return Status::OK(); } +int64_t DeltaStats::UpdateCount() const { + int64_t ret = 0; + for (const auto& entry : update_counts_by_col_id_) { + ret += entry.second; + } + return ret; +} + string DeltaStats::ToString() const { return strings::Substitute( "ts range=[$0, $1], delete_count=[$2], reinsert_count=[$3], update_counts_by_col_id=[$4]", http://git-wip-us.apache.org/repos/asf/kudu/blob/1da6501e/src/kudu/tablet/delta_stats.h ---------------------------------------------------------------------- diff --git a/src/kudu/tablet/delta_stats.h b/src/kudu/tablet/delta_stats.h index 1d5a134..de7d255 100644 --- a/src/kudu/tablet/delta_stats.h +++ b/src/kudu/tablet/delta_stats.h @@ -85,6 +85,9 @@ class DeltaStats { min_timestamp_ = timestamp; } + // Returns the number of updates across all columns. + int64_t UpdateCount() const; + std::string ToString() const; // Convert this object to the protobuf which is stored in the DeltaFile footer. http://git-wip-us.apache.org/repos/asf/kudu/blob/1da6501e/src/kudu/tablet/delta_tracker.cc ---------------------------------------------------------------------- diff --git a/src/kudu/tablet/delta_tracker.cc b/src/kudu/tablet/delta_tracker.cc index 0e41203..b10465b 100644 --- a/src/kudu/tablet/delta_tracker.cc +++ b/src/kudu/tablet/delta_tracker.cc @@ -26,7 +26,6 @@ #include <boost/range/adaptor/reversed.hpp> #include <glog/logging.h> -#include <glog/stl_logging.h> #include "kudu/cfile/cfile_util.h" #include "kudu/common/iterator.h" @@ -405,8 +404,11 @@ Status DeltaTracker::CompactStores(const IOContext* io_context, int start_idx, i RowSetMetadataUpdate update; update.ReplaceRedoDeltaBlocks(compacted_blocks, new_blocks); - LOG_WITH_PREFIX(INFO) << "Flushing compaction of redo delta blocks { " << compacted_blocks - << " } into block " << new_block_id; + LOG_WITH_PREFIX(INFO) << Substitute("Flushing compaction of $0 redo delta " + "blocks { $1 } into block $2", + compacted_blocks.size(), + BlockId::JoinStrings(compacted_blocks), + new_block_id.ToString()); RETURN_NOT_OK_PREPEND(CommitDeltaStoreMetadataUpdate(update, compacted_stores, new_blocks, io_context, REDO, FLUSH_METADATA), "DeltaTracker: CompactStores: Unable to commit delta update"); http://git-wip-us.apache.org/repos/asf/kudu/blob/1da6501e/src/kudu/tablet/diskrowset.h ---------------------------------------------------------------------- diff --git a/src/kudu/tablet/diskrowset.h b/src/kudu/tablet/diskrowset.h index de2e7f6..977cc78 100644 --- a/src/kudu/tablet/diskrowset.h +++ b/src/kudu/tablet/diskrowset.h @@ -207,7 +207,7 @@ class RollingDiskRowSetWriter { Status Finish(); - int64_t written_count() const { return written_count_; } + int64_t rows_written_count() const { return written_count_; } const Schema &schema() const { return schema_; } @@ -217,6 +217,8 @@ class RollingDiskRowSetWriter { uint64_t written_size() const { return written_size_; } + int64_t drs_written_count() const { return written_drs_metas_.size(); } + private: Status RollWriter(); http://git-wip-us.apache.org/repos/asf/kudu/blob/1da6501e/src/kudu/tablet/tablet.cc ---------------------------------------------------------------------- diff --git a/src/kudu/tablet/tablet.cc b/src/kudu/tablet/tablet.cc index a480c4c..f3a5143 100644 --- a/src/kudu/tablet/tablet.cc +++ b/src/kudu/tablet/tablet.cc @@ -1482,10 +1482,10 @@ Status Tablet::DoMergeCompactionOrFlush(const RowSetsInCompaction &input, "PostWriteSnapshot hook failed"); } - // Though unlikely, it's possible that all of the input rows were actually - // GCed in this compaction. In that case, we don't actually want to reopen. - bool gced_all_input = drsw.written_count() == 0; - if (gced_all_input) { + // Though unlikely, it's possible that no rows were written because all of + // the input rows were GCed in this compaction. In that case, we don't + // actually want to reopen. + if (drsw.rows_written_count() == 0) { LOG_WITH_PREFIX(INFO) << op_name << " resulted in no output rows (all input rows " << "were GCed!) Removing all input rowsets."; return HandleEmptyCompactionOrFlush(input.rowsets(), mrs_being_flushed); @@ -1648,8 +1648,11 @@ Status Tablet::DoMergeCompactionOrFlush(const RowSetsInCompaction &input, // their metadata was written to disk. AtomicSwapRowSets({ inprogress_rowset }, new_disk_rowsets); - LOG_WITH_PREFIX(INFO) << op_name << " successful on " << drsw.written_count() - << " rows " << "(" << drsw.written_size() << " bytes)"; + LOG_WITH_PREFIX(INFO) << Substitute("$0 successful on $1 rows ($2 rowsets, $3 bytes)", + op_name, + drsw.rows_written_count(), + drsw.drs_written_count(), + drsw.written_size()); if (common_hooks_) { RETURN_NOT_OK_PREPEND(common_hooks_->PostSwapNewRowSet(),
