Reland: Add a trace-event for each runtime-stats timer (CL 2052523002)

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.

The original CL was failing the TSAN builder, the variable in question was intended to be accessed quickly with no guarantee.
Switched to using an Atomic variable with no barrier read/write.

BUG=v8:5089

patch from issue 2052523002 at patchset 100001 (http://crrev.com/2052523002#ps100001)

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

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;
@@ -4354,6 +4357,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**));
@@ -4382,6 +4386,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);
@@ -4432,6 +4437,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);
@@ -4457,6 +4463,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**));
@@ -5604,6 +5611,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;
@@ -8794,6 +8803,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);
@@ -8807,6 +8817,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(isolate) || !setter->IsNull(isolate));
@@ -12112,6 +12118,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

@@ -6,6 +6,10 @@
 
 #include "src/v8.h"
 
+// A global flag used as a shortcut to check for the
+// v8.runtime category due to its high frequency use.
+TRACE_EVENT_API_ATOMIC_BYTE g_runtime_calls_trace_enabled = 0;
+
 namespace v8 {
 namespace internal {
 namespace tracing {

src/tracing/trace-event.h

@@ -133,6 +133,7 @@ enum CategoryGroupEnabledFlags {
       ->UpdateTraceEventDuration
 
 // Defines atomic operations used internally by the tracing system.
+#define TRACE_EVENT_API_ATOMIC_BYTE v8::base::Atomic8
 #define TRACE_EVENT_API_ATOMIC_WORD v8::base::AtomicWord
 #define TRACE_EVENT_API_ATOMIC_LOAD(var) v8::base::NoBarrier_Load(&(var))
 #define TRACE_EVENT_API_ATOMIC_STORE(var, value) \
@@ -594,4 +595,31 @@ class TraceEventSamplingStateScope {
 }  // namespace internal
 }  // namespace v8
 
+// V8 Specific macros
+
+// Runtime calls happen at a high frequency, the following set of macros
+// minimizes the tracing overhead of those calls. A global variable is set
+// when top level V8 API is called, and checked per runtime call.
+extern TRACE_EVENT_API_ATOMIC_BYTE g_runtime_calls_trace_enabled;
+
+#define TRACE_IS_RUNTIME_CALLS_TRACING_ENABLED() \
+  TRACE_EVENT_API_ATOMIC_LOAD(g_runtime_calls_trace_enabled)
+
+#define TRACE_CHECK_AND_SET_RUNTIME_CALLS_TRACING()                            \
+  do {                                                                         \
+    INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(                                    \
+        TRACE_DISABLED_BY_DEFAULT("v8.runtime"));                              \
+    TRACE_EVENT_API_ATOMIC_STORE(g_runtime_calls_trace_enabled,                \
+        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_