Revision: 3340
Author: [email protected]
Date: Fri Nov 20 04:15:46 2009
Log: 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
http://code.google.com/p/v8/source/detail?r=3340
Modified:
/branches/bleeding_edge/src/log.cc
/branches/bleeding_edge/src/log.h
/branches/bleeding_edge/test/cctest/test-log.cc
=======================================
--- /branches/bleeding_edge/src/log.cc Wed Nov 11 04:35:50 2009
+++ /branches/bleeding_edge/src/log.cc Fri Nov 20 04:15:46 2009
@@ -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,7 +638,25 @@
}
+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.
class CompressionHelper {
@@ -1071,6 +1090,7 @@
LOG(UncheckedStringEvent("profiler", "resume"));
FLAG_log_code = true;
LogCompiledFunctions();
+ LogCallbacks();
if (!FLAG_sliding_state_window) ticker_->Start();
}
profiler_->resume();
@@ -1200,6 +1220,69 @@
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
=======================================
--- /branches/bleeding_edge/src/log.h Wed Nov 11 04:35:50 2009
+++ /branches/bleeding_edge/src/log.h Fri Nov 20 04:15:46 2009
@@ -122,6 +122,7 @@
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 @@
// ==== 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 @@
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:
=======================================
--- /branches/bleeding_edge/test/cctest/test-log.cc Wed Nov 11 01:50:06 2009
+++ /branches/bleeding_edge/test/cctest/test-log.cc Fri Nov 20 04:15:46 2009
@@ -247,7 +247,7 @@
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();
@@ -472,6 +472,66 @@
// Must not crash.
i::Logger::LogCompiledFunctions();
}
+
+
+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) {
--~--~---------~--~----~------------~-------~--~----~
v8-dev mailing list
[email protected]
http://groups.google.com/group/v8-dev
-~----------~----~----~----~------~----~------~--~---
