Implement AggregatableHistogramTimer and use it to measure how much time

of running a script is really spent in compilation. That is, sum up the
total time spent compiling (parsing + compile proper) within a run call
as seen through the API.

@jochen: So many questions:
- Is it ok to re-use V8.CompileLazy?
  This measures something a little different.
- clang-format does funny things to the huge macro definitions.
  I accepted clang-format changes for all code, but reverted for
  the #define orgies in counters.h. ok?
- Am I measuring the right thing. That is, are Aggregat[ing|ed]TimerScope
  in the right place?

I'll fiddle a bit more with this to see if it does the right thing. Would
be happy if you could still review now-ish.

BUG=

Review URL: https://codereview.chromium.org/790413004

Cr-Commit-Position: refs/heads/master@{#26226}

diff --git a/src/api.cc b/src/api.cc
index d1e782f..9870323 100644 (file)
--- a/src/api.cc
+++ b/src/api.cc
@@ -1480,6 +1480,7 @@ Local<Value> Script::Run() {
   ON_BAILOUT(isolate, "v8::Script::Run()", return Local<Value>());
   LOG_API(isolate, "Script::Run");
   ENTER_V8(isolate);
+  i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy());
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
   i::HandleScope scope(isolate);
   i::Handle<i::JSFunction> fun = i::Handle<i::JSFunction>::cast(obj);

diff --git a/src/compiler.cc b/src/compiler.cc
index bcae3b9..07ed3df 100644 (file)
--- a/src/compiler.cc
+++ b/src/compiler.cc
@@ -940,6 +940,7 @@ MaybeHandle<Code> Compiler::GetLazyCode(Handle<JSFunction> function) {
   Isolate* isolate = function->GetIsolate();
   DCHECK(!isolate->has_pending_exception());
   DCHECK(!function->is_compiled());
+  AggregatedHistogramTimerScope timer(isolate->counters()->compile_lazy());
   // If the debugger is active, do not compile with turbofan unless we can
   // deopt from turbofan code.
   if (FLAG_turbo_asm && function->shared()->asm_function() &&

diff --git a/src/counters.cc b/src/counters.cc
index 972bd68..ec5d21d 100644 (file)
--- a/src/counters.cc
+++ b/src/counters.cc
@@ -66,6 +66,11 @@ Counters::Counters(Isolate* isolate) {
     HISTOGRAM_TIMER_LIST(HT)
 #undef HT
 
+#define AHT(name, caption) \
+  name##_ = AggregatableHistogramTimer(#caption, 0, 10000, 50, isolate);
+    AGGREGATABLE_HISTOGRAM_TIMER_LIST(AHT)
+#undef AHT
+
 #define HP(name, caption) \
     name##_ = Histogram(#caption, 0, 101, 100, isolate);
     HISTOGRAM_PERCENTAGE_LIST(HP)
@@ -156,6 +161,10 @@ void Counters::ResetHistograms() {
     HISTOGRAM_TIMER_LIST(HT)
 #undef HT
 
+#define AHT(name, caption) name##_.Reset();
+    AGGREGATABLE_HISTOGRAM_TIMER_LIST(AHT)
+#undef AHT
+
 #define HP(name, caption) name##_.Reset();
     HISTOGRAM_PERCENTAGE_LIST(HP)
 #undef HP

diff --git a/src/counters.h b/src/counters.h
index cbd8093..1209b45 100644 (file)
--- a/src/counters.h
+++ b/src/counters.h
@@ -8,6 +8,7 @@
 #include "include/v8.h"
 #include "src/allocation.h"
 #include "src/base/platform/elapsed-timer.h"
+#include "src/base/platform/time.h"
 #include "src/globals.h"
 #include "src/objects.h"
 
@@ -291,6 +292,68 @@ class HistogramTimerScope BASE_EMBEDDED {
 #endif
 };
 
+
+// A histogram timer that can aggregate events within a larger scope.
+//
+// Intended use of this timer is to have an outer (aggregating) and an inner
+// (to be aggregated) scope, where the inner scope measure the time of events,
+// and all those inner scope measurements will be summed up by the outer scope.
+// An example use might be to aggregate the time spent in lazy compilation
+// while running a script.
+//
+// Helpers:
+// - AggregatingHistogramTimerScope, the "outer" scope within which
+//     times will be summed up.
+// - AggregatedHistogramTimerScope, the "inner" scope which defines the
+//     events to be timed.
+class AggregatableHistogramTimer : public Histogram {
+ public:
+  AggregatableHistogramTimer() {}
+  AggregatableHistogramTimer(const char* name, int min, int max,
+                             int num_buckets, Isolate* isolate)
+      : Histogram(name, min, max, num_buckets, isolate) {}
+
+  // Start/stop the "outer" scope.
+  void Start() { time_ = base::TimeDelta(); }
+  void Stop() { AddSample(static_cast<int>(time_.InMilliseconds())); }
+
+  // Add a time value ("inner" scope).
+  void Add(base::TimeDelta other) { time_ += other; }
+
+ private:
+  base::TimeDelta time_;
+};
+
+
+// A helper class for use with AggregatableHistogramTimer.
+class AggregatingHistogramTimerScope {
+ public:
+  explicit AggregatingHistogramTimerScope(AggregatableHistogramTimer* histogram)
+      : histogram_(histogram) {
+    histogram_->Start();
+  }
+  ~AggregatingHistogramTimerScope() { histogram_->Stop(); }
+
+ private:
+  AggregatableHistogramTimer* histogram_;
+};
+
+
+// A helper class for use with AggregatableHistogramTimer.
+class AggregatedHistogramTimerScope {
+ public:
+  explicit AggregatedHistogramTimerScope(AggregatableHistogramTimer* histogram)
+      : histogram_(histogram) {
+    timer_.Start();
+  }
+  ~AggregatedHistogramTimerScope() { histogram_->Add(timer_.Elapsed()); }
+
+ private:
+  base::ElapsedTimer timer_;
+  AggregatableHistogramTimer* histogram_;
+};
+
+
 #define HISTOGRAM_RANGE_LIST(HR)                                              \
   /* Generic range histograms */                                              \
   HR(gc_idle_time_allotted_in_ms, V8.GCIdleTimeAllottedInMS, 0, 10000, 101)   \
@@ -319,6 +382,10 @@ class HistogramTimerScope BASE_EMBEDDED {
   HT(compile_script, V8.CompileScript)
 
 
+#define AGGREGATABLE_HISTOGRAM_TIMER_LIST(AHT) \
+  AHT(compile_lazy, V8.CompileLazy)
+
+
 #define HISTOGRAM_PERCENTAGE_LIST(HP)                                 \
   /* Heap fragmentation. */                                           \
   HP(external_fragmentation_total,                                    \
@@ -569,6 +636,11 @@ class Counters {
   HISTOGRAM_TIMER_LIST(HT)
 #undef HT
 
+#define AHT(name, caption) \
+  AggregatableHistogramTimer* name() { return &name##_; }
+  AGGREGATABLE_HISTOGRAM_TIMER_LIST(AHT)
+#undef AHT
+
 #define HP(name, caption) \
   Histogram* name() { return &name##_; }
   HISTOGRAM_PERCENTAGE_LIST(HP)
@@ -619,6 +691,9 @@ class Counters {
 #define RATE_ID(name, caption) k_##name,
     HISTOGRAM_TIMER_LIST(RATE_ID)
 #undef RATE_ID
+#define AGGREGATABLE_ID(name, caption) k_##name,
+    AGGREGATABLE_HISTOGRAM_TIMER_LIST(AGGREGATABLE_ID)
+#undef AGGREGATABLE_ID
 #define PERCENTAGE_ID(name, caption) k_##name,
     HISTOGRAM_PERCENTAGE_LIST(PERCENTAGE_ID)
 #undef PERCENTAGE_ID
@@ -660,6 +735,11 @@ class Counters {
   HISTOGRAM_TIMER_LIST(HT)
 #undef HT
 
+#define AHT(name, caption) \
+  AggregatableHistogramTimer name##_;
+  AGGREGATABLE_HISTOGRAM_TIMER_LIST(AHT)
+#undef AHT
+
 #define HP(name, caption) \
   Histogram name##_;
   HISTOGRAM_PERCENTAGE_LIST(HP)