[#11294] Docdb : Support use of MonoTime for understanding latencies …

…better

Summary:
CoarseMonoTime only produces timestamp at a granularity of 1ms, which makes it cheaper to use than MonoTime. However, if we are doing perf experiments we may want a more fine grained break down instead.

```
e.g:

.. 1113 06:14:17.542610 (+     0us) inbound_call.cc:90] Created InboundCall
.. 1113 06:14:17.542610 (+     0us) service_pool.cc:180] Inserting onto call queue
.. 1113 06:14:17.542610 (+     0us) service_pool.cc:261] Handling call Write
.. 1113 06:14:17.542610 (+     0us) tablet_service.cc:1591] Start Write
.. 1113 06:14:17.544610 (+  2000us) tablet.cc:2019] AcquireLocksAndPerformDocOperations
.. 1113 06:14:17.544610 (+     0us) tablet.cc:3776] Acquiring write permit
.. 1113 06:14:17.544610 (+     0us) operation_counter.cc:187] ScopedRWOperation Tablet schema
.. 1113 06:14:17.544610 (+     0us) tablet.cc:3777] Acquiring write permit done
.. 1113 06:14:17.544610 (+     0us) operation_counter.cc:199] Reset null
.. 1113 06:14:17.544610 (+     0us) operation_counter.cc:199] Reset null
.. 1113 06:14:17.544610 (+     0us) operation_counter.cc:187] ScopedRWOperation RocksDB non-abortable read/write operations
.. 1113 06:14:17.544610 (+     0us) operation_counter.cc:199] Reset null
.. 1113 06:14:17.544610 (+     0us) shared_lock_manager.cc:255] Locking a batch of 3 keys
.. 1113 06:14:17.544610 (+     0us) shared_lock_manager.cc:295] Acquired a lock batch of 3 keys
.. 1113 06:14:17.544610 (+     0us) conflict_resolution.cc:966] ResolveTransactionConflicts
.. 1113 06:14:17.545610 (+  1000us) conflict_resolution.cc:266] No conflicts.
.. 1113 06:14:17.545610 (+     0us) running_transaction.cc:210] SendStatusRequest : 52ec72c4-c941-4f40-96ad-3478a3ca0528
.. 1113 06:14:17.545610 (+     0us) operation_counter.cc:199] Reset null
.. 1113 06:14:17.545610 (+     0us) operation_counter.cc:199] Reset RocksDB non-abortable read/write operations
.. 1113 06:14:17.545610 (+     0us) operation_counter.cc:199] Reset Tablet schema
.. 1113 06:14:17.545610 (+     0us) tablet.cc:3599] self->TransactionalConflictsResolved
.. 1113 06:14:17.545610 (+     0us) conflict_resolution.cc:973] resolver->Resolve done
```

This diff introduces a flag for using MonoTime instead of CoarseMonoTime

The default is to still use CoarseMonoTime to avoid any perf degradation.

Test Plan: Jenkins

Reviewers: rsami

Reviewed By: rsami

Subscribers: ybase

Differential Revision: https://phabricator.dev.yugabyte.com/D14481

src/yb/rpc/inbound_call.cc

@@ -88,12 +88,8 @@ InboundCall::InboundCall(ConnectionPtr conn, RpcMetrics* rpc_metrics,
 
 InboundCall::~InboundCall() {
   TRACE_TO(trace_, "Destroying InboundCall");
-  if (trace_->must_print()) {
-    LOG(INFO) << "Tracing op: \n " << trace_->DumpToString(true);
-  } else {
-    YB_LOG_IF_EVERY_N(INFO, FLAGS_print_trace_every > 0, FLAGS_print_trace_every)
-        << "Tracing op: \n " << trace_->DumpToString(true);
-  }
+  YB_LOG_IF_EVERY_N(INFO, FLAGS_print_trace_every > 0, FLAGS_print_trace_every)
+      << "Tracing op: \n " << trace_->DumpToString(true);
   DecrementGauge(rpc_metrics_->inbound_calls_alive);
 }
 

src/yb/util/trace.cc

@@ -52,6 +52,12 @@ DEFINE_bool(enable_tracing, false, "Flag to enable/disable tracing across the co
 TAG_FLAG(enable_tracing, advanced);
 TAG_FLAG(enable_tracing, runtime);
 
+DEFINE_bool(use_monotime_for_traces, false, "Flag to enable use of MonoTime::Now() instead of "
+    "CoarseMonoClock::Now(). CoarseMonoClock is much cheaper so it is better to use it. However "
+    "if we need more accurate sub-millisecond level breakdown, we could use MonoTime.");
+TAG_FLAG(use_monotime_for_traces, advanced);
+TAG_FLAG(use_monotime_for_traces, runtime);
+
 DEFINE_int32(tracing_level, 0, "verbosity levels (like --v) up to which tracing is enabled.");
 TAG_FLAG(tracing_level, advanced);
 TAG_FLAG(tracing_level, runtime);

src/yb/util/trace.h

@@ -52,6 +52,7 @@
 #include "yb/util/monotime.h"
 
 DECLARE_bool(enable_tracing);
+DECLARE_bool(use_monotime_for_traces);
 DECLARE_int32(tracing_level);
 
 // Adopt a Trace on the current thread for the duration of the current
@@ -60,22 +61,36 @@ DECLARE_int32(tracing_level);
 // 't' should be a Trace* pointer.
 #define ADOPT_TRACE(t) yb::ScopedAdoptTrace _adopt_trace(t);
 
+// Like the above, but takes the trace pointer as an explicit argument.
+#define TRACE_TO_WITH_TIME(trace, time, format, substitutions...) \
+  do { \
+    if (GetAtomicFlag(&FLAGS_enable_tracing)) { \
+      if ((trace)) { \
+        (trace)->SubstituteAndTrace( \
+            __FILE__, __LINE__, (time), (format), ##substitutions); \
+      } \
+    } \
+  } while (0)
+
+#define VTRACE_TO(level, trace, format, substitutions...) \
+  do { \
+    if (GetAtomicFlag(&FLAGS_enable_tracing) && level <= GetAtomicFlag(&FLAGS_tracing_level)) { \
+      const bool use_fine_ts = GetAtomicFlag(&FLAGS_use_monotime_for_traces); \
+      auto time = (use_fine_ts ? ToCoarse(MonoTime::Now()) : CoarseMonoClock::Now()); \
+      TRACE_TO_WITH_TIME(trace, time, format, ##substitutions); \
+    } \
+  } while (0)
+
+#define TRACE_TO(trace, format, substitutions...) \
+  VTRACE_TO(0, (trace), (format), ##substitutions)
+
 // Issue a trace message, if tracing is enabled in the current thread.
 // and the current tracing level flag is >= the specified level.
 // See Trace::SubstituteAndTrace for arguments.
 // Example:
 //  VTRACE(1, "Acquired timestamp $0", timestamp);
 #define VTRACE(level, format, substitutions...) \
-  do { \
-    if (GetAtomicFlag(&FLAGS_enable_tracing) && \
-            level <= GetAtomicFlag(&FLAGS_tracing_level)) { \
-      yb::Trace* _trace = Trace::CurrentTrace(); \
-      if (_trace) { \
-        _trace->SubstituteAndTrace(__FILE__, __LINE__, CoarseMonoClock::Now(), (format),  \
-          ##substitutions); \
-      } \
-    } \
-  } while (0)
+  VTRACE_TO(level, Trace::CurrentTrace(), format, ##substitutions)
 
 // Issue a trace message, if tracing is enabled in the current thread.
 // See Trace::SubstituteAndTrace for arguments.
@@ -87,28 +102,6 @@ DECLARE_int32(tracing_level);
 #define TRACE_FUNC() \
   TRACE(__func__)
 
-// Like the above, but takes the trace pointer as an explicit argument.
-#define VTRACE_TO(level, trace, format, substitutions...) \
-  do { \
-    if (GetAtomicFlag(&FLAGS_enable_tracing) && \
-            level <= GetAtomicFlag(&FLAGS_tracing_level)) { \
-      (trace)->SubstituteAndTrace( \
-          __FILE__, __LINE__, CoarseMonoClock::Now(), (format), ##substitutions); \
-    } \
-  } while (0)
-
-#define TRACE_TO(trace, format, substitutions...) \
-  VTRACE_TO(0, (trace), (format), ##substitutions)
-
-// Like the above, but takes the trace pointer as an explicit argument.
-#define TRACE_TO_WITH_TIME(trace, time, format, substitutions...) \
-  do { \
-    if (GetAtomicFlag(&FLAGS_enable_tracing)) { \
-      (trace)->SubstituteAndTrace( \
-          __FILE__, __LINE__, (time), (format), ##substitutions); \
-    } \
-  } while (0)
-
 #define PLAIN_TRACE_TO(trace, message) \
   do { \
     if (GetAtomicFlag(&FLAGS_enable_tracing)) { \