The trace-events will have a high overhead when turned on, but they are in a...

The trace-events will have a high overhead when turned on, but they are in a disabled-by-default category.

As long as the off overhead is negligible, this CL allows us to understand the behavior of V8 rather than its performance at the moment.

BUG=v8:5089

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

src/api-arguments-inl.h

@@ -20,6 +20,7 @@ namespace internal {
                                                          Handle<Name> name) { \
     Isolate* isolate = this->isolate();                                       \
     RuntimeCallTimerScope timer(isolate, &RuntimeCallStats::Function);        \
+    TRACE_RUNTIME_CALL(#Function);                                           \
     VMState<EXTERNAL> state(isolate);                                         \
     ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));              \
     PropertyCallbackInfo<ApiReturn> info(begin());                            \
@@ -44,6 +45,7 @@ FOR_EACH_CALLBACK_TABLE_MAPPING_1_NAME(WRITE_CALL_1_NAME)
                                                          uint32_t index) { \
     Isolate* isolate = this->isolate();                                    \
     RuntimeCallTimerScope timer(isolate, &RuntimeCallStats::Function);     \
+    TRACE_RUNTIME_CALL(#Function);                                        \
     VMState<EXTERNAL> state(isolate);                                      \
     ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));           \
     PropertyCallbackInfo<ApiReturn> info(begin());                         \
@@ -64,6 +66,7 @@ Handle<Object> PropertyCallbackArguments::Call(
   Isolate* isolate = this->isolate();
   RuntimeCallTimerScope timer(
       isolate, &RuntimeCallStats::GenericNamedPropertySetterCallback);
+  TRACE_RUNTIME_CALL("GenericNamedPropertySetterCallback");
   VMState<EXTERNAL> state(isolate);
   ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
   PropertyCallbackInfo<v8::Value> info(begin());
@@ -79,6 +82,7 @@ Handle<Object> PropertyCallbackArguments::Call(IndexedPropertySetterCallback f,
   Isolate* isolate = this->isolate();
   RuntimeCallTimerScope timer(isolate,
                               &RuntimeCallStats::IndexedPropertySetterCallback);
+  TRACE_RUNTIME_CALL("IndexedPropertySetterCallback");
   VMState<EXTERNAL> state(isolate);
   ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
   PropertyCallbackInfo<v8::Value> info(begin());
@@ -93,6 +97,7 @@ void PropertyCallbackArguments::Call(AccessorNameSetterCallback f,
   Isolate* isolate = this->isolate();
   RuntimeCallTimerScope timer(isolate,
                               &RuntimeCallStats::AccessorNameSetterCallback);
+  TRACE_RUNTIME_CALL("AccessorNameSetterCallback");
   VMState<EXTERNAL> state(isolate);
   ExternalCallbackScope call_scope(isolate, FUNCTION_ADDR(f));
   PropertyCallbackInfo<void> info(begin());

src/api-arguments.cc

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

src/api.cc

@@ -73,6 +73,7 @@ namespace v8 {
 #define LOG_API(isolate, class_name, function_name)                       \
   i::RuntimeCallTimerScope _runtime_timer(                                \
       isolate, &i::RuntimeCallStats::API_##class_name##_##function_name); \
+  TRACE_RUNTIME_CALL(#class_name "::" #function_name);                    \
   LOG(isolate, ApiEntryCall("v8::" #class_name "::" #function_name))
 
 #define ENTER_V8(isolate) i::VMState<v8::OTHER> __state__((isolate))
@@ -1764,6 +1765,7 @@ MaybeLocal<Value> Script::Run(Local<Context> context) {
   i::AggregatingHistogramTimerScope timer(isolate->counters()->compile_lazy());
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
   TRACE_EVENT0("v8", "V8.Execute");
+  TRACE_CHECK_AND_SET_RUNTIME_CALLS_TRACING();
   auto fun = i::Handle<i::JSFunction>::cast(Utils::OpenHandle(this));
   i::Handle<i::Object> receiver = isolate->global_proxy();
   Local<Value> result;
@@ -1818,6 +1820,7 @@ MaybeLocal<UnboundScript> ScriptCompiler::CompileUnboundInternal(
   {
     i::HistogramTimerScope total(isolate->counters()->compile_script(), true);
     TRACE_EVENT0("v8", "V8.CompileScript");
+    TRACE_CHECK_AND_SET_RUNTIME_CALLS_TRACING();
     i::Handle<i::Object> name_obj;
     i::Handle<i::Object> source_map_url;
     int line_offset = 0;
@@ -4342,6 +4345,7 @@ MaybeLocal<Value> Object::CallAsFunction(Local<Context> context,
   i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
   TRACE_EVENT0("v8", "V8.Execute");
+  TRACE_CHECK_AND_SET_RUNTIME_CALLS_TRACING();
   auto self = Utils::OpenHandle(this);
   auto recv_obj = Utils::OpenHandle(*recv);
   STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Object**));
@@ -4370,6 +4374,7 @@ MaybeLocal<Value> Object::CallAsConstructor(Local<Context> context, int argc,
   i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
   TRACE_EVENT0("v8", "V8.Execute");
+  TRACE_CHECK_AND_SET_RUNTIME_CALLS_TRACING();
   auto self = Utils::OpenHandle(this);
   STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Object**));
   i::Handle<i::Object>* args = reinterpret_cast<i::Handle<i::Object>*>(argv);
@@ -4420,6 +4425,7 @@ MaybeLocal<Object> Function::NewInstance(Local<Context> context, int argc,
   i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
   TRACE_EVENT0("v8", "V8.Execute");
+  TRACE_CHECK_AND_SET_RUNTIME_CALLS_TRACING();
   auto self = Utils::OpenHandle(this);
   STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Object**));
   i::Handle<i::Object>* args = reinterpret_cast<i::Handle<i::Object>*>(argv);
@@ -4445,6 +4451,7 @@ MaybeLocal<v8::Value> Function::Call(Local<Context> context,
   i::HistogramTimerScope execute_timer(isolate->counters()->execute(), true);
   i::TimerEventScope<i::TimerEventExecute> timer_scope(isolate);
   TRACE_EVENT0("v8", "V8.Execute");
+  TRACE_CHECK_AND_SET_RUNTIME_CALLS_TRACING();
   auto self = Utils::OpenHandle(this);
   i::Handle<i::Object> recv_obj = Utils::OpenHandle(*recv);
   STATIC_ASSERT(sizeof(v8::Local<v8::Value>) == sizeof(i::Object**));
@@ -5589,6 +5596,8 @@ Local<Context> v8::Context::New(v8::Isolate* external_isolate,
                                 v8::Local<Value> global_object) {
   i::Isolate* isolate = reinterpret_cast<i::Isolate*>(external_isolate);
   LOG_API(isolate, Context, New);
+  TRACE_EVENT0("v8", "V8.NewContext");
+  TRACE_CHECK_AND_SET_RUNTIME_CALLS_TRACING();
   i::HandleScope scope(isolate);
   ExtensionConfiguration no_extensions;
   if (extensions == NULL) extensions = &no_extensions;
@@ -8778,6 +8787,7 @@ void InvokeAccessorGetterCallback(
   Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate());
   RuntimeCallTimerScope timer(isolate,
                               &RuntimeCallStats::AccessorGetterCallback);
+  TRACE_RUNTIME_CALL("AccessorGetterCallback");
   Address getter_address = reinterpret_cast<Address>(reinterpret_cast<intptr_t>(
       getter));
   VMState<EXTERNAL> state(isolate);
@@ -8791,6 +8801,7 @@ void InvokeFunctionCallback(const v8::FunctionCallbackInfo<v8::Value>& info,
   Isolate* isolate = reinterpret_cast<Isolate*>(info.GetIsolate());
   RuntimeCallTimerScope timer(isolate,
                               &RuntimeCallStats::InvokeFunctionCallback);
+  TRACE_RUNTIME_CALL("InvokeFunctionCallback");
   Address callback_address =
       reinterpret_cast<Address>(reinterpret_cast<intptr_t>(callback));
   VMState<EXTERNAL> state(isolate);

src/counters.h

@@ -13,6 +13,7 @@
 #include "src/globals.h"
 #include "src/objects.h"
 #include "src/runtime/runtime.h"
+#include "src/tracing/trace-event.h"
 
 namespace v8 {
 namespace internal {
@@ -786,6 +787,7 @@ class RuntimeCallStats {
 
 #define TRACE_RUNTIME_CALL_STATS(isolate, counter_name) \
   do {                                                  \
+    TRACE_RUNTIME_CALL(#counter_name);                  \
     if (FLAG_runtime_call_stats) {                      \
       RuntimeCallStats::CorrectCurrentCounterId(        \
           isolate, &RuntimeCallStats::counter_name);    \

src/execution.cc

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

src/lookup.cc

@@ -352,6 +352,8 @@ void LookupIterator::Delete() {
         isolate_, is_prototype_map
                       ? &RuntimeCallStats::PrototypeObject_DeleteProperty
                       : &RuntimeCallStats::Object_DeleteProperty);
+    TRACE_RUNTIME_CALL(is_prototype_map ? "PrototypeObject_DeleteProperty"
+                                        : "Object_DeleteProperty");
 
     PropertyNormalizationMode mode =
         is_prototype_map ? KEEP_INOBJECT_PROPERTIES : CLEAR_INOBJECT_PROPERTIES;

src/objects.cc

@@ -9161,6 +9161,9 @@ Handle<Map> Map::TransitionToDataProperty(Handle<Map> map, Handle<Name> name,
       *map, map->is_prototype_map()
                 ? &RuntimeCallStats::PrototypeMap_TransitionToDataProperty
                 : &RuntimeCallStats::Map_TransitionToDataProperty);
+  TRACE_RUNTIME_CALL(map->is_prototype_map()
+                         ? "PrototypeMap_TransitionToDataProperty"
+                         : "Map_TransitionToDataProperty");
 
   DCHECK(name->IsUniqueName());
   DCHECK(!map->is_dictionary_map());
@@ -9247,6 +9250,9 @@ Handle<Map> Map::TransitionToAccessorProperty(Isolate* isolate, Handle<Map> map,
       map->is_prototype_map()
           ? &RuntimeCallStats::PrototypeMap_TransitionToAccessorProperty
           : &RuntimeCallStats::Map_TransitionToAccessorProperty);
+  TRACE_RUNTIME_CALL(map->is_prototype_map()
+                         ? "PrototypeMap_TransitionToAccessorProperty"
+                         : "Map_TransitionToAccessorProperty");
 
   // At least one of the accessors needs to be a new value.
   DCHECK(!getter->IsNull() || !setter->IsNull());
@@ -12110,6 +12116,7 @@ Handle<Cell> Map::GetOrCreatePrototypeChainValidityCell(Handle<Map> map,
 void Map::SetPrototype(Handle<Map> map, Handle<Object> prototype,
                        PrototypeOptimizationMode proto_mode) {
   RuntimeCallTimerScope stats_scope(*map, &RuntimeCallStats::Map_SetPrototype);
+  TRACE_RUNTIME_CALL("Map_SetPrototype");
 
   bool is_hidden = false;
   if (prototype->IsJSObject()) {

src/tracing/trace-event.cc

@@ -10,6 +10,10 @@ namespace v8 {
 namespace internal {
 namespace tracing {
 
+// A global flag used as a shortcut to check for the
+// v8.runtime category due to its high frequency use.
+int kRuntimeCallsTracingEnabled = 0;
+
 v8::Platform* TraceEventHelper::GetCurrentPlatform() {
   return v8::internal::V8::GetCurrentPlatform();
 }

src/tracing/trace-event.h

@@ -292,6 +292,8 @@ const int kZeroNumArgs = 0;
 const decltype(nullptr) kGlobalScope = nullptr;
 const uint64_t kNoId = 0;
 
+extern int kRuntimeCallsTracingEnabled;
+
 class TraceEventHelper {
  public:
   static v8::Platform* GetCurrentPlatform();
@@ -594,4 +596,25 @@ class TraceEventSamplingStateScope {
 }  // namespace internal
 }  // namespace v8
 
+// V8 Specific macros
+#define TRACE_IS_RUNTIME_CALLS_TRACING_ENABLED() \
+  v8::internal::tracing::kRuntimeCallsTracingEnabled == 1
+
+#define TRACE_CHECK_AND_SET_RUNTIME_CALLS_TRACING()                           \
+  do {                                                                        \
+    INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(                                   \
+        TRACE_DISABLED_BY_DEFAULT("v8.runtime"));                             \
+    v8::internal::tracing::kRuntimeCallsTracingEnabled =                      \
+        INTERNAL_TRACE_EVENT_CATEGORY_GROUP_ENABLED_FOR_RECORDING_MODE() ? 1  \
+                                                                         : 0; \
+  } while (0)
+
+#define TRACE_RUNTIME_CALL(name)                                               \
+  do {                                                                         \
+    if (V8_UNLIKELY(TRACE_IS_RUNTIME_CALLS_TRACING_ENABLED())) {               \
+      INTERNAL_TRACE_EVENT_ADD_SCOPED(TRACE_DISABLED_BY_DEFAULT("v8.runtime"), \
+                                      name);                                   \
+    }                                                                          \
+  } while (0)
+
 #endif  // SRC_TRACING_TRACE_EVENT_H_