[counters] Annotate v8 with more runtime call counters.

By fully annotating the API with runtime counters we can properly measure
how much time we spend in total in v8. When --runtime-call-stats is specified
we now disable the fast-paths for callbacks to properly measure them.
As a drive-by-fix this CL unifies the LOG messages in api.cc.
Additionally we added missing timers to gain better resolution in the parser
and callbacks.

BUG=

Review-Url: https://codereview.chromium.org/1923893002
Cr-Commit-Position: refs/heads/master@{#36248}

src/api-arguments.cc

@@ -9,6 +9,7 @@ namespace internal {
 
 Handle<Object> FunctionCallbackArguments::Call(FunctionCallback f) {
   Isolate* isolate = this->isolate();
+  RuntimeCallTimerScope timer(isolate, &RuntimeCallStats::FunctionCallback);
   VMState<EXTERNAL> state(isolate);
   ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
   FunctionCallbackInfo<v8::Value> info(begin(), argv_, argc_);
@@ -19,6 +20,7 @@ Handle<Object> FunctionCallbackArguments::Call(FunctionCallback f) {
 Handle<JSObject> PropertyCallbackArguments::Call(
     IndexedPropertyEnumeratorCallback f) {
   Isolate* isolate = this->isolate();
+  RuntimeCallTimerScope timer(isolate, &RuntimeCallStats::PropertyCallback);
   VMState<EXTERNAL> state(isolate);
   ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
   PropertyCallbackInfo<v8::Array> info(begin());

src/api-arguments.h

@@ -116,6 +116,7 @@ class PropertyCallbackArguments
 #define WRITE_CALL_1_NAME(Function, type, ApiReturn, InternalReturn)         \
   Handle<InternalReturn> Call(Function f, Handle<Name> name) {               \
     Isolate* isolate = this->isolate();                                      \
+    RuntimeCallTimerScope timer(isolate, &RuntimeCallStats::Function);       \
     VMState<EXTERNAL> state(isolate);                                        \
     ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));             \
     PropertyCallbackInfo<ApiReturn> info(begin());                           \
@@ -138,6 +139,7 @@ class PropertyCallbackArguments
 #define WRITE_CALL_1_INDEX(Function, type, ApiReturn, InternalReturn)  \
   Handle<InternalReturn> Call(Function f, uint32_t index) {            \
     Isolate* isolate = this->isolate();                                \
+    RuntimeCallTimerScope timer(isolate, &RuntimeCallStats::Function); \
     VMState<EXTERNAL> state(isolate);                                  \
     ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));       \
     PropertyCallbackInfo<ApiReturn> info(begin());                     \
@@ -155,6 +157,8 @@ class PropertyCallbackArguments
   Handle<Object> Call(GenericNamedPropertySetterCallback f, Handle<Name> name,
                       Handle<Object> value) {
     Isolate* isolate = this->isolate();
+    RuntimeCallTimerScope timer(
+        isolate, &RuntimeCallStats::GenericNamedPropertySetterCallback);
     VMState<EXTERNAL> state(isolate);
     ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
     PropertyCallbackInfo<v8::Value> info(begin());
@@ -167,6 +171,8 @@ class PropertyCallbackArguments
   Handle<Object> Call(IndexedPropertySetterCallback f, uint32_t index,
                       Handle<Object> value) {
     Isolate* isolate = this->isolate();
+    RuntimeCallTimerScope timer(
+        isolate, &RuntimeCallStats::IndexedPropertySetterCallback);
     VMState<EXTERNAL> state(isolate);
     ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
     PropertyCallbackInfo<v8::Value> info(begin());
@@ -179,6 +185,8 @@ class PropertyCallbackArguments
   void Call(AccessorNameSetterCallback f, Handle<Name> name,
             Handle<Object> value) {
     Isolate* isolate = this->isolate();
+    RuntimeCallTimerScope timer(isolate,
+                                &RuntimeCallStats::AccessorNameSetterCallback);
     VMState<EXTERNAL> state(isolate);
     ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
     PropertyCallbackInfo<void> info(begin());

src/compiler.cc

@@ -1024,6 +1024,9 @@ Handle<SharedFunctionInfo> CompileToplevel(CompilationInfo* info) {
     // 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.
+    RuntimeCallTimerScope runtimeTimer(
+        isolate, parse_info->is_eval() ? &RuntimeCallStats::CompileEval
+                                       : &RuntimeCallStats::Compile);
     HistogramTimer* rate = parse_info->is_eval()
                                ? info->isolate()->counters()->compile_eval()
                                : info->isolate()->counters()->compile();

src/counters.cc

@@ -312,6 +312,10 @@ void RuntimeCallStats::Print(std::ostream& os) {
   BUILTIN_LIST_C(PRINT_COUNTER)
 #undef PRINT_COUNTER
 
+#define PRINT_COUNTER(name) entries.Add(&this->API_##name);
+  FOR_EACH_API_COUNTER(PRINT_COUNTER)
+#undef PRINT_COUNTER
+
 #define PRINT_COUNTER(name) entries.Add(&this->Handler_##name);
   FOR_EACH_HANDLER_COUNTER(PRINT_COUNTER)
 #undef PRINT_COUNTER
@@ -321,15 +325,25 @@ void RuntimeCallStats::Print(std::ostream& os) {
 
 void RuntimeCallStats::Reset() {
   if (!FLAG_runtime_call_stats) return;
-#define RESET_COUNTER(name, nargs, ressize) this->Runtime_##name.Reset();
+#define RESET_COUNTER(name) this->name.Reset();
+  FOR_EACH_MANUAL_COUNTER(RESET_COUNTER)
+#undef RESET_COUNTER
+
+#define RESET_COUNTER(name, nargs, result_size) this->Runtime_##name.Reset();
   FOR_EACH_INTRINSIC(RESET_COUNTER)
 #undef RESET_COUNTER
+
 #define RESET_COUNTER(name, type) this->Builtin_##name.Reset();
   BUILTIN_LIST_C(RESET_COUNTER)
 #undef RESET_COUNTER
-  this->ExternalCallback.Reset();
-  this->GC.Reset();
-  this->UnexpectedStubMiss.Reset();
+
+#define RESET_COUNTER(name) this->API_##name.Reset();
+  FOR_EACH_API_COUNTER(RESET_COUNTER)
+#undef RESET_COUNTER
+
+#define RESET_COUNTER(name) this->Handler_##name.Reset();
+  FOR_EACH_HANDLER_COUNTER(RESET_COUNTER)
+#undef RESET_COUNTER
 }
 
 }  // namespace internal

src/deoptimizer.cc

@@ -374,6 +374,8 @@ void Deoptimizer::DeoptimizeMarkedCodeForContext(Context* context) {
 
 
 void Deoptimizer::DeoptimizeAll(Isolate* isolate) {
+  RuntimeCallTimerScope runtimeTimer(isolate,
+                                     &RuntimeCallStats::DeoptimizeCode);
   TimerEventScope<TimerEventDeoptimizeCode> timer(isolate);
   TRACE_EVENT0("v8", "V8.DeoptimizeCode");
   if (FLAG_trace_deopt) {
@@ -393,6 +395,8 @@ void Deoptimizer::DeoptimizeAll(Isolate* isolate) {
 
 
 void Deoptimizer::DeoptimizeMarkedCode(Isolate* isolate) {
+  RuntimeCallTimerScope runtimeTimer(isolate,
+                                     &RuntimeCallStats::DeoptimizeCode);
   TimerEventScope<TimerEventDeoptimizeCode> timer(isolate);
   TRACE_EVENT0("v8", "V8.DeoptimizeCode");
   if (FLAG_trace_deopt) {
@@ -422,7 +426,10 @@ void Deoptimizer::MarkAllCodeForContext(Context* context) {
 
 
 void Deoptimizer::DeoptimizeFunction(JSFunction* function) {
-  TimerEventScope<TimerEventDeoptimizeCode> timer(function->GetIsolate());
+  Isolate* isolate = function->GetIsolate();
+  RuntimeCallTimerScope runtimeTimer(isolate,
+                                     &RuntimeCallStats::DeoptimizeCode);
+  TimerEventScope<TimerEventDeoptimizeCode> timer(isolate);
   TRACE_EVENT0("v8", "V8.DeoptimizeCode");
   Code* code = function->code();
   if (code->kind() == Code::OPTIMIZED_FUNCTION) {

src/execution.cc

@@ -94,6 +94,7 @@ MUST_USE_RESULT MaybeHandle<Object> Invoke(Isolate* isolate, bool is_construct,
     if (FLAG_profile_deserialization && target->IsJSFunction()) {
       PrintDeserializedCodeInfo(Handle<JSFunction>::cast(target));
     }
+    RuntimeCallTimerScope timer(isolate, &RuntimeCallStats::JS_Execution);
     value = CALL_GENERATED_CODE(isolate, stub_entry, orig_func, func, recv,
                                 argc, argv);
   }

src/full-codegen/full-codegen.cc

@@ -28,6 +28,8 @@ namespace internal {
 bool FullCodeGenerator::MakeCode(CompilationInfo* info) {
   Isolate* isolate = info->isolate();
 
+  RuntimeCallTimerScope runtimeTimer(isolate,
+                                     &RuntimeCallStats::CompileFullCode);
   TimerEventScope<TimerEventCompileFullCode> timer(info->isolate());
   TRACE_EVENT0("v8", "V8.CompileFullCode");
 

src/ic/ic.cc

@@ -1197,8 +1197,10 @@ Handle<Code> LoadIC::CompileHandler(LookupIterator* lookup,
         if (call_optimization.is_simple_api_call()) {
           TRACE_HANDLER_STATS(isolate(), LoadIC_LoadCallback);
           int index = lookup->GetAccessorIndex();
-          return compiler.CompileLoadCallback(lookup->name(), call_optimization,
-                                              index);
+          Handle<Code> code = compiler.CompileLoadCallback(
+              lookup->name(), call_optimization, index);
+          if (FLAG_runtime_call_stats) return slow_stub();
+          return code;
         }
         TRACE_HANDLER_STATS(isolate(), LoadIC_LoadViaGetter);
         int expected_arguments = Handle<JSFunction>::cast(getter)
@@ -1216,7 +1218,9 @@ Handle<Code> LoadIC::CompileHandler(LookupIterator* lookup,
         DCHECK(!info->is_sloppy() || receiver->IsJSReceiver());
         TRACE_HANDLER_STATS(isolate(), LoadIC_LoadCallback);
         NamedLoadHandlerCompiler compiler(isolate(), map, holder, cache_holder);
-        return compiler.CompileLoadCallback(lookup->name(), info);
+        Handle<Code> code = compiler.CompileLoadCallback(lookup->name(), info);
+        if (FLAG_runtime_call_stats) return slow_stub();
+        return code;
       }
       UNREACHABLE();
     }
@@ -1790,8 +1794,10 @@ Handle<Code> StoreIC::CompileHandler(LookupIterator* lookup,
         DCHECK(!info->is_sloppy() || receiver->IsJSReceiver());
         TRACE_HANDLER_STATS(isolate(), StoreIC_StoreCallback);
         NamedStoreHandlerCompiler compiler(isolate(), receiver_map(), holder);
-        return compiler.CompileStoreCallback(receiver, lookup->name(), info,
-                                             language_mode());
+        Handle<Code> code = compiler.CompileStoreCallback(
+            receiver, lookup->name(), info, language_mode());
+        if (FLAG_runtime_call_stats) return slow_stub();
+        return code;
       } else {
         DCHECK(accessors->IsAccessorPair());
         Handle<Object> setter(Handle<AccessorPair>::cast(accessors)->setter(),
@@ -1802,9 +1808,11 @@ Handle<Code> StoreIC::CompileHandler(LookupIterator* lookup,
         if (call_optimization.is_simple_api_call()) {
           DCHECK(call_optimization.IsCompatibleReceiver(receiver, holder));
           TRACE_HANDLER_STATS(isolate(), StoreIC_StoreCallback);
-          return compiler.CompileStoreCallback(receiver, lookup->name(),
-                                               call_optimization,
-                                               lookup->GetAccessorIndex());
+          Handle<Code> code = compiler.CompileStoreCallback(
+              receiver, lookup->name(), call_optimization,
+              lookup->GetAccessorIndex());
+          if (FLAG_runtime_call_stats) return slow_stub();
+          return code;
         }
         TRACE_HANDLER_STATS(isolate(), StoreIC_StoreViaSetter);
         int expected_arguments = JSFunction::cast(*setter)

src/interpreter/interpreter.cc

@@ -131,6 +131,8 @@ int Interpreter::InterruptBudget() {
 }
 
 bool Interpreter::MakeBytecode(CompilationInfo* info) {
+  RuntimeCallTimerScope runtimeTimer(info->isolate(),
+                                     &RuntimeCallStats::CompileIgnition);
   TimerEventScope<TimerEventCompileIgnition> timer(info->isolate());
   TRACE_EVENT0("v8", "V8.CompileIgnition");
 

src/parsing/parser.cc

@@ -820,6 +820,7 @@ FunctionLiteral* Parser::ParseProgram(Isolate* isolate, ParseInfo* info) {
   DCHECK(parsing_on_main_thread_);
 
   HistogramTimerScope timer_scope(isolate->counters()->parse(), true);
+  RuntimeCallTimerScope runtime_timer(isolate, &RuntimeCallStats::Parse);
   TRACE_EVENT0("v8", "V8.Parse");
   Handle<String> source(String::cast(info->script()->source()));
   isolate->counters()->total_parse_size()->Increment(source->length());
@@ -984,6 +985,7 @@ FunctionLiteral* Parser::ParseLazy(Isolate* isolate, ParseInfo* info) {
   // It's OK to use the Isolate & counters here, since this function is only
   // called in the main thread.
   DCHECK(parsing_on_main_thread_);
+  RuntimeCallTimerScope runtime_timer(isolate, &RuntimeCallStats::ParseLazy);
   HistogramTimerScope timer_scope(isolate->counters()->parse_lazy());
   TRACE_EVENT0("v8", "V8.ParseLazy");
   Handle<String> source(String::cast(info->script()->source()));

src/vm-state-inl.h

@@ -63,18 +63,11 @@ ExternalCallbackScope::ExternalCallbackScope(Isolate* isolate, Address callback)
   scope_address_ = Simulator::current(isolate)->get_sp();
 #endif
   isolate_->set_external_callback_scope(this);
-  if (FLAG_runtime_call_stats) {
-    RuntimeCallStats::Enter(isolate_, &timer_,
-                            &RuntimeCallStats::ExternalCallback);
-  }
   TRACE_EVENT_BEGIN0(TRACE_DISABLED_BY_DEFAULT("v8.runtime"),
                      "V8.ExternalCallback");
 }
 
 ExternalCallbackScope::~ExternalCallbackScope() {
-  if (FLAG_runtime_call_stats) {
-    RuntimeCallStats::Leave(isolate_, &timer_);
-  }
   isolate_->set_external_callback_scope(previous_scope_);
   TRACE_EVENT_END0(TRACE_DISABLED_BY_DEFAULT("v8.runtime"),
                    "V8.ExternalCallback");

src/vm-state.h

@@ -49,7 +49,6 @@ class ExternalCallbackScope BASE_EMBEDDED {
   Isolate* isolate_;
   Address callback_;
   ExternalCallbackScope* previous_scope_;
-  RuntimeCallTimer timer_;
 #ifdef USE_SIMULATOR
   Address scope_address_;
 #endif