kudu-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From granthe...@apache.org
Subject [kudu] 03/09: Eliminate redundant VLOG_IS_ON calls
Date Thu, 10 Jan 2019 23:05:19 GMT
This is an automated email from the ASF dual-hosted git repository.

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

commit 7c17dc2ceeec0c27f7b36ff24bd5a725026d8da8
Author: Will Berkeley <wdberkeley@gmail.org>
AuthorDate: Tue Jan 8 14:20:42 2019 -0800

    Eliminate redundant VLOG_IS_ON calls
    
    In an expression like
    
      VLOG(3) << Substitute("Your $0 is $1", expensive_foo(), costly_bar());
    
    The expression on the righthand side of the << operator is evaluated
    only when VLOG_IS_ON(3) is true. However, there were some cases of
    defensive programming like
    
      if (VLOG_IS_ON(3)) {
        VLOG(3) << Substitute("Your $0 is $1", expensive_foo(), costly_bar());
      }
    
    with a redundant call to VLOG_IS_ON. This patch removes such cases as I
    found from a simple review of all VLOG_IS_ON callsites. I also sometimes
    transformed VLOG messages from a chain of <<'s to calls to Substitute.
    
    This patch contains no functional changes.
    
    Change-Id: I0781e64f95e33fe067f9f3e65e77aec8654f4ba3
    Reviewed-on: http://gerrit.cloudera.org:8080/12194
    Tested-by: Kudu Jenkins
    Reviewed-by: Alexey Serbin <aserbin@cloudera.com>
---
 src/kudu/client/batcher.cc                |  7 ++---
 src/kudu/clock/hybrid_clock.cc            | 17 ++++++------
 src/kudu/consensus/consensus_queue.cc     | 46 +++++++++++++++++--------------
 src/kudu/consensus/raft_consensus.cc      |  6 ++--
 src/kudu/tablet/tablet-test-base.h        |  6 ++--
 src/kudu/tablet/tablet-test-util.h        | 14 ++++++----
 src/kudu/tablet/tablet_bootstrap.cc       |  4 +--
 src/kudu/tablet/tablet_history_gc-test.cc |  9 ++----
 src/kudu/tserver/tablet_server-test.cc    |  4 +--
 src/kudu/tserver/tablet_service.cc        |  6 ++--
 src/kudu/util/logging-test.cc             | 17 ++++++++++++
 11 files changed, 75 insertions(+), 61 deletions(-)

diff --git a/src/kudu/client/batcher.cc b/src/kudu/client/batcher.cc
index 0710f9a..c213d00 100644
--- a/src/kudu/client/batcher.cc
+++ b/src/kudu/client/batcher.cc
@@ -53,6 +53,7 @@
 #include "kudu/gutil/stl_util.h"
 #include "kudu/gutil/strings/substitute.h"
 #include "kudu/rpc/connection.h"
+#include "kudu/rpc/request_tracker.h"
 #include "kudu/rpc/response_callback.h"
 #include "kudu/rpc/retriable_rpc.h"
 #include "kudu/rpc/rpc.h"
@@ -79,7 +80,6 @@ class Schema;
 
 namespace rpc {
 class Messenger;
-class RequestTracker;
 }
 
 using pb_util::SecureDebugString;
@@ -317,9 +317,8 @@ WriteRpc::WriteRpc(const scoped_refptr<Batcher>& batcher,
     VLOG(4) << ++ctr << ". Encoded row " << op->ToString();
   }
 
-  if (VLOG_IS_ON(3)) {
-    VLOG(3) << "Created batch for " << tablet_id << ":\n" << SecureShortDebugString(req_);
-  }
+  VLOG(3) << Substitute("Created batch for $0:\n$1",
+                        tablet_id, SecureShortDebugString(req_));
 }
 
 WriteRpc::~WriteRpc() {
diff --git a/src/kudu/clock/hybrid_clock.cc b/src/kudu/clock/hybrid_clock.cc
index 7e87d4d..bec8cba 100644
--- a/src/kudu/clock/hybrid_clock.cc
+++ b/src/kudu/clock/hybrid_clock.cc
@@ -180,11 +180,10 @@ void HybridClock::NowWithError(Timestamp* timestamp, uint64_t* max_error_usec)
{
     next_timestamp_ = candidate_phys_timestamp;
     *timestamp = Timestamp(next_timestamp_++);
     *max_error_usec = error_usec;
-    if (PREDICT_FALSE(VLOG_IS_ON(2))) {
-      VLOG(2) << "Current clock is higher than the last one. Resetting logical values."
-          << " Physical Value: " << now_usec << " usec Logical Value: 0
 Error: "
-          << error_usec;
-    }
+    VLOG(2) << Substitute("Current clock is higher than the last one. "
+                          "Resetting logical values. Physical Value: $0 usec "
+                          "Logical Value: 0  Error: $1",
+                          now_usec, error_usec);
     return;
   }
 
@@ -208,10 +207,10 @@ void HybridClock::NowWithError(Timestamp* timestamp, uint64_t* max_error_usec)
{
 
   *max_error_usec = (next_timestamp_ >> kBitsToShift) - (now_usec - error_usec);
   *timestamp = Timestamp(next_timestamp_++);
-  if (PREDICT_FALSE(VLOG_IS_ON(2))) {
-    VLOG(2) << "Current clock is lower than the last one. Returning last read and incrementing"
-        " logical values. Clock: " + Stringify(*timestamp) << " Error: " << *max_error_usec;
-  }
+  VLOG(2) << Substitute("Current clock is lower than the last one. Returning "
+                        "last read and incrementing logical values. "
+                        "Clock: $0 Error: $1",
+                        Stringify(*timestamp), *max_error_usec);
 }
 
 Status HybridClock::Update(const Timestamp& to_update) {
diff --git a/src/kudu/consensus/consensus_queue.cc b/src/kudu/consensus/consensus_queue.cc
index c618002..383a5cd 100644
--- a/src/kudu/consensus/consensus_queue.cc
+++ b/src/kudu/consensus/consensus_queue.cc
@@ -750,13 +750,17 @@ Status PeerMessageQueue::RequestForPeer(const string& uuid,
 
   if (PREDICT_FALSE(VLOG_IS_ON(2))) {
     if (request->ops_size() > 0) {
-      VLOG_WITH_PREFIX_UNLOCKED(2) << "Sending request with operations to Peer: " <<
uuid
-          << ". Size: " << request->ops_size()
-          << ". From: " << SecureShortDebugString(request->ops(0).id()) <<
". To: "
-          << SecureShortDebugString(request->ops(request->ops_size() - 1).id());
+      VLOG_WITH_PREFIX_UNLOCKED(2)
+          << Substitute("Sending request with operations to Peer: $0. Size: $1. From:
$2. To: $3",
+                        uuid,
+                        request->ops_size(),
+                        SecureShortDebugString(request->ops(0).id()),
+                        SecureShortDebugString(request->ops(request->ops_size() - 1).id()));
     } else {
-      VLOG_WITH_PREFIX_UNLOCKED(2) << "Sending status only request to Peer: " <<
uuid
-          << ": " << SecureDebugString(*request);
+      VLOG_WITH_PREFIX_UNLOCKED(2)
+          << Substitute("Sending status only request to Peer: $0: $1",
+                        uuid,
+                        SecureDebugString(*request));
     }
   }
 
@@ -797,12 +801,14 @@ void PeerMessageQueue::AdvanceQueueWatermark(const char* type,
                                              ReplicaTypes replica_types,
                                              const TrackedPeer* who_caused) {
 
-  if (VLOG_IS_ON(2)) {
-    VLOG_WITH_PREFIX_UNLOCKED(2) << "Updating " << type << " watermark:
"
-        << "Peer (" << who_caused->ToString() << ") changed from "
-        << replicated_before << " to " << replicated_after << ".
"
-                                 << "Current value: " << *watermark;
-  }
+  VLOG_WITH_PREFIX_UNLOCKED(2)
+      << Substitute("Updating $0 watermark: Peer ($1) changed from $2 to $3. "
+                    "Current value: $4",
+                    type,
+                    who_caused->ToString(),
+                    OpIdToString(replicated_before),
+                    OpIdToString(replicated_after),
+                    *watermark);
 
   // Go through the peer's watermarks, we want the highest watermark that
   // 'num_peers_required' of peers has replicated. To find this we do the
@@ -855,15 +861,16 @@ void PeerMessageQueue::AdvanceQueueWatermark(const char* type,
   int64_t old_watermark = *watermark;
   *watermark = new_watermark;
 
-  VLOG_WITH_PREFIX_UNLOCKED(1) << "Updated " << type << " watermark "
-      << "from " << old_watermark << " to " << new_watermark;
+  VLOG_WITH_PREFIX_UNLOCKED(1)
+      << Substitute("Updated $0 watermark from $1 to $2",
+                    type, old_watermark, new_watermark);
   if (VLOG_IS_ON(3)) {
     VLOG_WITH_PREFIX_UNLOCKED(3) << "Peers: ";
-    for (const PeersMap::value_type& peer : peers_map_) {
+    for (const auto& peer : peers_map_) {
       VLOG_WITH_PREFIX_UNLOCKED(3) << "Peer: " << peer.second->ToString();
     }
     VLOG_WITH_PREFIX_UNLOCKED(3) << "Sorted watermarks:";
-    for (int64_t watermark : watermarks) {
+    for (const auto watermark : watermarks) {
       VLOG_WITH_PREFIX_UNLOCKED(3) << "Watermark: " << watermark;
     }
   }
@@ -1176,10 +1183,9 @@ bool PeerMessageQueue::ResponseFromPeer(const std::string& peer_uuid,
       CHECK_LE(response.responder_term(), queue_state_.current_term);
     }
 
-    if (PREDICT_FALSE(VLOG_IS_ON(2))) {
-      VLOG_WITH_PREFIX_UNLOCKED(2) << "Received Response from Peer (" << peer->ToString()
<< "). "
-          << "Response: " << SecureShortDebugString(response);
-    }
+    VLOG_WITH_PREFIX_UNLOCKED(2)
+        << Substitute("Received Response from Peer ($0). Response: $1",
+                      peer->ToString(), SecureShortDebugString(response));
 
     mode_copy = queue_state_.mode;
 
diff --git a/src/kudu/consensus/raft_consensus.cc b/src/kudu/consensus/raft_consensus.cc
index 7428fe0..3435d5d 100644
--- a/src/kudu/consensus/raft_consensus.cc
+++ b/src/kudu/consensus/raft_consensus.cc
@@ -1012,9 +1012,9 @@ Status RaftConsensus::Update(const ConsensusRequestPB* request,
   Status s = UpdateReplica(request, response);
   if (PREDICT_FALSE(VLOG_IS_ON(1))) {
     if (request->ops().empty()) {
-      VLOG_WITH_PREFIX(1) << "Replica replied to status only request. Replica: "
-                          << ToString() << ". Response: "
-                          << SecureShortDebugString(*response);
+      VLOG_WITH_PREFIX(1)
+          << Substitute("Replica replied to status only request. Replica: $0. Response:
$1",
+                        ToString(), SecureShortDebugString(*response));
     }
   }
   return s;
diff --git a/src/kudu/tablet/tablet-test-base.h b/src/kudu/tablet/tablet-test-base.h
index 3386f56..d6977f6 100644
--- a/src/kudu/tablet/tablet-test-base.h
+++ b/src/kudu/tablet/tablet-test-base.h
@@ -453,10 +453,8 @@ class TabletTestBase : public KuduTabletTest {
       ASSERT_OK_FAST(iter->NextBlock(&block));
 
       RowBlockRow rb_row = block.row(0);
-      if (VLOG_IS_ON(2)) {
-        VLOG(2) << "Fetched batch of " << block.nrows() << "\n"
-                << "First row: " << schema_.DebugRow(rb_row);
-      }
+      VLOG(2) << Substitute("Fetched batch of $0\nFirst row: $1",
+                            block.nrows(), schema_.DebugRow(rb_row));
 
       for (int i = 0; i < block.nrows(); i++) {
         rb_row.Reset(&block, i);
diff --git a/src/kudu/tablet/tablet-test-util.h b/src/kudu/tablet/tablet-test-util.h
index b5947ea..22651af 100644
--- a/src/kudu/tablet/tablet-test-util.h
+++ b/src/kudu/tablet/tablet-test-util.h
@@ -81,6 +81,8 @@
 #include "kudu/util/test_macros.h"
 #include "kudu/util/test_util.h"
 
+using strings::Substitute;
+
 namespace kudu {
 
 namespace clock {
@@ -418,8 +420,8 @@ class MirroredDeltas {
                       const SelectionVector& filter) {
     if (VLOG_IS_ON(3)) {
       std::string lower_ts_str = lower_ts ? lower_ts->ToString() : "INF";
-      VLOG(3) << "Begin applying for timestamps [" << lower_ts_str << ","
-              << upper_ts << ")";
+      VLOG(3) << Substitute("Begin applying for timestamps [$0, $1)",
+                            lower_ts_str, upper_ts.ToString());
     }
     for (int i = 0; i < cb->nrows(); i++) {
       rowid_t row_idx = start_row_idx + i;
@@ -902,14 +904,14 @@ void RunDeltaFuzzTest(const DeltaStore& store,
                                                        AllowIsDeleted::NO);
     size_t projection_vc_is_deleted_idx =
         projection.find_first_is_deleted_virtual_column();
-    SCOPED_TRACE(strings::Substitute("Projection $0", projection.ToString()));
+    SCOPED_TRACE(Substitute("Projection $0", projection.ToString()));
     RowIteratorOptions opts;
     opts.projection = &projection;
     if (lower_ts) {
       opts.snap_to_exclude = MvccSnapshot(*lower_ts);
     }
     opts.snap_to_include = MvccSnapshot(upper_ts);
-    SCOPED_TRACE(strings::Substitute("Timestamps: [$0,$1)",
+    SCOPED_TRACE(Substitute("Timestamps: [$0,$1)",
                                      lower_ts ? lower_ts->ToString() : "INF",
                                      upper_ts.ToString()));
     DeltaIterator* raw_iter;
@@ -928,7 +930,7 @@ void RunDeltaFuzzTest(const DeltaStore& store,
     rowid_t start_row_idx = 0;
     while (iter->HasNext()) {
       int batch_size = prng->Uniform(kMaxBatchSize) + 1;
-      SCOPED_TRACE(strings::Substitute("batch starting at $0 ($1 rows)",
+      SCOPED_TRACE(Substitute("batch starting at $0 ($1 rows)",
                                        start_row_idx, batch_size));
       int prepare_flags = DeltaIterator::PREPARE_FOR_APPLY |
                           DeltaIterator::PREPARE_FOR_COLLECT;
@@ -969,7 +971,7 @@ void RunDeltaFuzzTest(const DeltaStore& store,
 
       // Test ApplyUpdates: all relevant updates are applied to the column block.
       for (int j = 0; j < opts.projection->num_columns(); j++) {
-        SCOPED_TRACE(strings::Substitute("Column $0", j));
+        SCOPED_TRACE(Substitute("Column $0", j));
         bool col_is_nullable = opts.projection->column(j).is_nullable();
         ScopedColumnBlock<UINT32> expected_scb(batch_size, col_is_nullable);
         ScopedColumnBlock<UINT32> actual_scb(batch_size, col_is_nullable);
diff --git a/src/kudu/tablet/tablet_bootstrap.cc b/src/kudu/tablet/tablet_bootstrap.cc
index d32316c..084b1e0 100644
--- a/src/kudu/tablet/tablet_bootstrap.cc
+++ b/src/kudu/tablet/tablet_bootstrap.cc
@@ -835,9 +835,7 @@ Status TabletBootstrap::HandleEntry(const IOContext* io_context,
                                     unique_ptr<LogEntryPB> entry,
                                     string* entry_debug_info) {
   DCHECK(entry);
-  if (VLOG_IS_ON(1)) {
-    VLOG_WITH_PREFIX(1) << "Handling entry: " << SecureShortDebugString(*entry);
-  }
+  VLOG_WITH_PREFIX(1) << "Handling entry: " << SecureShortDebugString(*entry);
 
   const auto entry_type = entry->type();
   switch (entry_type) {
diff --git a/src/kudu/tablet/tablet_history_gc-test.cc b/src/kudu/tablet/tablet_history_gc-test.cc
index 37397aa..4969900 100644
--- a/src/kudu/tablet/tablet_history_gc-test.cc
+++ b/src/kudu/tablet/tablet_history_gc-test.cc
@@ -17,7 +17,6 @@
 
 #include <algorithm>
 #include <atomic>
-
 #include <cstdint>
 #include <memory>
 #include <ostream>
@@ -40,6 +39,7 @@
 #include "kudu/gutil/casts.h"
 #include "kudu/gutil/port.h"
 #include "kudu/gutil/ref_counted.h"
+#include "kudu/gutil/strings/join.h"
 #include "kudu/gutil/strings/substitute.h"
 #include "kudu/gutil/walltime.h"
 #include "kudu/tablet/compaction.h"
@@ -49,6 +49,7 @@
 #include "kudu/tablet/rowset_metadata.h"
 #include "kudu/tablet/tablet-harness.h"
 #include "kudu/tablet/tablet-test-base.h"
+#include "kudu/tablet/tablet-test-util.h"
 #include "kudu/tablet/tablet.h"
 #include "kudu/tablet/tablet_metadata.h"
 #include "kudu/tablet/tablet_metrics.h"
@@ -540,11 +541,7 @@ TEST_F(TabletHistoryGcTest, TestGcWithConcurrentCompaction) {
   vector<string> rows;
   ASSERT_OK(IterateToStringList(&rows));
 
-  if (VLOG_IS_ON(2)) {
-    for (const string& r : rows) {
-      VLOG(2) << r;
-    }
-  }
+  VLOG(2) << JoinStrings(rows, "\n");
 
   vector<int32_t> expected_rows = { 1, 3, 5, 7, 9 };
   for (int i = 0; i < expected_rows.size(); i++) {
diff --git a/src/kudu/tserver/tablet_server-test.cc b/src/kudu/tserver/tablet_server-test.cc
index bfdd7ab..dd60bd1 100644
--- a/src/kudu/tserver/tablet_server-test.cc
+++ b/src/kudu/tserver/tablet_server-test.cc
@@ -1782,8 +1782,8 @@ TEST_F(TabletServerTest, TestSnapshotScan) {
     ASSERT_EQ(expected_num_rows, results.size());
 
     if (VLOG_IS_ON(2)) {
-      VLOG(2) << "Scanner: " << resp.scanner_id() << " performing a snapshot
read at: "
-              << read_timestamp.ToString() << " got back: ";
+      VLOG(2) << Substitute("Scanner: $0 performing a snapshot read at $1 got back:
",
+                            resp.scanner_id(), read_timestamp.ToString());
       for (const string& result : results) {
         VLOG(2) << result;
       }
diff --git a/src/kudu/tserver/tablet_service.cc b/src/kudu/tserver/tablet_service.cc
index 0ec4e5f..40c855d 100644
--- a/src/kudu/tserver/tablet_service.cc
+++ b/src/kudu/tserver/tablet_service.cc
@@ -1756,10 +1756,8 @@ static Status SetupScanSpec(const NewScanRequestPB& scan_pb,
 
     auto pred = ColumnPredicate::InclusiveRange(col, lower_bound, upper_bound, scanner->arena());
     if (pred) {
-      if (VLOG_IS_ON(3)) {
-        VLOG(3) << "Parsed predicate " << pred->ToString()
-                << " from " << SecureShortDebugString(scan_pb);
-      }
+      VLOG(3) << Substitute("Parsed predicate $0 from $1",
+                            pred->ToString(), SecureShortDebugString(scan_pb));
       ret->AddPredicate(*pred);
     }
   }
diff --git a/src/kudu/util/logging-test.cc b/src/kudu/util/logging-test.cc
index cceece8..9562919 100644
--- a/src/kudu/util/logging-test.cc
+++ b/src/kudu/util/logging-test.cc
@@ -246,4 +246,21 @@ TEST(LoggingTest, TestLogTiming) {
 
   ASSERT_EQ("hello", s2);
 }
+
+// Test that VLOG(n) does not evaluate its message if the verbose level is < n,
+// ensuring that it is perf-safe to write things like
+//
+//   VLOG(1) << Substitute("your foo is $0", compute_costly_bar_string());
+//
+// in hot code paths.
+TEST(LoggingTest, TestVlogDoesNotEvaluateMessage) {
+  if (VLOG_IS_ON(1)) {
+    LOG(INFO) << "Test skipped: verbose level is at least 1";
+    return;
+  }
+
+  int numVlogs = 0;
+  VLOG(1) << "This shouldn't be logged: " << numVlogs++;
+  ASSERT_EQ(0, numVlogs);
+}
 } // namespace kudu


Mime
View raw message