[counters] Fix reentrant timers for V8.Execute

This CL fixes a long standing issue where reentering TimedHistograms
scopes would cause spurious measurements. Only the non-nested scopes
yielded correct results.

Due to the changed numbers, the V8.Execute histogram is renamed to
V8.ExecuteMicroSeconds. Note that this histogram is also guarded
behind the --slow-histograms flag due to the additional overhead.

Unlike before, it does no longer include time for external callbacks
and only measures self time. The following example illustrates the
new behaviour:

1. Enter V8:           |--+.......+--| self-time: 4 units (reported)
2. Exit V8 (callback):    |-+...+-|    self-time: 2 units (ignored)
3. Re-enter V8:             |---|      self-time: 3 units (reported)

This would result in 2 histogram entries with 4 time units for the first
V8 slice and 3 units for the nested part. Note that the callback time
itself is ignored.

This CL attempts to clean up how TimedHistograms work:
- Histogram: the base class
- TimedHistograms: used for time-related histograms that are not nested
- NestedTimeHistograms: Extends TimedHistograms and is used for nested
  histograms

This CL changes Histograms to not measure time themselves. Measurements
happen in the *HistogramScopes:
- BaseTimedHistogramScope: Base functionality
- TimedHistogramScope: For non-nested measurements
- NestedTimedHistogramScope: For nested measurements
- PauseNestedTimedHistogramScope: Ignore time during a given scope.
  This is used to pause timers during callbacks.

Additional changes:
- ExternalCallbackScope now contains a PauseNestedTimedHistogramScope
  and always sets VMState<EXTERNAL>

Bug: v8:11946
Change-Id: I45e4b7ff77b5948b605dd50539044cb26222fa21
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3001345Reviewed-by: Omer Katz <omerkatz@chromium.org>
Reviewed-by: Thibaud Michaud <thibaudm@chromium.org>
Reviewed-by: Victor Gomes <victorgomes@chromium.org>
Reviewed-by: Leszek Swirski <leszeks@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/master@{#76111}

BUILD.bazel

@@ -1411,6 +1411,7 @@ filegroup(
         "src/logging/counters-definitions.h",
         "src/logging/counters.cc",
         "src/logging/counters.h",
+        "src/logging/counters-scopes.h",
         "src/logging/local-logger.cc",
         "src/logging/local-logger.h",
         "src/logging/log-inl.h",

BUILD.gn

@@ -2829,6 +2829,7 @@ v8_header_set("v8_internal_headers") {
     "src/libsampler/sampler.h",
     "src/logging/code-events.h",
     "src/logging/counters-definitions.h",
+    "src/logging/counters-scopes.h",
     "src/logging/counters.h",
     "src/logging/local-logger.h",
     "src/logging/log-inl.h",

src/api/api-arguments-inl.h

@@ -76,7 +76,6 @@ inline JSReceiver FunctionCallbackArguments::holder() {
           CALLBACK_INFO, RECEIVER, Debug::k##ACCESSOR_KIND)) {           \
     return RETURN_VALUE();                                               \
   }                                                                      \
-  VMState<EXTERNAL> state(ISOLATE);                                      \
   ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F));           \
   PropertyCallbackInfo<API_RETURN_TYPE> callback_info(values_);
 
@@ -85,7 +84,6 @@ inline JSReceiver FunctionCallbackArguments::holder() {
   if (ISOLATE->debug_execution_mode() == DebugInfo::kSideEffects) {            \
     return RETURN_VALUE();                                                     \
   }                                                                            \
-  VMState<EXTERNAL> state(ISOLATE);                                            \
   ExternalCallbackScope call_scope(ISOLATE, FUNCTION_ADDR(F));                 \
   PropertyCallbackInfo<API_RETURN_TYPE> callback_info(values_);
 
@@ -149,7 +147,6 @@ Handle<Object> FunctionCallbackArguments::Call(CallHandlerInfo handler) {
           Debug::kNotAccessor)) {
     return Handle<Object>();
   }
-  VMState<EXTERNAL> state(isolate);
   ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
   FunctionCallbackInfo<v8::Value> info(values_, argv_, argc_);
   f(info);

src/api/api.cc

@@ -58,7 +58,7 @@
 #include "src/init/v8.h"
 #include "src/json/json-parser.h"
 #include "src/json/json-stringifier.h"
-#include "src/logging/counters.h"
+#include "src/logging/counters-scopes.h"
 #include "src/logging/metrics.h"
 #include "src/logging/runtime-call-stats-scope.h"
 #include "src/logging/tracing-flags.h"
@@ -1967,10 +1967,11 @@ MaybeLocal<Value> Script::Run(Local<Context> context) {
   TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute");
   ENTER_V8(isolate, context, Script, Run, MaybeLocal<Value>(),
            InternalEscapableScope);
-  i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
+  i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
+  i::NestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute_precise());
   i::AggregatingHistogramTimerScope histogram_timer(
       isolate->counters()->compile_lazy());
-  i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
   auto fun = i::Handle<i::JSFunction>::cast(Utils::OpenHandle(this));
 
   // TODO(crbug.com/1193459): remove once ablation study is completed
@@ -2293,9 +2294,10 @@ MaybeLocal<Value> Module::Evaluate(Local<Context> context) {
   TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute");
   ENTER_V8(isolate, context, Module, Evaluate, MaybeLocal<Value>(),
            InternalEscapableScope);
-  i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
-  i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy());
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
+  i::NestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute_precise());
+  i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy());
 
   i::Handle<i::Module> self = Utils::OpenHandle(this);
   Utils::ApiCheck(self->status() >= i::Module::kInstantiated,
@@ -4950,6 +4952,8 @@ MaybeLocal<Value> Object::CallAsFunction(Local<Context> context,
   ENTER_V8(isolate, context, Object, CallAsFunction, MaybeLocal<Value>(),
            InternalEscapableScope);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
+  i::NestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute_precise());
   auto self = Utils::OpenHandle(this);
   auto recv_obj = Utils::OpenHandle(*recv);
   STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
@@ -4968,6 +4972,8 @@ MaybeLocal<Value> Object::CallAsConstructor(Local<Context> context, int argc,
   ENTER_V8(isolate, context, Object, CallAsConstructor, MaybeLocal<Value>(),
            InternalEscapableScope);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
+  i::NestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute_precise());
   auto self = Utils::OpenHandle(this);
   STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
   i::Handle<i::Object>* args = reinterpret_cast<i::Handle<i::Object>*>(argv);
@@ -5005,6 +5011,8 @@ MaybeLocal<Object> Function::NewInstanceWithSideEffectType(
   ENTER_V8(isolate, context, Function, NewInstance, MaybeLocal<Object>(),
            InternalEscapableScope);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
+  i::NestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute_precise());
   auto self = Utils::OpenHandle(this);
   STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Handle<i::Object>));
   bool should_set_has_no_side_effect =
@@ -5054,6 +5062,8 @@ MaybeLocal<v8::Value> Function::Call(Local<Context> context,
   ENTER_V8(isolate, context, Function, Call, MaybeLocal<Value>(),
            InternalEscapableScope);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
+  i::NestedTimedHistogramScope execute_timer(
+      isolate->counters()->execute_precise());
   auto self = Utils::OpenHandle(this);
   Utils::ApiCheck(!self.is_null(), "v8::Function::Call",
                   "Function to be called is a null pointer");
@@ -8884,7 +8894,7 @@ bool Isolate::IdleNotificationDeadline(double deadline_in_seconds) {
 void Isolate::LowMemoryNotification() {
   i::Isolate* isolate = reinterpret_cast<i::Isolate*>(this);
   {
-    i::HistogramTimerScope idle_notification_scope(
+    i::NestedTimedHistogramScope idle_notification_scope(
         isolate->counters()->gc_low_memory_notification());
     TRACE_EVENT0("v8", "V8.GCLowMemoryNotification");
     isolate->heap()->CollectAllAvailableGarbage(
@@ -10230,7 +10240,6 @@ void InvokeAccessorGetterCallback(
   Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate());
   RCS_SCOPE(isolate, RuntimeCallCounterId::kAccessorGetterCallback);
   Address getter_address = reinterpret_cast<Address>(getter);
-  VMState<EXTERNAL> state(isolate);
   ExternalCallbackScope call_scope(isolate, getter_address);
   getter(property, info);
 }
@@ -10240,7 +10249,6 @@ void InvokeFunctionCallback(const v8::FunctionCallbackInfo<v8::Value>& info,
   Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate());
   RCS_SCOPE(isolate, RuntimeCallCounterId::kFunctionCallback);
   Address callback_address = reinterpret_cast<Address>(callback);
-  VMState<EXTERNAL> state(isolate);
   ExternalCallbackScope call_scope(isolate, callback_address);
   callback(info);
 }

src/base/platform/elapsed-timer.h

@@ -14,15 +14,20 @@ namespace base {
 class ElapsedTimer final {
  public:
 #ifdef DEBUG
-  ElapsedTimer() : started_(false) {}
+  ElapsedTimer() : start_ticks_(), started_(false) {}
+#else
+  ElapsedTimer() : start_ticks_() {}
 #endif
 
   // Starts this timer. Once started a timer can be checked with
   // |Elapsed()| or |HasExpired()|, and may be restarted using |Restart()|.
   // This method must not be called on an already started timer.
-  void Start() {
+  void Start() { Start(Now()); }
+
+  void Start(TimeTicks now) {
+    DCHECK(!now.IsNull());
     DCHECK(!IsStarted());
-    start_ticks_ = Now();
+    set_start_ticks(now);
 #ifdef DEBUG
     started_ = true;
 #endif
@@ -33,7 +38,7 @@ class ElapsedTimer final {
   // started before.
   void Stop() {
     DCHECK(IsStarted());
-    start_ticks_ = TimeTicks();
+    set_start_ticks(TimeTicks());
 #ifdef DEBUG
     started_ = false;
 #endif
@@ -52,21 +57,51 @@ class ElapsedTimer final {
   // and then starting the timer again, but does so in one single operation,
   // avoiding the need to obtain the clock value twice. It may only be called
   // on a previously started timer.
-  TimeDelta Restart() {
+  TimeDelta Restart() { return Restart(Now()); }
+
+  TimeDelta Restart(TimeTicks now) {
+    DCHECK(!now.IsNull());
     DCHECK(IsStarted());
-    TimeTicks ticks = Now();
-    TimeDelta elapsed = ticks - start_ticks_;
+    TimeDelta elapsed = now - start_ticks_;
     DCHECK_GE(elapsed.InMicroseconds(), 0);
-    start_ticks_ = ticks;
+    set_start_ticks(now);
     DCHECK(IsStarted());
     return elapsed;
   }
 
+  void Pause() { Pause(Now()); }
+
+  void Pause(TimeTicks now) {
+    TimeDelta elapsed = Elapsed(now);
+    DCHECK(IsStarted());
+    DCHECK(!is_paused_);
+#ifdef DEBUG
+    is_paused_ = true;
+#endif
+    set_paused_elapsed(elapsed);
+  }
+
+  void Resume() { Resume(Now()); }
+
+  void Resume(TimeTicks now) {
+    DCHECK(!now.IsNull());
+    DCHECK(IsStarted());
+    TimeDelta elapsed = paused_elapsed();
+#ifdef DEBUG
+    is_paused_ = false;
+#endif
+    set_start_ticks(now - elapsed);
+    DCHECK(IsStarted());
+  }
+
   // Returns the time elapsed since the previous start. This method may only
   // be called on a previously started timer.
-  TimeDelta Elapsed() const {
+  TimeDelta Elapsed() const { return Elapsed(Now()); }
+
+  TimeDelta Elapsed(TimeTicks now) const {
+    DCHECK(!now.IsNull());
     DCHECK(IsStarted());
-    TimeDelta elapsed = Now() - start_ticks_;
+    TimeDelta elapsed = now - start_ticks();
     DCHECK_GE(elapsed.InMicroseconds(), 0);
     return elapsed;
   }
@@ -86,9 +121,34 @@ class ElapsedTimer final {
     return now;
   }
 
+  TimeDelta paused_elapsed() {
+    DCHECK(IsStarted());
+    DCHECK(is_paused_);
+    return paused_elapsed_;
+  }
+
+  void set_paused_elapsed(TimeDelta delta) {
+    DCHECK(IsStarted());
+    DCHECK(is_paused_);
+    paused_elapsed_ = delta;
+  }
+
+  TimeTicks start_ticks() const {
+    DCHECK(!is_paused_);
+    return start_ticks_;
+  }
+  void set_start_ticks(TimeTicks start_ticks) {
+    DCHECK(!is_paused_);
+    start_ticks_ = start_ticks;
+  }
+
+  union {
     TimeTicks start_ticks_;
+    TimeDelta paused_elapsed_;
+  };
 #ifdef DEBUG
   bool started_;
+  bool is_paused_ = false;
 #endif
 };
 

src/codegen/compiler.cc

@@ -44,7 +44,7 @@
 #include "src/heap/parked-scope.h"
 #include "src/init/bootstrapper.h"
 #include "src/interpreter/interpreter.h"
-#include "src/logging/counters.h"
+#include "src/logging/counters-scopes.h"
 #include "src/logging/log-inl.h"
 #include "src/logging/runtime-call-stats-scope.h"
 #include "src/objects/feedback-cell-inl.h"
@@ -1354,10 +1354,10 @@ MaybeHandle<SharedFunctionInfo> CompileToplevel(
   // Measure how long it takes to do the compilation; only take the
   // rest of the function into account to avoid overlap with the
   // parsing statistics.
-  HistogramTimer* rate = parse_info->flags().is_eval()
+  NestedTimedHistogram* rate = parse_info->flags().is_eval()
                                    ? isolate->counters()->compile_eval()
                                    : isolate->counters()->compile();
-  HistogramTimerScope timer(rate);
+  NestedTimedHistogramScope timer(rate);
   TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
                parse_info->flags().is_eval() ? "V8.CompileEval" : "V8.Compile");
 
@@ -1726,7 +1726,8 @@ bool Compiler::CollectSourcePositions(Isolate* isolate,
   RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileCollectSourcePositions);
   TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
                "V8.CollectSourcePositions");
-  HistogramTimerScope timer(isolate->counters()->collect_source_positions());
+  NestedTimedHistogramScope timer(
+      isolate->counters()->collect_source_positions());
 
   // Set up parse info.
   UnoptimizedCompileFlags flags =
@@ -2248,14 +2249,14 @@ MaybeHandle<JSFunction> Compiler::GetFunctionFromEval(
 // (via v8::Isolate::SetAllowCodeGenerationFromStringsCallback)
 bool CodeGenerationFromStringsAllowed(Isolate* isolate, Handle<Context> context,
                                       Handle<String> source) {
+  RCS_SCOPE(isolate, RuntimeCallCounterId::kCodeGenerationFromStringsCallbacks);
   DCHECK(context->allow_code_gen_from_strings().IsFalse(isolate));
   DCHECK(isolate->allow_code_gen_callback());
-
-  // Callback set. Let it decide if code generation is allowed.
-  VMState<EXTERNAL> state(isolate);
-  RCS_SCOPE(isolate, RuntimeCallCounterId::kCodeGenerationFromStringsCallbacks);
   AllowCodeGenerationFromStringsCallback callback =
       isolate->allow_code_gen_callback();
+  ExternalCallbackScope external_callback(isolate,
+                                          reinterpret_cast<Address>(callback));
+  // Callback set. Let it decide if code generation is allowed.
   return callback(v8::Utils::ToLocal(context), v8::Utils::ToLocal(source));
 }
 
@@ -2439,8 +2440,7 @@ struct ScriptCompileTimerScope {
   explicit ScriptCompileTimerScope(
       Isolate* isolate, ScriptCompiler::NoCacheReason no_cache_reason)
       : isolate_(isolate),
-        all_scripts_histogram_scope_(isolate->counters()->compile_script(),
-                                     true),
+        all_scripts_histogram_scope_(isolate->counters()->compile_script()),
         no_cache_reason_(no_cache_reason),
         hit_isolate_cache_(false),
         producing_code_cache_(false),
@@ -2479,7 +2479,7 @@ struct ScriptCompileTimerScope {
   LazyTimedHistogramScope histogram_scope_;
   // TODO(leszeks): This timer is the sum of the other times, consider removing
   // it to save space.
-  HistogramTimerScope all_scripts_histogram_scope_;
+  NestedTimedHistogramScope all_scripts_histogram_scope_;
   ScriptCompiler::NoCacheReason no_cache_reason_;
   bool hit_isolate_cache_;
   bool producing_code_cache_;
@@ -2845,7 +2845,8 @@ MaybeHandle<SharedFunctionInfo> Compiler::GetSharedFunctionInfoForScript(
     } else if (can_consume_code_cache) {
       compile_timer.set_consuming_code_cache();
       // Then check cached code provided by embedder.
-      HistogramTimerScope timer(isolate->counters()->compile_deserialize());
+      NestedTimedHistogramScope timer(
+          isolate->counters()->compile_deserialize());
       RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileDeserialize);
       TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
                    "V8.CompileDeserialize");
@@ -2932,7 +2933,7 @@ MaybeHandle<JSFunction> Compiler::GetWrappedFunction(
   if (can_consume_code_cache) {
     compile_timer.set_consuming_code_cache();
     // Then check cached code provided by embedder.
-    HistogramTimerScope timer(isolate->counters()->compile_deserialize());
+    NestedTimedHistogramScope timer(isolate->counters()->compile_deserialize());
     RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileDeserialize);
     TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"),
                  "V8.CompileDeserialize");

src/execution/vm-state-inl.h

@@ -54,7 +54,9 @@ VMState<Tag>::~VMState() {
 ExternalCallbackScope::ExternalCallbackScope(Isolate* isolate, Address callback)
     : isolate_(isolate),
       callback_(callback),
-      previous_scope_(isolate->external_callback_scope()) {
+      previous_scope_(isolate->external_callback_scope()),
+      vm_state_(isolate),
+      pause_timed_histogram_scope_(isolate->counters()->execute_precise()) {
 #ifdef USE_SIMULATOR
   scope_address_ = Simulator::current(isolate)->get_sp();
 #endif

src/execution/vm-state.h

@@ -7,6 +7,7 @@
 
 #include "include/v8.h"
 #include "src/common/globals.h"
+#include "src/logging/counters-scopes.h"
 
 namespace v8 {
 namespace internal {
@@ -46,6 +47,8 @@ class V8_NODISCARD ExternalCallbackScope {
   Isolate* isolate_;
   Address callback_;
   ExternalCallbackScope* previous_scope_;
+  VMState<EXTERNAL> vm_state_;
+  PauseNestedTimedHistogramScope pause_timed_histogram_scope_;
 #ifdef USE_SIMULATOR
   Address scope_address_;
 #endif

src/heap/heap.cc

@@ -3767,7 +3767,7 @@ void Heap::FinalizeIncrementalMarkingIncrementally(
   DevToolsTraceEventScope devtools_trace_event_scope(
       this, "MajorGC", "incremental finalization step");
 
-  HistogramTimerScope incremental_marking_scope(
+  NestedTimedHistogramScope incremental_marking_scope(
       isolate()->counters()->gc_incremental_marking_finalize());
   TRACE_EVENT1("v8", "V8.GCIncrementalMarkingFinalize", "epoch", epoch_full());
   TRACE_GC_EPOCH(tracer(), GCTracer::Scope::MC_INCREMENTAL_FINALIZE,
@@ -4001,7 +4001,7 @@ bool Heap::IdleNotification(double deadline_in_seconds) {
   double deadline_in_ms =
       deadline_in_seconds *
       static_cast<double>(base::Time::kMillisecondsPerSecond);
-  HistogramTimerScope idle_notification_scope(
+  NestedTimedHistogramScope idle_notification_scope(
       isolate_->counters()->gc_idle_notification());
   TRACE_EVENT0("v8", "V8.GCIdleNotification");
   double start_ms = MonotonicallyIncreasingTimeInMs();

src/heap/incremental-marking.cc

@@ -194,7 +194,7 @@ void IncrementalMarking::Start(GarbageCollectionReason gc_reason) {
 
   counters->incremental_marking_reason()->AddSample(
       static_cast<int>(gc_reason));
-  HistogramTimerScope incremental_marking_scope(
+  NestedTimedHistogramScope incremental_marking_scope(
       counters->gc_incremental_marking_start());
   TRACE_EVENT1("v8", "V8.GCIncrementalMarkingStart", "epoch",
                heap_->epoch_full());
@@ -784,7 +784,7 @@ StepResult CombineStepResults(StepResult a, StepResult b) {
 StepResult IncrementalMarking::AdvanceWithDeadline(
     double deadline_in_ms, CompletionAction completion_action,
     StepOrigin step_origin) {
-  HistogramTimerScope incremental_marking_scope(
+  NestedTimedHistogramScope incremental_marking_scope(
       heap_->isolate()->counters()->gc_incremental_marking());
   TRACE_EVENT1("v8", "V8.GCIncrementalMarking", "epoch", heap_->epoch_full());
   TRACE_GC_EPOCH(heap_->tracer(), GCTracer::Scope::MC_INCREMENTAL,
@@ -889,7 +889,7 @@ void IncrementalMarking::AdvanceOnAllocation() {
       state_ != MARKING || heap_->always_allocate()) {
     return;
   }
-  HistogramTimerScope incremental_marking_scope(
+  NestedTimedHistogramScope incremental_marking_scope(
       heap_->isolate()->counters()->gc_incremental_marking());
   TRACE_EVENT0("v8", "V8.GCIncrementalMarking");
   TRACE_GC_EPOCH(heap_->tracer(), GCTracer::Scope::MC_INCREMENTAL,

src/heap/safepoint.cc

@@ -14,6 +14,7 @@
 #include "src/heap/heap-inl.h"
 #include "src/heap/heap.h"
 #include "src/heap/local-heap.h"
+#include "src/logging/counters-scopes.h"
 
 namespace v8 {
 namespace internal {

src/logging/counters-definitions.h

@@ -102,7 +102,7 @@ namespace internal {
   /* The maximum of 100M backtracks takes roughly 2 seconds on my machine. */  \
   HR(regexp_backtracks, V8.RegExpBacktracks, 1, 100000000, 50)
 
-#define HISTOGRAM_TIMER_LIST(HT)                                               \
+#define NESTED_TIMED_HISTOGRAM_LIST(HT)                                       \
   /* Timer histograms, not thread safe: HT(name, caption, max, unit) */       \
   /* Garbage collection timers. */                                            \
   HT(gc_idle_notification, V8.GCIdleNotification, 10000, MILLISECOND)         \
@@ -128,9 +128,9 @@ namespace internal {
   HT(wasm_lazy_compile_time, V8.WasmLazyCompileTimeMicroSeconds, 100000000,   \
      MICROSECOND)
 
-#define HISTOGRAM_TIMER_LIST_SLOW(HT)                                          \
-  /* Total JavaScript execution time (including callbacks and runtime calls */ \
-  HT(execute, V8.Execute, 1000000, MICROSECOND)
+#define NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT)                               \
+  /* Total V8 time (including JS and runtime calls, exluding callbacks) */ \
+  HT(execute_precise, V8.ExecuteMicroSeconds, 1000000, MICROSECOND)
 
 #define TIMED_HISTOGRAM_LIST(HT)                                               \
   /* Timer histograms, thread safe: HT(name, caption, max, unit) */            \

src/logging/counters-scopes.h

+// Copyright 2021 the V8 project authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef V8_LOGGING_COUNTERS_SCOPES_H_
+#define V8_LOGGING_COUNTERS_SCOPES_H_
+
+#include "src/execution/isolate.h"
+#include "src/logging/counters.h"
+#include "src/logging/log.h"
+
+namespace v8 {
+namespace internal {
+
+class BaseTimedHistogramScope {
+ protected:
+  explicit BaseTimedHistogramScope(TimedHistogram* histogram)
+      : histogram_(histogram) {}
+
+  void Start() {
+    if (!histogram_->Enabled()) return;
+    DCHECK(histogram_->ToggleRunningState(true));
+    timer_.Start();
+  }
+
+  void Stop() {
+    if (!histogram_->Enabled()) return;
+    DCHECK(histogram_->ToggleRunningState(false));
+    histogram_->AddTimedSample(timer_.Elapsed());
+    timer_.Stop();
+  }
+
+  void LogStart(Isolate* isolate) {
+    Logger::CallEventLogger(isolate, histogram_->name(), Logger::START, true);
+  }
+
+  void LogEnd(Isolate* isolate) {
+    Logger::CallEventLogger(isolate, histogram_->name(), Logger::END, true);
+  }
+
+  base::ElapsedTimer timer_;
+  TimedHistogram* histogram_;
+};
+
+// Helper class for scoping a TimedHistogram.
+class V8_NODISCARD TimedHistogramScope : public BaseTimedHistogramScope {
+ public:
+  explicit TimedHistogramScope(TimedHistogram* histogram,
+                               Isolate* isolate = nullptr)
+      : BaseTimedHistogramScope(histogram), isolate_(isolate) {
+    Start();
+    if (isolate_) LogStart(isolate_);
+  }
+
+  ~TimedHistogramScope() {
+    Stop();
+    if (isolate_) LogEnd(isolate_);
+  }
+
+ private:
+  Isolate* const isolate_;
+
+  DISALLOW_IMPLICIT_CONSTRUCTORS(TimedHistogramScope);
+};
+
+enum class OptionalTimedHistogramScopeMode { TAKE_TIME, DONT_TAKE_TIME };
+
+// Helper class for scoping a TimedHistogram.
+// It will not take time for mode = DONT_TAKE_TIME.
+class V8_NODISCARD OptionalTimedHistogramScope
+    : public BaseTimedHistogramScope {
+ public:
+  OptionalTimedHistogramScope(TimedHistogram* histogram, Isolate* isolate,
+                              OptionalTimedHistogramScopeMode mode)
+      : BaseTimedHistogramScope(histogram), isolate_(isolate), mode_(mode) {
+    if (mode != OptionalTimedHistogramScopeMode::TAKE_TIME) return;
+    Start();
+    LogStart(isolate_);
+  }
+
+  ~OptionalTimedHistogramScope() {
+    if (mode_ != OptionalTimedHistogramScopeMode::TAKE_TIME) return;
+    Stop();
+    LogEnd(isolate_);
+  }
+
+ private:
+  Isolate* const isolate_;
+  const OptionalTimedHistogramScopeMode mode_;
+  DISALLOW_IMPLICIT_CONSTRUCTORS(OptionalTimedHistogramScope);
+};
+
+// Helper class for scoping a TimedHistogram, where the histogram is selected at
+// stop time rather than start time.
+class V8_NODISCARD LazyTimedHistogramScope : public BaseTimedHistogramScope {
+ public:
+  LazyTimedHistogramScope() : BaseTimedHistogramScope(nullptr) {
+    timer_.Start();
+  }
+  ~LazyTimedHistogramScope() {
+    // We should set the histogram before this scope exits.
+    Stop();
+  }
+
+  void set_histogram(TimedHistogram* histogram) {
+    DCHECK_IMPLIES(histogram->Enabled(), histogram->ToggleRunningState(true));
+    histogram_ = histogram;
+  }
+};
+
+// Helper class for scoping a NestedHistogramTimer.
+class V8_NODISCARD NestedTimedHistogramScope : public BaseTimedHistogramScope {
+ public:
+  explicit NestedTimedHistogramScope(NestedTimedHistogram* histogram)
+      : BaseTimedHistogramScope(histogram) {
+    Start();
+  }
+  ~NestedTimedHistogramScope() { Stop(); }
+
+ private:
+  friend NestedTimedHistogram;
+  friend PauseNestedTimedHistogramScope;
+
+  void Start() {
+    previous_scope_ = timed_histogram()->Enter(this);
+    if (histogram_->Enabled()) {
+      base::TimeTicks now = base::TimeTicks::HighResolutionNow();
+      if (previous_scope_) previous_scope_->Pause(now);
+      timer_.Start(now);
+    }
+    LogStart(timed_histogram()->counters()->isolate());
+  }
+
+  void Stop() {
+    timed_histogram()->Leave(previous_scope_);
+    if (histogram_->Enabled()) {
+      base::TimeTicks now = base::TimeTicks::HighResolutionNow();
+      histogram_->AddTimedSample(timer_.Elapsed(now));
+      timer_.Stop();
+      if (previous_scope_) previous_scope_->Resume(now);
+    }
+    LogEnd(timed_histogram()->counters()->isolate());
+  }
+
+  void Pause(base::TimeTicks now) {
+    DCHECK(histogram_->Enabled());
+    timer_.Pause(now);
+  }
+
+  void Resume(base::TimeTicks now) {
+    DCHECK(histogram_->Enabled());
+    timer_.Resume(now);
+  }
+
+  NestedTimedHistogram* timed_histogram() {
+    return static_cast<NestedTimedHistogram*>(histogram_);
+  }
+
+  NestedTimedHistogramScope* previous_scope_;
+};
+
+// Temporarily pause a NestedTimedHistogram when for instance leaving V8 for
+// external callbacks.
+class V8_NODISCARD PauseNestedTimedHistogramScope {
+ public:
+  explicit PauseNestedTimedHistogramScope(NestedTimedHistogram* histogram)
+      : histogram_(histogram) {
+    previous_scope_ = histogram_->Enter(nullptr);
+    if (isEnabled()) {
+      previous_scope_->Pause(base::TimeTicks::HighResolutionNow());
+    }
+  }
+  ~PauseNestedTimedHistogramScope() {
+    histogram_->Leave(previous_scope_);
+    if (isEnabled()) {
+      previous_scope_->Resume(base::TimeTicks::HighResolutionNow());
+    }
+  }
+
+ private:
+  bool isEnabled() const { return previous_scope_ && histogram_->Enabled(); }
+  NestedTimedHistogram* histogram_;
+  NestedTimedHistogramScope* previous_scope_;
+};
+
+}  // namespace internal
+}  // namespace v8
+
+#endif  // V8_LOGGING_COUNTERS_SCOPES_H_

src/logging/counters.cc

@@ -77,37 +77,27 @@ void* Histogram::CreateHistogram() const {
   return counters_->CreateHistogram(name_, min_, max_, num_buckets_);
 }
 
+void TimedHistogram::Stop(base::ElapsedTimer* timer) {
+  DCHECK(Enabled());
+  AddTimedSample(timer->Elapsed());
+  timer->Stop();
+}
+
 void TimedHistogram::AddTimedSample(base::TimeDelta sample) {
   if (Enabled()) {
-    int64_t sample_int = resolution_ == HistogramTimerResolution::MICROSECOND
+    int64_t sample_int = resolution_ == TimedHistogramResolution::MICROSECOND
                              ? sample.InMicroseconds()
                              : sample.InMilliseconds();
     AddSample(static_cast<int>(sample_int));
   }
 }
 
-void TimedHistogram::Start(base::ElapsedTimer* timer, Isolate* isolate) {
-  if (Enabled()) timer->Start();
-  if (isolate) Logger::CallEventLogger(isolate, name(), Logger::START, true);
-}
-
-void TimedHistogram::Stop(base::ElapsedTimer* timer, Isolate* isolate) {
-  if (Enabled()) {
-    base::TimeDelta delta = timer->Elapsed();
-    timer->Stop();
-    AddTimedSample(delta);
-  }
-  if (isolate != nullptr) {
-    Logger::CallEventLogger(isolate, name(), Logger::END, true);
-  }
-}
-
 void TimedHistogram::RecordAbandon(base::ElapsedTimer* timer,
                                    Isolate* isolate) {
   if (Enabled()) {
     DCHECK(timer->IsStarted());
     timer->Stop();
-    int64_t sample = resolution_ == HistogramTimerResolution::MICROSECOND
+    int64_t sample = resolution_ == TimedHistogramResolution::MICROSECOND
                          ? base::TimeDelta::Max().InMicroseconds()
                          : base::TimeDelta::Max().InMilliseconds();
     AddSample(static_cast<int>(sample));
@@ -117,6 +107,18 @@ void TimedHistogram::RecordAbandon(base::ElapsedTimer* timer,
   }
 }
 
+#ifdef DEBUG
+bool TimedHistogram::ToggleRunningState(bool expect_to_run) const {
+  static thread_local base::LazyInstance<
+      std::unordered_map<const TimedHistogram*, bool>>::type active_timer =
+      LAZY_INSTANCE_INITIALIZER;
+  bool is_running = (*active_timer.Pointer())[this];
+  DCHECK_NE(is_running, expect_to_run);
+  (*active_timer.Pointer())[this] = !is_running;
+  return true;
+}
+#endif
+
 Counters::Counters(Isolate* isolate)
     :
 #define SC(name, caption) name##_(this, "c:" #caption),
@@ -149,18 +151,19 @@ Counters::Counters(Isolate* isolate)
   const int DefaultTimedHistogramNumBuckets = 50;
 
   static const struct {
-    HistogramTimer Counters::*member;
+    NestedTimedHistogram Counters::*member;
     const char* caption;
     int max;
-    HistogramTimerResolution res;
-  } kHistogramTimers[] = {
+    TimedHistogramResolution res;
+  } kNestedTimedHistograms[] = {
 #define HT(name, caption, max, res) \
-  {&Counters::name##_, #caption, max, HistogramTimerResolution::res},
-      HISTOGRAM_TIMER_LIST(HT) HISTOGRAM_TIMER_LIST_SLOW(HT)
+  {&Counters::name##_, #caption, max, TimedHistogramResolution::res},
+      NESTED_TIMED_HISTOGRAM_LIST(HT) NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT)
 #undef HT
   };
-  for (const auto& timer : kHistogramTimers) {
-    this->*timer.member = HistogramTimer(timer.caption, 0, timer.max, timer.res,
+  for (const auto& timer : kNestedTimedHistograms) {
+    this->*timer.member =
+        NestedTimedHistogram(timer.caption, 0, timer.max, timer.res,
                              DefaultTimedHistogramNumBuckets, this);
   }
 
@@ -168,10 +171,10 @@ Counters::Counters(Isolate* isolate)
     TimedHistogram Counters::*member;
     const char* caption;
     int max;
-    HistogramTimerResolution res;
+    TimedHistogramResolution res;
   } kTimedHistograms[] = {
 #define HT(name, caption, max, res) \
-  {&Counters::name##_, #caption, max, HistogramTimerResolution::res},
+  {&Counters::name##_, #caption, max, TimedHistogramResolution::res},
       TIMED_HISTOGRAM_LIST(HT)
 #undef HT
   };
@@ -297,11 +300,11 @@ void Counters::ResetCreateHistogramFunction(CreateHistogramCallback f) {
 #undef HR
 
 #define HT(name, caption, max, res) name##_.Reset();
-  HISTOGRAM_TIMER_LIST(HT)
+  NESTED_TIMED_HISTOGRAM_LIST(HT)
 #undef HT
 
 #define HT(name, caption, max, res) name##_.Reset(FLAG_slow_histograms);
-  HISTOGRAM_TIMER_LIST_SLOW(HT)
+  NESTED_TIMED_HISTOGRAM_LIST_SLOW(HT)
 #undef HT
 
 #define HT(name, caption, max, res) name##_.Reset();

src/logging/log-inl.h

@@ -28,16 +28,6 @@ CodeEventListener::LogEventsAndTags Logger::ToNativeByScript(
   }
 }
 
-void Logger::CallEventLogger(Isolate* isolate, const char* name, StartEnd se,
-                             bool expose_to_api) {
-  if (isolate->event_logger()) {
-    if (isolate->event_logger() == DefaultEventLoggerSentinel) {
-      LOG(isolate, TimerEvent(se, name));
-    } else if (expose_to_api) {
-      isolate->event_logger()(name, se);
-    }
-  }
-}
 
 template <class TimerEvent>
 void TimerEventScope<TimerEvent>::LogTimerEvent(Logger::StartEnd se) {

src/logging/log.h

@@ -12,6 +12,7 @@
 
 #include "include/v8-profiler.h"
 #include "src/base/platform/elapsed-timer.h"
+#include "src/execution/isolate.h"
 #include "src/logging/code-events.h"
 #include "src/objects/objects.h"
 
@@ -273,8 +274,15 @@ class Logger : public CodeEventListener {
 
   static void DefaultEventLoggerSentinel(const char* name, int event) {}
 
-  V8_INLINE static void CallEventLogger(Isolate* isolate, const char* name,
-                                        StartEnd se, bool expose_to_api);
+  static void CallEventLogger(Isolate* isolate, const char* name, StartEnd se,
+                              bool expose_to_api) {
+    if (!isolate->event_logger()) return;
+    if (isolate->event_logger() == DefaultEventLoggerSentinel) {
+      LOG(isolate, TimerEvent(se, name));
+    } else if (expose_to_api) {
+      isolate->event_logger()(name, se);
+    }
+  }
 
   V8_EXPORT_PRIVATE bool is_logging();
 

src/parsing/parser.cc

@@ -516,8 +516,6 @@ void MaybeProcessSourceRanges(ParseInfo* parse_info, Expression* root,
 void Parser::ParseProgram(Isolate* isolate, Handle<Script> script,
                           ParseInfo* info,
                           MaybeHandle<ScopeInfo> maybe_outer_scope_info) {
-  // TODO(bmeurer): We temporarily need to pass allow_nesting = true here,
-  // see comment for HistogramTimerScope class.
   DCHECK_EQ(script->id(), flags().script_id());
 
   // It's OK to use the Isolate & counters here, since this function is only

src/snapshot/code-serializer.cc

@@ -14,7 +14,7 @@
 #include "src/heap/heap-inl.h"
 #include "src/heap/local-factory-inl.h"
 #include "src/heap/parked-scope.h"
-#include "src/logging/counters.h"
+#include "src/logging/counters-scopes.h"
 #include "src/logging/log.h"
 #include "src/logging/runtime-call-stats-scope.h"
 #include "src/objects/objects-inl.h"
@@ -48,7 +48,8 @@ ScriptCompiler::CachedData* CodeSerializer::Serialize(
     Handle<SharedFunctionInfo> info) {
   Isolate* isolate = info->GetIsolate();
   TRACE_EVENT_CALL_STATS_SCOPED(isolate, "v8", "V8.Execute");
-  HistogramTimerScope histogram_timer(isolate->counters()->compile_serialize());
+  NestedTimedHistogramScope histogram_timer(
+      isolate->counters()->compile_serialize());
   RCS_SCOPE(isolate, RuntimeCallCounterId::kCompileSerialize);
   TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), "V8.CompileSerialize");
 

src/wasm/function-compiler.cc

@@ -11,7 +11,7 @@
 #include "src/codegen/optimized-compilation-info.h"
 #include "src/compiler/wasm-compiler.h"
 #include "src/diagnostics/code-tracer.h"
-#include "src/logging/counters.h"
+#include "src/logging/counters-scopes.h"
 #include "src/logging/log.h"
 #include "src/utils/ostreams.h"
 #include "src/wasm/baseline/liftoff-compiler.h"

src/wasm/module-compiler.cc

@@ -17,7 +17,7 @@
 #include "src/base/utils/random-number-generator.h"
 #include "src/compiler/wasm-compiler.h"
 #include "src/heap/heap-inl.h"  // For CodeSpaceMemoryModificationScope.
-#include "src/logging/counters.h"
+#include "src/logging/counters-scopes.h"
 #include "src/logging/metrics.h"
 #include "src/objects/property-descriptor.h"
 #include "src/tasks/task-utils.h"

src/wasm/module-instantiate.cc

@@ -7,7 +7,7 @@
 #include "src/api/api.h"
 #include "src/asmjs/asm-js.h"
 #include "src/base/platform/wrappers.h"
-#include "src/logging/counters.h"
+#include "src/logging/counters-scopes.h"
 #include "src/logging/metrics.h"
 #include "src/numbers/conversions-inl.h"
 #include "src/objects/descriptor-array-inl.h"

test/cctest/test-api.cc

@@ -22622,25 +22622,68 @@ TEST(ChainSignatureCheck) {
 
 
 static const char* last_event_message;
+// See Logger::StartEnd
 static int last_event_status;
+static int event_count = 0;
 void StoringEventLoggerCallback(const char* message, int status) {
     last_event_message = message;
     last_event_status = status;
+    event_count++;
 }
 
 
 TEST(EventLogging) {
   v8::Isolate* isolate = CcTest::isolate();
   isolate->SetEventLogger(StoringEventLoggerCallback);
-  v8::internal::HistogramTimer histogramTimer(
-      "V8.Test", 0, 10000, v8::internal::HistogramTimerResolution::MILLISECOND,
+  v8::internal::NestedTimedHistogram histogram(
+      "V8.Test", 0, 10000, v8::internal::TimedHistogramResolution::MILLISECOND,
       50, reinterpret_cast<v8::internal::Isolate*>(isolate)->counters());
-  histogramTimer.Start();
+  event_count = 0;
+  int count = 0;
+  {
+    CHECK_EQ(0, event_count);
+    v8::internal::NestedTimedHistogramScope scope1(&histogram);
+    CHECK_EQ(0, strcmp("V8.Test", last_event_message));
+    CHECK_EQ(0, last_event_status);
+    CHECK_EQ(++count, event_count);
+    {
+      CHECK_EQ(count, event_count);
+      v8::internal::NestedTimedHistogramScope scope2(&histogram);
       CHECK_EQ(0, strcmp("V8.Test", last_event_message));
       CHECK_EQ(0, last_event_status);
-  histogramTimer.Stop();
+      CHECK_EQ(++count, event_count);
+      {
+        CHECK_EQ(count, event_count);
+        v8::internal::NestedTimedHistogramScope scope3(&histogram);
+        CHECK_EQ(++count, event_count);
+        v8::internal::PauseNestedTimedHistogramScope scope4(&histogram);
+        // The outer timer scope is just paused, no event is emited yet.
+        CHECK_EQ(count, event_count);
+        {
+          CHECK_EQ(count, event_count);
+          v8::internal::NestedTimedHistogramScope scope5(&histogram);
+          CHECK_EQ(0, strcmp("V8.Test", last_event_message));
+          CHECK_EQ(0, last_event_status);
+          CHECK_EQ(++count, event_count);
+        }
+        CHECK_EQ(0, strcmp("V8.Test", last_event_message));
+        CHECK_EQ(1, last_event_status);
+        CHECK_EQ(++count, event_count);
+      }
+      CHECK_EQ(0, strcmp("V8.Test", last_event_message));
+      CHECK_EQ(1, last_event_status);
+      CHECK_EQ(++count, event_count);
+      v8::internal::PauseNestedTimedHistogramScope scope6(&histogram);
+      // The outer timer scope is just paused, no event is emited yet.
+      CHECK_EQ(count, event_count);
+    }
+    CHECK_EQ(0, strcmp("V8.Test", last_event_message));
+    CHECK_EQ(1, last_event_status);
+    CHECK_EQ(++count, event_count);
+  }
   CHECK_EQ(0, strcmp("V8.Test", last_event_message));
   CHECK_EQ(1, last_event_status);
+  CHECK_EQ(++count, event_count);
 }
 
 TEST(PropertyDescriptor) {

test/unittests/base/platform/time-unittest.cc

@@ -379,6 +379,108 @@ TEST(TimeTicks, IsMonotonic) {
   }
 }
 
+namespace {
+void Sleep(TimeDelta wait_time) {
+  ElapsedTimer waiter;
+  waiter.Start();
+  while (!waiter.HasExpired(wait_time)) {
+    OS::Sleep(TimeDelta::FromMilliseconds(1));
+  }
+}
+}  // namespace
+
+TEST(ElapsedTimer, StartStop) {
+  TimeDelta wait_time = TimeDelta::FromMilliseconds(100);
+  TimeDelta noise = TimeDelta::FromMilliseconds(100);
+  ElapsedTimer timer;
+  DCHECK(!timer.IsStarted());
+
+  timer.Start();
+  DCHECK(timer.IsStarted());
+
+  Sleep(wait_time);
+  TimeDelta delta = timer.Elapsed();
+  DCHECK(timer.IsStarted());
+  EXPECT_GE(delta, wait_time);
+  EXPECT_LT(delta, wait_time + noise);
+
+  timer.Pause();
+  DCHECK(timer.IsStarted());
+  Sleep(wait_time);
+
+  timer.Resume();
+  DCHECK(timer.IsStarted());
+  delta = timer.Elapsed();
+  timer.Pause();
+  DCHECK(timer.IsStarted());
+  EXPECT_GE(delta, wait_time);
+  EXPECT_LT(delta, wait_time + noise);
+
+  Sleep(wait_time);
+  timer.Resume();
+  DCHECK(timer.IsStarted());
+  delta = timer.Elapsed();
+  EXPECT_GE(delta, wait_time);
+  EXPECT_LT(delta, wait_time + noise);
+
+  timer.Stop();
+  DCHECK(!timer.IsStarted());
+}
+
+TEST(ElapsedTimer, StartStopArgs) {
+  TimeDelta wait_time = TimeDelta::FromMilliseconds(100);
+  ElapsedTimer timer1;
+  ElapsedTimer timer2;
+  DCHECK(!timer1.IsStarted());
+  DCHECK(!timer2.IsStarted());
+
+  TimeTicks now = TimeTicks::HighResolutionNow();
+  timer1.Start(now);
+  timer2.Start(now);
+  DCHECK(timer1.IsStarted());
+  DCHECK(timer2.IsStarted());
+
+  Sleep(wait_time);
+  now = TimeTicks::HighResolutionNow();
+  TimeDelta delta1 = timer1.Elapsed(now);
+  Sleep(wait_time);
+  TimeDelta delta2 = timer2.Elapsed(now);
+  DCHECK(timer1.IsStarted());
+  DCHECK(timer2.IsStarted());
+  EXPECT_GE(delta1, delta2);
+  Sleep(wait_time);
+  EXPECT_NE(delta1, timer2.Elapsed());
+
+  TimeTicks now2 = TimeTicks::HighResolutionNow();
+  EXPECT_NE(timer1.Elapsed(now), timer1.Elapsed(now2));
+  EXPECT_NE(delta1, timer1.Elapsed(now2));
+  EXPECT_NE(delta2, timer2.Elapsed(now2));
+  EXPECT_GE(timer1.Elapsed(now2), timer2.Elapsed(now2));
+
+  now = TimeTicks::HighResolutionNow();
+  timer1.Pause(now);
+  timer2.Pause(now);
+  DCHECK(timer1.IsStarted());
+  DCHECK(timer2.IsStarted());
+  Sleep(wait_time);
+
+  now = TimeTicks::HighResolutionNow();
+  timer1.Resume(now);
+  Sleep(wait_time);
+  timer2.Resume(now);
+  DCHECK(timer1.IsStarted());
+  DCHECK(timer2.IsStarted());
+
+  delta1 = timer1.Elapsed(now);
+  Sleep(wait_time);
+  delta2 = timer2.Elapsed(now);
+  EXPECT_GE(delta1, delta2);
+
+  timer1.Stop();
+  timer2.Stop();
+  DCHECK(!timer1.IsStarted());
+  DCHECK(!timer2.IsStarted());
+}
 
 #if V8_OS_ANDROID
 #define MAYBE_ThreadNow DISABLED_ThreadNow