Add logging of callbacks in prof-lazy mode.

This is needed to show calls to DOM in CPU profiles. I can think
of a better approach like adding specific functions into V8 API
for explicitly providing callback names and modifying bindings codegen
appropriately. My plan is as follows:
 - submit this CL;
 - implement anything I need to process log data and display DOM
   calls in profiles;
 - think again about adding specific functions and modifying bindings
   codegen.

BUG=http://code.google.com/p/chromium/issues/detail?id=27613

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

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

src/log.cc

@@ -30,6 +30,7 @@
 #include "v8.h"
 
 #include "bootstrapper.h"
+#include "global-handles.h"
 #include "log.h"
 #include "macro-assembler.h"
 #include "serialize.h"
@@ -637,6 +638,24 @@ void Logger::DeleteEvent(const char* name, void* object) {
 }
 
 
+void Logger::CallbackEvent(const char* class_name, const char* method_name,
+                           Address entry_point) {
+#ifdef ENABLE_LOGGING_AND_PROFILING
+  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);
+  msg.Append(",0,\"");
+  if (class_name != NULL) {
+    msg.Append("%s.", class_name);
+  }
+  msg.Append("%s\"\n", method_name);
+  msg.WriteToLogFile();
+#endif
+}
+
+
 #ifdef ENABLE_LOGGING_AND_PROFILING
 
 // A class that contains all common code dealing with record compression.
@@ -1071,6 +1090,7 @@ void Logger::ResumeProfiler(int flags) {
       LOG(UncheckedStringEvent("profiler", "resume"));
       FLAG_log_code = true;
       LogCompiledFunctions();
+      LogCallbacks();
       if (!FLAG_sliding_state_window) ticker_->Start();
     }
     profiler_->resume();
@@ -1201,6 +1221,69 @@ void Logger::LogCompiledFunctions() {
   DeleteArray(sfis);
 }
 
+
+namespace {
+
+class FunctionTemplateInfosVisitor : public ObjectVisitor {
+ public:
+  virtual ~FunctionTemplateInfosVisitor() {}
+  virtual void VisitPointers(Object** start, Object** end) {
+    for (Object** p = start; p < end; ++p) {
+      VisitFTI(*p);
+    }
+  }
+
+ private:
+  void VisitFTI(Object* o) {
+    // The data about callbacks is in fact dynamically typed
+    // (Object ptrs are used), so we use runtime type checking
+    // to be sure that we retrieve the right thing.
+    if (!o->IsFunctionTemplateInfo())
+      return;
+    AssertNoAllocation no_alloc;
+    FunctionTemplateInfo* fti = FunctionTemplateInfo::cast(o);
+    if (!fti->prototype_template()->IsObjectTemplateInfo())
+      return;
+    SmartPointer<char> class_name;
+    if (fti->class_name()->IsString()) {
+      class_name = String::cast(fti->class_name())->
+          ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
+    }
+    ObjectTemplateInfo* proto =
+        ObjectTemplateInfo::cast(fti->prototype_template());
+    NeanderArray props(Handle<Object>(proto->property_list()));
+    // Properties are triples: [property name, entry point, attributes].
+    // See Template::Set in api.cc.
+    for (int i = 0; i < props.length(); i += 3) {
+      if (!props.get(i)->IsString()
+          || !props.get(i + 1)->IsFunctionTemplateInfo())
+        continue;
+      FunctionTemplateInfo* native_fti =
+          FunctionTemplateInfo::cast(props.get(i + 1));
+      Object* raw_call_data = native_fti->call_code();
+      if (raw_call_data->IsUndefined())
+        continue;
+      CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
+      Object* callback_obj = call_data->callback();
+      Address entry_point = v8::ToCData<Address>(callback_obj);
+      SmartPointer<char> method_name(
+          String::cast(props.get(i))->
+          ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL));
+      LOG(CallbackEvent(*class_name, *method_name, entry_point));
+    }
+  }
+};
+
+}  // anonymous namespace
+
+
+void Logger::LogCallbacks() {
+  // We are looking for callbacks information exposed via persistent
+  // FunctionTemplate objects.
+  FunctionTemplateInfosVisitor visitor;
+  GlobalHandles::IterateStrongRoots(&visitor);
+}
+
 #endif
 
 

src/log.h

@@ -122,6 +122,7 @@ class VMState BASE_EMBEDDED {
   V(CALL_MISS_TAG,                  "CallMiss",               "cm")       \
   V(CALL_NORMAL_TAG,                "CallNormal",             "cn")       \
   V(CALL_PRE_MONOMORPHIC_TAG,       "CallPreMonomorphic",     "cpm")      \
+  V(CALLBACK_TAG,                   "Callback",               "cb")       \
   V(EVAL_TAG,                       "Eval",                   "e")        \
   V(FUNCTION_TAG,                   "Function",               "f")        \
   V(KEYED_LOAD_IC_TAG,              "KeyedLoadIC",            "klic")     \
@@ -200,6 +201,9 @@ class Logger {
 
 
   // ==== Events logged by --log-code. ====
+  // Emits a code event for a callback function.
+  static void CallbackEvent(const char* class_name, const char* method_name,
+                            Address entry_point);
   // Emits a code create event.
   static void CodeCreateEvent(LogEventsAndTags tag,
                               Code* code, const char* source);
@@ -267,6 +271,10 @@ class Logger {
   static void LogCompiledFunctions();
   // Used for logging stubs found in the snapshot.
   static void LogCodeObject(Object* code_object);
+  // Used for logging callback entry points to be able to reveal their
+  // names in call stacks when information about native code exports is
+  // inaccessible.
+  static void LogCallbacks();
 
  private:
 

test/cctest/test-log.cc

@@ -247,7 +247,7 @@ TEST(ProfLazyMode) {
   i::FLAG_logfile = "*";
 
   // If tests are being run manually, V8 will be already initialized
-  // by the test below.
+  // 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();
@@ -474,6 +474,66 @@ TEST(Issue23768) {
 }
 
 
+static v8::Handle<v8::Value> ObjMethod1(const v8::Arguments& args) {
+  return v8::Handle<v8::Value>();
+}
+
+TEST(LogCallbacks) {
+  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> proto = obj->PrototypeTemplate();
+  v8::Local<v8::Signature> signature = v8::Signature::New(obj);
+  proto->Set(v8::String::New("method1"),
+             v8::FunctionTemplate::New(ObjMethod1,
+                                       v8::Handle<v8::Value>(),
+                                       signature),
+             static_cast<v8::PropertyAttribute>(v8::DontDelete));
+
+  i::Logger::LogCallbacks();
+  log_pos = GetLogLines(log_pos, &buffer);
+  CHECK_GT(log_pos, 0);
+  buffer[log_pos] = 0;
+
+  const char* callback_rec = "code-creation,Callback,";
+  const char* pos = strstr(buffer.start(), callback_rec);
+  CHECK_NE(NULL, pos);
+  pos += strlen(callback_rec);
+  EmbeddedVector<char, 100> ref_data;
+  i::OS::SNPrintF(ref_data,
+                  "0x%" V8PRIxPTR ",0,\"Obj.method1\"\n", ObjMethod1);
+  CHECK_EQ(ref_data.start(), pos);
+
+  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;
 }