kudu-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From a...@apache.org
Subject [kudu] 03/08: Reduce MRS flush and rowset compaction logging
Date Wed, 23 Jan 2019 17:54:17 GMT
This is an automated email from the ASF dual-hosted git repository.

adar pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/kudu.git

commit 190404016ffb916f0e00bb254adfa68ae529aaed
Author: Will Berkeley <wdberkeley@gmail.org>
AuthorDate: Thu Jan 17 16:53:33 2019 -0800

    Reduce MRS flush and rowset compaction logging
    
    MRS flushes and rowset compaction (which share much of the same code)
    are both very verbose. Here's an example of a large rowset compaction:
    
    I0113 21:55:44.541332 67917 maintenance_manager.cc:302] P 0fe9d23b0e9c49f1af1b1095bfd395fb:
Scheduling CompactRowSetsOp(be6681dcfc7a41dca7268c71f7d9bd21): perf score=0.604064
    I0113 21:55:44.543792 63804 tablet.cc:1664] T be6681dcfc7a41dca7268c71f7d9bd21 P 0fe9d23b0e9c49f1af1b1095bfd395fb:
Compaction: stage 1 complete, picked 46 rowsets to compact or flush
    I0113 21:55:44.543824 63804 compaction.cc:914] Selected 46 rowsets to compact:
    I0113 21:55:44.543833 63804 compaction.cc:917] RowSet(50276)(current size on disk: ~9737
bytes)
    I0113 21:55:44.543840 63804 compaction.cc:917] RowSet(50277)(current size on disk: ~9229
bytes)
    I0113 21:55:44.543848 63804 compaction.cc:917] RowSet(50331)(current size on disk: ~9723
bytes)
    I0113 21:55:44.543854 63804 compaction.cc:917] RowSet(50333)(current size on disk: ~9226
bytes)
    I0113 21:55:44.543860 63804 compaction.cc:917] RowSet(50359)(current size on disk: ~9196
bytes)
    I0113 21:55:44.543866 63804 compaction.cc:917] RowSet(50360)(current size on disk: ~9815
bytes)
    I0113 21:55:44.543874 63804 compaction.cc:917] RowSet(50366)(current size on disk: ~9718
bytes)
    I0113 21:55:44.543885 63804 compaction.cc:917] RowSet(50367)(current size on disk: ~9184
bytes)
    I0113 21:55:44.543892 63804 compaction.cc:917] RowSet(50368)(current size on disk: ~9161
bytes)
    I0113 21:55:44.543898 63804 compaction.cc:917] RowSet(50407)(current size on disk: ~9184
bytes)
    I0113 21:55:44.543905 63804 compaction.cc:917] RowSet(50409)(current size on disk: ~9178
bytes)
    I0113 21:55:44.543910 63804 compaction.cc:917] RowSet(50410)(current size on disk: ~9165
bytes)
    I0113 21:55:44.543917 63804 compaction.cc:917] RowSet(50412)(current size on disk: ~9825
bytes)
    I0113 21:55:44.543923 63804 compaction.cc:917] RowSet(50413)(current size on disk: ~9162
bytes)
    I0113 21:55:44.543931 63804 compaction.cc:917] RowSet(50420)(current size on disk: ~9175
bytes)
    I0113 21:55:44.543942 63804 compaction.cc:917] RowSet(50421)(current size on disk: ~9821
bytes)
    I0113 21:55:44.543953 63804 compaction.cc:917] RowSet(50422)(current size on disk: ~9215
bytes)
    I0113 21:55:44.543962 63804 compaction.cc:917] RowSet(50424)(current size on disk: ~9234
bytes)
    I0113 21:55:44.543972 63804 compaction.cc:917] RowSet(50429)(current size on disk: ~9179
bytes)
    I0113 21:55:44.543982 63804 compaction.cc:917] RowSet(50430)(current size on disk: ~9209
bytes)
    I0113 21:55:44.543999 63804 compaction.cc:917] RowSet(50432)(current size on disk: ~9206
bytes)
    I0113 21:55:44.544008 63804 compaction.cc:917] RowSet(50433)(current size on disk: ~9194
bytes)
    I0113 21:55:44.544018 63804 compaction.cc:917] RowSet(50434)(current size on disk: ~9157
bytes)
    I0113 21:55:44.544026 63804 compaction.cc:917] RowSet(50435)(current size on disk: ~9201
bytes)
    I0113 21:55:44.544036 63804 compaction.cc:917] RowSet(50436)(current size on disk: ~9155
bytes)
    I0113 21:55:44.544044 63804 compaction.cc:917] RowSet(50461)(current size on disk: ~9260
bytes)
    I0113 21:55:44.544054 63804 compaction.cc:917] RowSet(50465)(current size on disk: ~9179
bytes)
    I0113 21:55:44.544064 63804 compaction.cc:917] RowSet(50468)(current size on disk: ~9263
bytes)
    I0113 21:55:44.544070 63804 compaction.cc:917] RowSet(50473)(current size on disk: ~9232
bytes)
    I0113 21:55:44.544077 63804 compaction.cc:917] RowSet(50500)(current size on disk: ~9228
bytes)
    I0113 21:55:44.544083 63804 compaction.cc:917] RowSet(50502)(current size on disk: ~9247
bytes)
    I0113 21:55:44.544092 63804 compaction.cc:917] RowSet(50527)(current size on disk: ~9250
bytes)
    I0113 21:55:44.544100 63804 compaction.cc:917] RowSet(50533)(current size on disk: ~9240
bytes)
    I0113 21:55:44.544109 63804 compaction.cc:917] RowSet(50540)(current size on disk: ~35746907
bytes)
    I0113 21:55:44.544121 63804 compaction.cc:917] RowSet(50541)(current size on disk: ~35630515
bytes)
    I0113 21:55:44.544131 63804 compaction.cc:917] RowSet(50542)(current size on disk: ~23027388
bytes)
    I0113 21:55:44.544142 63804 compaction.cc:917] RowSet(50545)(current size on disk: ~9911
bytes)
    I0113 21:55:44.544148 63804 compaction.cc:917] RowSet(50548)(current size on disk: ~9267
bytes)
    I0113 21:55:44.544158 63804 compaction.cc:917] RowSet(50549)(current size on disk: ~10061
bytes)
    I0113 21:55:44.544168 63804 compaction.cc:917] RowSet(50550)(current size on disk: ~9256
bytes)
    I0113 21:55:44.544174 63804 compaction.cc:917] RowSet(50559)(current size on disk: ~9847
bytes)
    I0113 21:55:44.544183 63804 compaction.cc:917] RowSet(50576)(current size on disk: ~9265
bytes)
    I0113 21:55:44.544189 63804 compaction.cc:917] RowSet(50587)(current size on disk: ~9856
bytes)
    I0113 21:55:44.544198 63804 compaction.cc:917] RowSet(50588)(current size on disk: ~10762
bytes)
    I0113 21:55:44.544206 63804 compaction.cc:917] RowSet(50589)(current size on disk: ~10064
bytes)
    I0113 21:55:44.544216 63804 compaction.cc:917] RowSet(50592)(current size on disk: ~10108
bytes)
    I0113 21:55:44.544230 63804 tablet.cc:1444] T be6681dcfc7a41dca7268c71f7d9bd21 P 0fe9d23b0e9c49f1af1b1095bfd395fb:
Compaction: entering phase 1 (flushing snapshot). Phase 1 snapshot: MvccSnapshot[committed={T|T
< 6338306555103207424 or (T in {6338306555103207424})}]
    I0113 21:55:44.548666 63804 multi_column_writer.cc:98] Opened CFile writers for 35 column(s)
    I0113 21:55:45.577991 63804 multi_column_writer.cc:98] Opened CFile writers for 35 column(s)
    I0113 21:55:46.560835 63804 multi_column_writer.cc:98] Opened CFile writers for 35 column(s)
    I0113 21:55:47.150137 63804 tablet.cc:1529] T be6681dcfc7a41dca7268c71f7d9bd21 P 0fe9d23b0e9c49f1af1b1095bfd395fb:
Compaction: entering phase 2 (starting to duplicate updates in new rowsets)
    I0113 21:55:47.151619 63804 tablet.cc:1584] T be6681dcfc7a41dca7268c71f7d9bd21 P 0fe9d23b0e9c49f1af1b1095bfd395fb:
Compaction Phase 2: carrying over any updates which arrived during Phase 1
    I0113 21:55:47.151638 63804 tablet.cc:1586] T be6681dcfc7a41dca7268c71f7d9bd21 P 0fe9d23b0e9c49f1af1b1095bfd395fb:
Phase 2 snapshot: MvccSnapshot[committed={T|T < 6338306555103207424 or (T in {6338306555103207424})}]
    I0113 21:55:47.625000 63804 tablet.cc:1634] T be6681dcfc7a41dca7268c71f7d9bd21 P 0fe9d23b0e9c49f1af1b1095bfd395fb:
Compaction successful on 1609240 rows (94320404 bytes)
    I0113 21:55:47.631129 63804 maintenance_manager.cc:492] P 0fe9d23b0e9c49f1af1b1095bfd395fb:
CompactRowSetsOp(be6681dcfc7a41dca7268c71f7d9bd21) complete. Timing: real 3.090s    user 2.770s
    sys 0.284s Metrics: {"cfile_cache_hit":2680,"cfile_cache_hit_bytes":8010765,"cfile_cache_miss":7724,"cfile_cache_miss_bytes":173275793,"cfile_init":1578,"data
dirs.queue_time_us":72960,"data dirs.run_cpu_time_us":2593,"data dirs.run_wall_time_us":3285,"delta_iterators_relevant":32,"fdatasync":83,
[...]
    
    Yikes. This patch moves the fluff in the middle to VLOG(1), and adds
    some trace metrics to provide useful information that's in the fluff.
    Namely,
    
    - bytes written
    - rows_written
    - number of input rowsets for a rowset compaction
    - number of output diskrowsets
    
    Here's how an MRS flush looks now:
    
    I0117 17:31:10.059830 200036352 maintenance_manager.cc:304] P 92c6463ad225421797bbb02aedbe6d8e:
Scheduling FlushMRSOp(dc75a0b793c44a52b40a642de6d0f260): perf score=0.033403
    I0117 17:31:10.067961 141012992 maintenance_manager.cc:494] P 92c6463ad225421797bbb02aedbe6d8e:
FlushMRSOp(dc75a0b793c44a52b40a642de6d0f260) complete. Timing: real 0.008s	user 0.005s	sys
0.003s Metrics: {"bytes_written":13462,"cfile_init":1,"drs_written":1,"fdatasync":6,"fdatasync_us":560,"rows_written":235,"thread_start_us":68,"threads_started":1,"wal-append.queue_time_us":115}
    
    Change-Id: Ie3123656cbdefe234c8cb6ec25994bace926932c
    Reviewed-on: http://gerrit.cloudera.org:8080/12234
    Tested-by: Will Berkeley <wdberkeley@gmail.com>
    Reviewed-by: Adar Dembo <adar@cloudera.com>
---
 src/kudu/tablet/compaction.cc          |  6 ++--
 src/kudu/tablet/multi_column_writer.cc |  4 ++-
 src/kudu/tablet/tablet.cc              | 52 +++++++++++++++++++++-------------
 3 files changed, 39 insertions(+), 23 deletions(-)

diff --git a/src/kudu/tablet/compaction.cc b/src/kudu/tablet/compaction.cc
index c05a258..e409d05 100644
--- a/src/kudu/tablet/compaction.cc
+++ b/src/kudu/tablet/compaction.cc
@@ -919,11 +919,11 @@ Status RowSetsInCompaction::CreateCompactionInput(const MvccSnapshot
&snap,
 }
 
 void RowSetsInCompaction::DumpToLog() const {
-  LOG(INFO) << "Selected " << rowsets_.size() << " rowsets to compact:";
+  VLOG(1) << "Selected " << rowsets_.size() << " rowsets to compact:";
   // Dump the selected rowsets to the log, and collect corresponding iterators.
   for (const shared_ptr<RowSet> &rs : rowsets_) {
-    LOG(INFO) << rs->ToString() << "(current size on disk: ~"
-              << rs->OnDiskSize() << " bytes)";
+    VLOG(1) << rs->ToString() << "(current size on disk: ~"
+            << rs->OnDiskSize() << " bytes)";
   }
 }
 
diff --git a/src/kudu/tablet/multi_column_writer.cc b/src/kudu/tablet/multi_column_writer.cc
index 7aa5d03..6e39b0f 100644
--- a/src/kudu/tablet/multi_column_writer.cc
+++ b/src/kudu/tablet/multi_column_writer.cc
@@ -32,6 +32,7 @@
 #include "kudu/fs/fs_manager.h"
 #include "kudu/gutil/gscoped_ptr.h"
 #include "kudu/gutil/stl_util.h"
+#include "kudu/gutil/strings/substitute.h"
 
 namespace kudu {
 namespace tablet {
@@ -95,7 +96,8 @@ Status MultiColumnWriter::Open() {
     cfile_writers_.push_back(writer.release());
     block_ids_.push_back(block_id);
   }
-  LOG(INFO) << "Opened CFile writers for " << cfile_writers_.size() <<
" column(s)";
+  VLOG(1) << strings::Substitute("Opened CFile writers for $0 column(s)",
+                                 cfile_writers_.size());
 
   return Status::OK();
 }
diff --git a/src/kudu/tablet/tablet.cc b/src/kudu/tablet/tablet.cc
index 40b728f..67f3853 100644
--- a/src/kudu/tablet/tablet.cc
+++ b/src/kudu/tablet/tablet.cc
@@ -1213,16 +1213,17 @@ Status Tablet::FlushInternal(const RowSetsInCompaction& input,
                           "PostSwapNewMemRowSet hook failed");
   }
 
-  LOG_WITH_PREFIX(INFO) << "Flush: entering stage 1 (old memrowset already frozen for
inserts)";
-  input.DumpToLog();
-  LOG_WITH_PREFIX(INFO) << "Memstore in-memory size: " << old_ms->memory_footprint()
<< " bytes";
+  VLOG_WITH_PREFIX(1) << Substitute("Flush: entering stage 1 (old memrowset"
+                                    "already frozen for inserts). Memstore"
+                                    "in-memory size: $0 bytes",
+                                    old_ms->memory_footprint());
 
   RETURN_NOT_OK(DoMergeCompactionOrFlush(input, mrs_being_flushed));
 
   // Sanity check that no insertions happened during our flush.
   CHECK_EQ(start_insert_count, old_ms->debug_insert_count())
     << "Sanity check failed: insertions continued in memrowset "
-    << "after flush was triggered! Aborting to prevent dataloss.";
+    << "after flush was triggered! Aborting to prevent data loss.";
 
   return Status::OK();
 }
@@ -1526,8 +1527,9 @@ Status Tablet::DoMergeCompactionOrFlush(const RowSetsInCompaction &input,
   const IOContext io_context({ tablet_id() });
 
   MvccSnapshot flush_snap(mvcc_);
-  LOG_WITH_PREFIX(INFO) << op_name << ": entering phase 1 (flushing snapshot).
Phase 1 snapshot: "
-                        << flush_snap.ToString();
+  VLOG_WITH_PREFIX(1) << Substitute("$0: entering phase 1 (flushing snapshot). "
+                                    "Phase 1 snapshot: $1",
+                                    op_name, flush_snap.ToString());
 
   if (common_hooks_) {
     RETURN_NOT_OK_PREPEND(common_hooks_->PostTakeMvccSnapshot(),
@@ -1612,8 +1614,9 @@ Status Tablet::DoMergeCompactionOrFlush(const RowSetsInCompaction &input,
   //
   // The way that we avoid this case is that DuplicatingRowSet's FlushDeltas method is a
   // no-op.
-  LOG_WITH_PREFIX(INFO) << op_name << ": entering phase 2 (starting to duplicate
updates "
-                        << "in new rowsets)";
+  VLOG_WITH_PREFIX(1) << Substitute("$0: entering phase 2 (starting to "
+                                    "duplicate updates in new rowsets)",
+                                    op_name);
   shared_ptr<DuplicatingRowSet> inprogress_rowset(
     new DuplicatingRowSet(input.rowsets(), new_disk_rowsets));
 
@@ -1667,9 +1670,9 @@ Status Tablet::DoMergeCompactionOrFlush(const RowSetsInCompaction &input,
 
   // Phase 2. Here we re-scan the compaction input, copying those missed updates into the
   // new rowset's DeltaTracker.
-  LOG_WITH_PREFIX(INFO) << op_name
-                        << " Phase 2: carrying over any updates which arrived during
Phase 1";
-  LOG_WITH_PREFIX(INFO) << "Phase 2 snapshot: " << non_duplicated_txns_snap.ToString();
+  VLOG_WITH_PREFIX(1) << Substitute("$0: Phase 2: carrying over any updates "
+                                    "which arrived during Phase 1. Snapshot: $1",
+                                    op_name, non_duplicated_txns_snap.ToString());
   RETURN_NOT_OK_PREPEND(
       input.CreateCompactionInput(non_duplicated_txns_snap, schema(), &io_context, &merge),
           Substitute("Failed to create $0 inputs", op_name).c_str());
@@ -1717,11 +1720,17 @@ Status Tablet::DoMergeCompactionOrFlush(const RowSetsInCompaction
&input,
   // their metadata was written to disk.
   AtomicSwapRowSets({ inprogress_rowset }, new_disk_rowsets);
 
-  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());
+  const auto rows_written = drsw.rows_written_count();
+  const auto drs_written = drsw.drs_written_count();
+  const auto bytes_written = drsw.written_size();
+  TRACE_COUNTER_INCREMENT("rows_written", rows_written);
+  TRACE_COUNTER_INCREMENT("drs_written", drs_written);
+  TRACE_COUNTER_INCREMENT("bytes_written", bytes_written);
+  VLOG_WITH_PREFIX(1) << Substitute("$0 successful on $1 rows ($2 rowsets, $3 bytes)",
+                                    op_name,
+                                    rows_written,
+                                    drs_written,
+                                    bytes_written);
 
   if (common_hooks_) {
     RETURN_NOT_OK_PREPEND(common_hooks_->PostSwapNewRowSet(),
@@ -1750,14 +1759,19 @@ Status Tablet::Compact(CompactFlags flags) {
   // Step 1. Capture the rowsets to be merged
   RETURN_NOT_OK_PREPEND(PickRowSetsToCompact(&input, flags),
                         "Failed to pick rowsets to compact");
-  LOG_WITH_PREFIX(INFO) << "Compaction: stage 1 complete, picked "
-                        << input.num_rowsets() << " rowsets to compact or flush";
+  const auto num_input_rowsets = input.num_rowsets();
+  TRACE_COUNTER_INCREMENT("num_input_rowsets", num_input_rowsets);
+  VLOG_WITH_PREFIX(1) << Substitute("Compaction: stage 1 complete, picked $0 "
+                                    "rowsets to compact or flush",
+                                    num_input_rowsets);
   if (compaction_hooks_) {
     RETURN_NOT_OK_PREPEND(compaction_hooks_->PostSelectIterators(),
                           "PostSelectIterators hook failed");
   }
 
-  input.DumpToLog();
+  if (VLOG_IS_ON(1)) {
+    input.DumpToLog();
+  }
 
   return DoMergeCompactionOrFlush(input, TabletMetadata::kNoMrsFlushed);
 }


Mime
View raw message