Skip to content

Commit

Permalink
[#20335] DocDB: Use MonoClock for write query metric
Browse files Browse the repository at this point in the history
Summary:
`CoarseMonoClock` time has been found to move backwards in time. This is likely due to its reliance
on clock `jiffies` which can overflow, and by default is set to `INITIAL_JIFFIES` to force an overflow
5minutes after the machine boots up.

The write query metric `kQlWriteLatency` requires microsecond precision which is not provided by `CoarseMonoClock`.
This diff switches the write query duration to use `MonoClock` which provided nanosecond granularity.
This is not a frequent operation call so the impact from this is minimal.
Jira: DB-9320

Test Plan: TestMonoTime.DontMoveBackwards

Reviewers: rthallam, qhu, esheng

Reviewed By: rthallam, esheng

Subscribers: ybase

Differential Revision: https://phorge.dev.yugabyte.com/D37866
  • Loading branch information
hari90 committed Sep 11, 2024
1 parent 31da65b commit 798db14
Show file tree
Hide file tree
Showing 3 changed files with 39 additions and 3 deletions.
5 changes: 3 additions & 2 deletions src/yb/tablet/write_query.cc
Original file line number Diff line number Diff line change
Expand Up @@ -197,7 +197,7 @@ WriteQuery::WriteQuery(
context_(context),
rpc_context_(rpc_context),
response_(response),
start_time_(CoarseMonoClock::Now()),
start_time_(MonoTime::Now()),
execute_mode_(ExecuteMode::kSimple) {
IncrementActiveWriteQueryObjectsBy(1);
}
Expand Down Expand Up @@ -308,7 +308,8 @@ void WriteQuery::Finished(WriteOperation* operation, const Status& status) {
TabletMetrics* metrics = tablet->metrics();
if (metrics) {
auto op_duration_usec =
make_unsigned(MonoDelta(CoarseMonoClock::now() - start_time_).ToMicroseconds());
make_unsigned(MonoDelta(MonoTime::Now() - start_time_).ToMicroseconds());

metrics->Increment(tablet::TabletEventStats::kQlWriteLatency, op_duration_usec);
}
}
Expand Down
2 changes: 1 addition & 1 deletion src/yb/tablet/write_query.h
Original file line number Diff line number Diff line change
Expand Up @@ -218,7 +218,7 @@ class WriteQuery {
tserver::WriteResponsePB* response_;

// this transaction's start time
CoarseTimePoint start_time_;
MonoTime start_time_;

HybridTime restart_read_ht_;

Expand Down
35 changes: 35 additions & 0 deletions src/yb/util/monotime-test.cc
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,7 @@
#include "yb/util/logging.h"
#include <gtest/gtest.h>

#include "yb/util/test_thread_holder.h"
#include "yb/util/test_util.h"

using namespace std::literals;
Expand Down Expand Up @@ -299,4 +300,38 @@ TEST(TestMonoTime, ToStringRelativeToNow) {
ASSERT_EQ(ToString(t), ToStringRelativeToNow(t, CoarseTimePoint::max()));
}

// Make sure the MonoTime::Now() value does not move backwards.
// Run multiple threads to increase the chance of catching the issue.
// Run for 30 seconds.
TEST(TestMonoTime, DontMoveBackwards) {
// Make sure we are using a steady clock for MonoTime.
ASSERT_TRUE(std::chrono::steady_clock::is_steady);

LOG(WARNING) << "Now: " << MonoTime::Now().ToSteadyTimePoint().time_since_epoch().count();

std::atomic<bool> stop_flag{false};

auto t = [&stop_flag]() {
auto old = MonoTime::Now();
while (!stop_flag.load(std::memory_order_acquire)) {
auto now = MonoTime::Now();
ASSERT_GE(now, old) << "Time moved back!! "
<< " Old:" << old.ToSteadyTimePoint().time_since_epoch().count()
<< ", Now:" << old.ToSteadyTimePoint().time_since_epoch().count();
old = now;
}
};

TestThreadHolder holder;
holder.AddThreadFunctor(t);
holder.AddThreadFunctor(t);
holder.AddThreadFunctor(t);
holder.AddThreadFunctor(t);

SleepFor(MonoDelta::FromSeconds(30));
stop_flag.store(true, std::memory_order_release);

holder.JoinAll();
}

} // namespace yb

0 comments on commit 798db14

Please sign in to comment.