Include getters and setters callbacks invocations in CPU profiler log.

Logging getters and setters from DOM API is extremely useful for web
developers as setting (and getting!) several properties can cause
page relayouts which take significant time.

Review URL: http://codereview.chromium.org/434074

git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@3363 ce2b1a6d-e550-0410-aec6-3dcde31c8c00

src/log.cc

@@ -680,22 +680,51 @@ class CompressionHelper {
 #endif  // ENABLE_LOGGING_AND_PROFILING
 
 
-void Logger::CallbackEvent(String* name, Address entry_point) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
+void Logger::CallbackEventInternal(const char* prefix, const char* name,
+                                   Address entry_point) {
   if (!Log::IsEnabled() || !FLAG_log_code) return;
   LogMessageBuilder msg;
   msg.Append("%s,%s,",
              log_events_[CODE_CREATION_EVENT], log_events_[CALLBACK_TAG]);
   msg.AppendAddress(entry_point);
-  SmartPointer<char> str =
-      name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
-  msg.Append(",1,\"%s\"", *str);
+  msg.Append(",1,\"%s%s\"", prefix, name);
   if (FLAG_compress_log) {
     ASSERT(compression_helper_ != NULL);
     if (!compression_helper_->HandleMessage(&msg)) return;
   }
   msg.Append('\n');
   msg.WriteToLogFile();
+}
+#endif
+
+
+void Logger::CallbackEvent(String* name, Address entry_point) {
+#ifdef ENABLE_LOGGING_AND_PROFILING
+  if (!Log::IsEnabled() || !FLAG_log_code) return;
+  SmartPointer<char> str =
+      name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
+  CallbackEventInternal("", *str, entry_point);
+#endif
+}
+
+
+void Logger::GetterCallbackEvent(String* name, Address entry_point) {
+#ifdef ENABLE_LOGGING_AND_PROFILING
+  if (!Log::IsEnabled() || !FLAG_log_code) return;
+  SmartPointer<char> str =
+      name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
+  CallbackEventInternal("get ", *str, entry_point);
+#endif
+}
+
+
+void Logger::SetterCallbackEvent(String* name, Address entry_point) {
+#ifdef ENABLE_LOGGING_AND_PROFILING
+  if (!Log::IsEnabled() || !FLAG_log_code) return;
+  SmartPointer<char> str =
+      name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
+  CallbackEventInternal("set ", *str, entry_point);
 #endif
 }
 
@@ -1098,6 +1127,7 @@ void Logger::ResumeProfiler(int flags) {
       LOG(UncheckedStringEvent("profiler", "resume"));
       FLAG_log_code = true;
       LogCompiledFunctions();
+      LogAccessorCallbacks();
       if (!FLAG_sliding_state_window) ticker_->Start();
     }
     profiler_->resume();
@@ -1242,6 +1272,28 @@ void Logger::LogCompiledFunctions() {
   DeleteArray(sfis);
 }
 
+
+void Logger::LogAccessorCallbacks() {
+  AssertNoAllocation no_alloc;
+  HeapIterator iterator;
+  while (iterator.has_next()) {
+    HeapObject* obj = iterator.next();
+    ASSERT(obj != NULL);
+    if (!obj->IsAccessorInfo()) continue;
+    AccessorInfo* ai = AccessorInfo::cast(obj);
+    if (!ai->name()->IsString()) continue;
+    String* name = String::cast(ai->name());
+    Address getter_entry = v8::ToCData<Address>(ai->getter());
+    if (getter_entry != 0) {
+      LOG(GetterCallbackEvent(name, getter_entry));
+    }
+    Address setter_entry = v8::ToCData<Address>(ai->setter());
+    if (setter_entry != 0) {
+      LOG(SetterCallbackEvent(name, setter_entry));
+    }
+  }
+}
+
 #endif
 
 

src/log.h

@@ -208,6 +208,8 @@ class Logger {
   // ==== Events logged by --log-code. ====
   // Emits a code event for a callback function.
   static void CallbackEvent(String* name, Address entry_point);
+  static void GetterCallbackEvent(String* name, Address entry_point);
+  static void SetterCallbackEvent(String* name, Address entry_point);
   // Emits a code create event.
   static void CodeCreateEvent(LogEventsAndTags tag,
                               Code* code, const char* source);
@@ -273,6 +275,8 @@ class Logger {
 
   // Logs all compiled functions found in the heap.
   static void LogCompiledFunctions();
+  // Logs all accessor callbacks found in the heap.
+  static void LogAccessorCallbacks();
   // Used for logging stubs found in the snapshot.
   static void LogCodeObject(Object* code_object);
 
@@ -287,6 +291,11 @@ class Logger {
   // Emits the profiler's first message.
   static void ProfilerBeginEvent();
 
+  // Emits callback event messages.
+  static void CallbackEventInternal(const char* prefix,
+                                    const char* name,
+                                    Address entry_point);
+
   // Emits aliases for compressed messages.
   static void LogAliases();
 

src/stub-cache.cc

@@ -750,6 +750,9 @@ Object* LoadCallbackProperty(Arguments args) {
   {
     // Leaving JavaScript.
     VMState state(EXTERNAL);
+#ifdef ENABLE_LOGGING_AND_PROFILING
+    state.set_external_callback(getter_address);
+#endif
     result = fun(v8::Utils::ToLocal(args.at<String>(4)), info);
   }
   RETURN_IF_SCHEDULED_EXCEPTION();
@@ -773,6 +776,9 @@ Object* StoreCallbackProperty(Arguments args) {
   {
     // Leaving JavaScript.
     VMState state(EXTERNAL);
+#ifdef ENABLE_LOGGING_AND_PROFILING
+    state.set_external_callback(setter_address);
+#endif
     fun(v8::Utils::ToLocal(name), v8::Utils::ToLocal(value), info);
   }
   RETURN_IF_SCHEDULED_EXCEPTION();

test/cctest/test-log.cc

@@ -538,6 +538,81 @@ TEST(LogCallbacks) {
 }
 
 
+static v8::Handle<v8::Value> Prop1Getter(v8::Local<v8::String> property,
+                                         const v8::AccessorInfo& info) {
+  return v8::Handle<v8::Value>();
+}
+
+static void Prop1Setter(v8::Local<v8::String> property,
+                                         v8::Local<v8::Value> value,
+                                         const v8::AccessorInfo& info) {
+}
+
+static v8::Handle<v8::Value> Prop2Getter(v8::Local<v8::String> property,
+                                         const v8::AccessorInfo& info) {
+  return v8::Handle<v8::Value>();
+}
+
+TEST(LogAccessorCallbacks) {
+  const bool saved_prof_lazy = i::FLAG_prof_lazy;
+  const bool saved_prof = i::FLAG_prof;
+  const bool saved_prof_auto = i::FLAG_prof_auto;
+  i::FLAG_prof = true;
+  i::FLAG_prof_lazy = false;
+  i::FLAG_prof_auto = false;
+  i::FLAG_logfile = "*";
+
+  // If tests are being run manually, V8 will be already initialized
+  // by the bottom test.
+  const bool need_to_set_up_logger = i::V8::IsRunning();
+  v8::HandleScope scope;
+  v8::Handle<v8::Context> env = v8::Context::New();
+  if (need_to_set_up_logger) Logger::Setup();
+  env->Enter();
+
+  // Skip all initially logged stuff.
+  EmbeddedVector<char, 102400> buffer;
+  int log_pos = GetLogLines(0, &buffer);
+
+  v8::Persistent<v8::FunctionTemplate> obj =
+      v8::Persistent<v8::FunctionTemplate>::New(v8::FunctionTemplate::New());
+  obj->SetClassName(v8::String::New("Obj"));
+  v8::Handle<v8::ObjectTemplate> inst = obj->InstanceTemplate();
+  inst->SetAccessor(v8::String::New("prop1"), Prop1Getter, Prop1Setter);
+  inst->SetAccessor(v8::String::New("prop2"), Prop2Getter);
+
+  i::Logger::LogAccessorCallbacks();
+  log_pos = GetLogLines(log_pos, &buffer);
+  CHECK_GT(log_pos, 0);
+  buffer[log_pos] = 0;
+  printf("%s", buffer.start());
+
+  EmbeddedVector<char, 100> prop1_getter_record;
+  i::OS::SNPrintF(prop1_getter_record,
+                  "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop1\"",
+                  Prop1Getter);
+  CHECK_NE(NULL, strstr(buffer.start(), prop1_getter_record.start()));
+  EmbeddedVector<char, 100> prop1_setter_record;
+  i::OS::SNPrintF(prop1_setter_record,
+                  "code-creation,Callback,0x%" V8PRIxPTR ",1,\"set prop1\"",
+                  Prop1Setter);
+  CHECK_NE(NULL, strstr(buffer.start(), prop1_setter_record.start()));
+  EmbeddedVector<char, 100> prop2_getter_record;
+  i::OS::SNPrintF(prop2_getter_record,
+                  "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop2\"",
+                  Prop2Getter);
+  CHECK_NE(NULL, strstr(buffer.start(), prop2_getter_record.start()));
+
+  obj.Dispose();
+
+  env->Exit();
+  Logger::TearDown();
+  i::FLAG_prof_lazy = saved_prof_lazy;
+  i::FLAG_prof = saved_prof;
+  i::FLAG_prof_auto = saved_prof_auto;
+}
+
+
 static inline bool IsStringEqualTo(const char* r, const char* s) {
   return strncmp(r, s, strlen(r)) == 0;
 }

tools/codemap.js

@@ -244,7 +244,7 @@ devtools.profiler.CodeMap.CodeEntry.prototype.toString = function() {
 
 
 devtools.profiler.CodeMap.NameGenerator = function() {
-  this.knownNames_ = [];
+  this.knownNames_ = {};
 };