kudu-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From aw...@apache.org
Subject [2/3] kudu git commit: [tablet] Improve logging of maintenance ops
Date Tue, 04 Sep 2018 17:05:19 GMT
[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 <aserbin@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 <wdberkeley@gmail.org>
Authored: Thu Aug 30 11:59:14 2018 -0700
Committer: Will Berkeley <wdberkeley@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(),


Mime
View raw message