#5359: Revert "#5081: Fix MetricsTest.SimpleLagTest"

Summary: This reverts commit 4c0a2fe. There is currently an issue with the new clock introduced with this diff that causes a crash in some scenarios when the metric is queried. ```#0 Now (this=0x742f680192a46a02) at ../../src/yb/common/clock.h:27 #1 lag_ms (this=0x5dadc40) at ../../src/yb/util/metrics.h:1355 #2 yb::AtomicMillisLag::WriteForPrometheus (this=0x5dadc40, writer=0x7fbdc2f84bb0, attr=..., opts=...) at ../../src/yb/util/metrics.h:1374 #3 0x00007fbdedc2ab83 in yb::MetricEntity::WriteForPrometheus (this=<optimized out>, writer=writer@entry=0x7fbdc2f84bb0, opts=...) at ../../src/yb/util/metrics.cc:351 #4 0x00007fbdedc2cf05 in yb::MetricRegistry::WriteForPrometheus (this=this@entry=0x1a70a80, writer=writer@entry=0x7fbdc2f84bb0, opts=...) at ../../src/yb/util/metrics.cc:491 #5 0x00007fbdf2cfe6d0 in yb::(anonymous namespace)::WriteForPrometheus (metrics=0x1a70a80, req=..., resp=0x7fbdc2f84de0) at ../../src/yb/server/default-path-handlers.cc:278 #6 0x00007fbdf2d2d95c in operator() (__args#1=0x7fbdc2f84de0, __args#0=..., this=<optimized out>) at /home/yugabyte/yb-software/yugabyte-2.3.0.0-b88-centos-x86_64/linuxbrew-xxxxxxxxxxxxx/Cellar/gcc/5.5.0_4/include/c++/5.5.0/functional:2267 #7 yb::Webserver::RunPathHandler (this=this@entry=0x1d64000, handler=..., connection=connection@entry=0x7d88000, request_info=request_info@entry=0x7d88000) at ../../src/yb/server/webserver.cc:423 #8 0x00007fbdf2d2e5ea in yb::Webserver::BeginRequestCallback (this=0x1d64000, connection=0x7d88000, request_info=0x7d88000) at ../../src/yb/server/webserver.cc:360 #9 0x00007fbdf2d438f6 in handle_request () from /home/yugabyte/yb-software/yugabyte-2.3.0.0-b88-centos-x86_64/lib/yb/libserver_process.so #10 0x00007fbdf2d464de in worker_thread () from /home/yugabyte/yb-software/yugabyte-2.3.0.0-b88-centos-x86_64/lib/yb/libserver_process.so #11 0x00007fbde84c5694 in start_thread (arg=0x7fbdc2f8f700) at pthread_create.c:333 #12 0x00007fbde7c0241d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109``` Test Plan: Build and unit tests Reviewers: bogdan, amitanand, kannan Reviewed By: kannan Subscribers: kannan, ybase Differential Revision: https://phabricator.dev.yugabyte.com/D9322
yugabyte · Sep 5, 2020 · ecf9a28 · ecf9a28
1 parent 8af029e
commit ecf9a28
Show file tree

Hide file tree

Showing 9 changed files with 62 additions and 141 deletions.
diff --git a/src/yb/common/hybrid_time.h b/src/yb/common/hybrid_time.h
@@ -202,11 +202,6 @@ class HybridTime {
     return v >> kBitsForLogicalComponent;
   }
 
-  // Returns the physical value embedded in this HybridTime, in milliseconds.
-  inline MillisTime GetPhysicalValueMillis() const {
-    return GetPhysicalValueMicros() / 1000;
-  }
-
   inline int64_t PhysicalDiff(const HybridTime& other) const {
     return static_cast<int64_t>(GetPhysicalValueMicros() - other.GetPhysicalValueMicros());
   }

diff --git a/src/yb/consensus/raft_consensus.cc b/src/yb/consensus/raft_consensus.cc
@@ -340,7 +340,7 @@ RaftConsensus::RaftConsensus(
       term_metric_(metric_entity->FindOrCreateGauge(&METRIC_raft_term,
                                                     cmeta->current_term())),
       follower_last_update_time_ms_metric_(
-          metric_entity->FindOrCreateAtomicMillisLag(&METRIC_follower_lag_ms, clock_)),
+          metric_entity->FindOrCreateAtomicMillisLag(&METRIC_follower_lag_ms)),
       is_raft_leader_metric_(metric_entity->FindOrCreateGauge(&METRIC_is_raft_leader,
                                                               static_cast<int64_t>(0))),
       parent_mem_tracker_(std::move(parent_mem_tracker)),
@@ -954,7 +954,7 @@ Status RaftConsensus::BecomeLeaderUnlocked() {
   // Set the timestamp to max uint64_t so that every time this metric is queried, the returned
   // lag is 0. We will need to restore the timestamp once this peer steps down.
   follower_last_update_time_ms_metric_->UpdateTimestampInMilliseconds(
-      std::numeric_limits<uint64_t>::max());
+      std::numeric_limits<int64_t>::max());
   is_raft_leader_metric_->set_value(1);
 
   return Status::OK();

diff --git a/src/yb/server/CMakeLists.txt b/src/yb/server/CMakeLists.txt
@@ -58,7 +58,6 @@ ADD_YB_TEST(hybrid_clock-test)
 ADD_YB_TEST(logical_clock-test)
 # This test is here and not in common because we need access to HybridClock.
 ADD_YB_TEST(doc_hybrid_time-test)
-ADD_YB_TEST(lag_metrics_test)
 
 #########################################
 # server_base_proto

diff --git a/src/yb/server/clock.h b/src/yb/server/clock.h
@@ -36,6 +36,7 @@
 #include <string>
 
 #include "yb/common/clock.h"
+#include "yb/common/common.pb.h"
 #include "yb/common/hybrid_time.h"
 
 #include "yb/gutil/ref_counted.h"

diff --git a/src/yb/server/lag_metrics_test.cc b/src/yb/server/lag_metrics_test.cc
diff --git a/src/yb/util/metrics-test.cc b/src/yb/util/metrics-test.cc
@@ -66,6 +66,22 @@ class MetricsTest : public YBTest {
   }
 
  protected:
+  template <class LagType>
+  void DoLagTest(const MillisLagPrototype& metric) {
+    auto lag = new LagType(&metric);
+    ASSERT_EQ(metric.description(), lag->prototype()->description());
+    auto now_ms = std::chrono::duration_cast<std::chrono::milliseconds>(
+        std::chrono::system_clock::now().time_since_epoch()).count();
+    SleepFor(MonoDelta::FromMilliseconds(100));
+    ASSERT_LT(now_ms, lag->lag_ms());
+    lag->UpdateTimestampInMilliseconds(now_ms);
+    ASSERT_GT(10000, lag->lag_ms());
+    // Set the timestamp to some time in the future to verify that the metric can correctly deal
+    // with this case.
+    lag->UpdateTimestampInMilliseconds(now_ms * 2);
+    ASSERT_EQ(0, lag->lag_ms());
+  }
+
   MetricRegistry registry_;
   scoped_refptr<MetricEntity> entity_;
 };
@@ -84,6 +100,17 @@ TEST_F(MetricsTest, SimpleCounterTest) {
   ASSERT_EQ(3, requests->value());
 }
 
+METRIC_DEFINE_lag(test_entity, lag_simple, "Test MillisLag", "Test MillisLag Description");
+TEST_F(MetricsTest, SimpleLagTest) {
+  ASSERT_NO_FATALS(DoLagTest<MillisLag>(METRIC_lag_simple));
+}
+
+METRIC_DEFINE_lag(test_entity, atomic_lag_simple, "Test Atomic MillisLag",
+                  "Test Atomic MillisLag Description");
+TEST_F(MetricsTest, SimpleAtomicLagTest) {
+  ASSERT_NO_FATALS(DoLagTest<AtomicMillisLag>(METRIC_atomic_lag_simple));
+}
+
 METRIC_DEFINE_gauge_uint64(test_entity, fake_memory_usage, "Memory Usage",
                            MetricUnit::kBytes, "Test Gauge 1");
 

diff --git a/src/yb/util/metrics.cc b/src/yb/util/metrics.cc
@@ -776,12 +776,11 @@ CHECKED_STATUS Counter::WriteForPrometheus(
 //
 
 scoped_refptr<MillisLag> MillisLagPrototype::Instantiate(
-    const scoped_refptr<MetricEntity>& entity, const scoped_refptr<server::Clock>& clock) {
-  return entity->FindOrCreateMillisLag(this, clock);
+    const scoped_refptr<MetricEntity>& entity) {
+  return entity->FindOrCreateMillisLag(this);
 }
 
-MillisLag::MillisLag(const MillisLagPrototype* proto, const scoped_refptr<server::Clock>& clock)
-  : Metric(proto), clock_(clock), timestamp_ms_(clock_->Now().GetPhysicalValueMillis()) {
+MillisLag::MillisLag(const MillisLagPrototype* proto) : Metric(proto) {
 }
 
 Status MillisLag::WriteAsJson(JsonWriter* writer, const MetricJsonOptions& opts) const {
@@ -794,7 +793,7 @@ Status MillisLag::WriteAsJson(JsonWriter* writer, const MetricJsonOptions& opts)
   prototype_->WriteFields(writer, opts);
 
   writer->String("value");
-  writer->Uint64(lag_ms());
+  writer->Int64(lag_ms());
 
   writer->EndObject();
   return Status::OK();
@@ -810,11 +809,6 @@ Status MillisLag::WriteForPrometheus(
   return writer->WriteSingleEntry(attr, prototype_->name(), lag_ms());
 }
 
-AtomicMillisLag::AtomicMillisLag(const MillisLagPrototype* proto,
-                                 const scoped_refptr<server::Clock>& clock)
-  : MillisLag(proto, clock), atomic_timestamp_ms_(clock_->Now().GetPhysicalValueMillis()) {
-}
-
 Status AtomicMillisLag::WriteAsJson(JsonWriter* writer, const MetricJsonOptions& opts) const {
   if (prototype_->level() < opts.level) {
     return Status::OK();
@@ -825,7 +819,7 @@ Status AtomicMillisLag::WriteAsJson(JsonWriter* writer, const MetricJsonOptions&
   prototype_->WriteFields(writer, opts);
 
   writer->String("value");
-  writer->Uint64(this->lag_ms());
+  writer->Int64(this->lag_ms());
 
   writer->EndObject();
   return Status::OK();

diff --git a/src/yb/util/metrics.h b/src/yb/util/metrics.h
@@ -258,8 +258,6 @@
 #include "yb/gutil/ref_counted.h"
 #include "yb/gutil/singleton.h"
 
-#include "yb/server/clock.h"
-
 #include "yb/util/atomic.h"
 #include "yb/util/jsonwriter.h"
 #include "yb/util/locks.h"
@@ -560,11 +558,8 @@ class MetricEntity : public RefCountedThreadSafe<MetricEntity> {
     ExternalPrometheusMetricsCb;
 
   scoped_refptr<Counter> FindOrCreateCounter(const CounterPrototype* proto);
-  scoped_refptr<MillisLag> FindOrCreateMillisLag(const MillisLagPrototype* proto,
-                                                 const scoped_refptr<server::Clock>& clock);
-  scoped_refptr<AtomicMillisLag> FindOrCreateAtomicMillisLag(
-      const MillisLagPrototype* proto,
-      const scoped_refptr<server::Clock>& clock);
+  scoped_refptr<MillisLag> FindOrCreateMillisLag(const MillisLagPrototype* proto);
+  scoped_refptr<AtomicMillisLag> FindOrCreateAtomicMillisLag(const MillisLagPrototype* proto);
   scoped_refptr<Histogram> FindOrCreateHistogram(const HistogramPrototype* proto);
 
   template<typename T>
@@ -1311,8 +1306,7 @@ class MillisLagPrototype : public MetricPrototype {
  public:
   explicit MillisLagPrototype(const MetricPrototype::CtorArgs& args) : MetricPrototype(args) {
   }
-  scoped_refptr<MillisLag> Instantiate(const scoped_refptr<MetricEntity>& entity,
-                                       const scoped_refptr<server::Clock>& clock);
+  scoped_refptr<MillisLag> Instantiate(const scoped_refptr<MetricEntity>& entity);
 
   virtual MetricType::Type type() const override { return MetricType::kLag; }
 
@@ -1325,13 +1319,12 @@ class MillisLagPrototype : public MetricPrototype {
 // will be in charge of calculating the lag by doing now() - metric_timestamp_.
 class MillisLag : public Metric {
  public:
-  MillisLag(const MillisLagPrototype* proto, const scoped_refptr<server::Clock>& clock);
-
-  virtual uint64_t lag_ms() const {
-    auto now = clock_->Now().GetPhysicalValueMillis();
-    return now > timestamp_ms_ ? now - timestamp_ms_ : 0;
+  virtual int64_t lag_ms() const {
+    return std::max(static_cast<int64_t>(0),
+        static_cast<int64_t>(std::chrono::duration_cast<std::chrono::milliseconds>(
+            std::chrono::system_clock::now().time_since_epoch()).count()) - timestamp_ms_);
   }
-  virtual void UpdateTimestampInMilliseconds(uint64_t timestamp) {
+  virtual void UpdateTimestampInMilliseconds(int64_t timestamp) {
     timestamp_ms_ = timestamp;
   }
   virtual CHECKED_STATUS WriteAsJson(JsonWriter* w,
@@ -1340,24 +1333,28 @@ class MillisLag : public Metric {
       PrometheusWriter* writer, const MetricEntity::AttributeMap& attr,
       const MetricPrometheusOptions& opts) const override;
 
- protected:
-  const scoped_refptr<server::Clock>& clock_;
-
  private:
-  uint64_t timestamp_ms_;
+  friend class MetricEntity;
+  friend class AtomicMillisLag;
+  friend class MetricsTest;
+
+  explicit MillisLag(const MillisLagPrototype* proto);
+
+  int64_t timestamp_ms_;
 };
 
 class AtomicMillisLag : public MillisLag {
  public:
-  AtomicMillisLag(const MillisLagPrototype* proto, const scoped_refptr<server::Clock>& clock);
+  explicit AtomicMillisLag(const MillisLagPrototype* proto) : MillisLag(proto) {}
 
-  uint64_t lag_ms() const override {
-    auto now = clock_->Now().GetPhysicalValueMillis();
-    auto timestamp = atomic_timestamp_ms_.load(std::memory_order_acquire);
-    return now > timestamp ? now - timestamp : 0;
+  int64_t lag_ms() const override {
+    return std::max(static_cast<int64_t>(0),
+        static_cast<int64_t>(std::chrono::duration_cast<std::chrono::milliseconds>(
+            std::chrono::system_clock::now().time_since_epoch()).count()) -
+                atomic_timestamp_ms_.load(std::memory_order_acquire));
   }
 
-  void UpdateTimestampInMilliseconds(uint64_t timestamp) override {
+  void UpdateTimestampInMilliseconds(int64_t timestamp) override {
     atomic_timestamp_ms_.store(timestamp, std::memory_order_release);
   }
 
@@ -1375,8 +1372,7 @@ class AtomicMillisLag : public MillisLag {
   }
 
  protected:
-  std::atomic<uint64_t> atomic_timestamp_ms_;
-
+  std::atomic<int64_t> atomic_timestamp_ms_;
  private:
   DISALLOW_COPY_AND_ASSIGN(AtomicMillisLag);
 };
@@ -1505,25 +1501,25 @@ inline scoped_refptr<Counter> MetricEntity::FindOrCreateCounter(
 }
 
 inline scoped_refptr<MillisLag> MetricEntity::FindOrCreateMillisLag(
-    const MillisLagPrototype* proto, const scoped_refptr<server::Clock>& clock) {
+    const MillisLagPrototype* proto) {
   CheckInstantiation(proto);
   std::lock_guard<simple_spinlock> l(lock_);
   scoped_refptr<MillisLag> m = down_cast<MillisLag*>(FindPtrOrNull(metric_map_, proto).get());
   if (!m) {
-    m = new MillisLag(proto, clock);
+    m = new MillisLag(proto);
     InsertOrDie(&metric_map_, proto, m);
   }
   return m;
 }
 
 inline scoped_refptr<AtomicMillisLag> MetricEntity::FindOrCreateAtomicMillisLag(
-     const MillisLagPrototype* proto, const scoped_refptr<server::Clock>& clock) {
+    const MillisLagPrototype* proto) {
   CheckInstantiation(proto);
   std::lock_guard<simple_spinlock> l(lock_);
   scoped_refptr<AtomicMillisLag> m = down_cast<AtomicMillisLag*>(
       FindPtrOrNull(metric_map_, proto).get());
   if (!m) {
-    m = new AtomicMillisLag(proto, clock);
+    m = new AtomicMillisLag(proto);
     InsertOrDie(&metric_map_, proto, m);
   }
   return m;

diff --git a/src/yb/util/physical_time.h b/src/yb/util/physical_time.h
@@ -21,7 +21,6 @@
 namespace yb {
 
 using MicrosTime = uint64_t;
-using MillisTime = uint64_t;
 
 struct PhysicalTime {
   MicrosTime time_point;