You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@kudu.apache.org by aw...@apache.org on 2018/09/04 17:05:19 UTC
[2/3] kudu git commit: [tablet] Improve logging of maintenance ops
[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 <as...@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 <wd...@gmail.org>
Authored: Thu Aug 30 11:59:14 2018 -0700
Committer: Will Berkeley <wd...@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(),