Fix CPU profiling for Crankshaft.

src/log.cc

 // Copyright 2009 the V8 project authors. All rights reserved.
 // Redistribution and use in source and binary forms, with or without
 // modification, are permitted provided that the following conditions are
 // met:
 //
 //     * Redistributions of source code must retain the above copyright
 //       notice, this list of conditions and the following disclaimer.
 //     * Redistributions in binary form must reproduce the above
 //       copyright notice, this list of conditions and the following
 //       disclaimer in the documentation and/or other materials provided
@@ skipping 141 matching lines @@
 
   // Avoid collecting traces while doing GC.
   if (sample->state == GC) return;
 
   const Address js_entry_sp = Top::js_entry_sp(Top::GetCurrentThread());
   if (js_entry_sp == 0) {
     // Not executing JS now.
     return;
   }
 
-  const Address function_address =
-      sample->fp + JavaScriptFrameConstants::kFunctionOffset;
-  if (SafeStackFrameIterator::IsWithinBounds(sample->sp, js_entry_sp,
-                                             function_address)) {
-    Object* object = Memory::Object_at(function_address);
-    if (object->IsHeapObject()) {
-      sample->function = HeapObject::cast(object)->address();
-    }
-  }
+  // Sample potential return address value for frameless invocation of
+  // stubs (we'll figure out later, if this value makes sense).
+  sample->function = Memory::Address_at(sample->sp);

[Vitaly Repeshko, 2011/02/22 15:11:19]

We should rename the "function" field in TickSample. How about "tos_value"?

[mnaganov (inactive), 2011/02/22 16:18:22]

Renamed it to "tos" -- it's shorter.

 
   int i = 0;
   const Address callback = Top::external_callback();
   // Surprisingly, PC can point _exactly_ to callback start, with good
   // probability, and this will result in reporting fake nested
   // callback call.
   if (callback != NULL && callback != sample->pc) {
     sample->stack[i++] = callback;
   }
 
   SafeStackTraceFrameIterator it(sample->fp, sample->sp,
                                  sample->sp, js_entry_sp);
   while (!it.done() && i < TickSample::kMaxFramesCount) {
-    Object* object = it.frame()->function_slot_object();
-    if (object->IsHeapObject()) {
-      sample->stack[i++] = HeapObject::cast(object)->address();
-    }
+    sample->stack[i++] = it.frame()->pc();
     it.Advance();
   }
   sample->frames_count = i;
 }
 
 
 //
 // Ticker used to provide ticks to the profiler and the sliding state
 // window.
 //
@@ skipping 505 matching lines @@
 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
 }
 
 
-#ifdef ENABLE_LOGGING_AND_PROFILING
-static const char* ComputeMarker(Code* code) {
-  switch (code->kind()) {
-    case Code::FUNCTION: return code->optimizable() ? "~" : "";
-    case Code::OPTIMIZED_FUNCTION: return "*";
-    default: return "";
-  }
-}
-#endif
-
-
 void Logger::CodeCreateEvent(LogEventsAndTags tag,
                              Code* code,
                              const char* comment) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log_code) return;
   LogMessageBuilder msg;
   msg.Append("%s,%s,",
              kLogEventsNames[CODE_CREATION_EVENT],
              kLogEventsNames[tag]);
   msg.AppendAddress(code->address());
-  msg.Append(",%d,\"%s", code->ExecutableSize(), ComputeMarker(code));
+  msg.Append(",%d,\"", code->ExecutableSize());
   for (const char* p = comment; *p != '\0'; p++) {
     if (*p == '"') {
       msg.Append('\\');
     }
     msg.Append(*p);
   }
   msg.Append('"');
   LowLevelCodeCreateEvent(code, &msg);
   msg.Append('\n');
   msg.WriteToLogFile();
 #endif
 }
 
 
-void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name) {
+void Logger::CodeCreateEvent(LogEventsAndTags tag,
+                             Code* code,
+                             String* name) {
+#ifdef ENABLE_LOGGING_AND_PROFILING
+  if (name != NULL) {
+    SmartPointer<char> str =
+        name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
+    CodeCreateEvent(tag, code, *str);
+  } else {
+    CodeCreateEvent(tag, code, "");
+  }
+#endif
+}
+
+
+#ifdef ENABLE_LOGGING_AND_PROFILING
+// ComputeMarker must only be used when SharedFunctionInfo is known.
+static const char* ComputeMarker(Code* code) {
+  switch (code->kind()) {
+    case Code::FUNCTION: return code->optimizable() ? "~" : "";
+    case Code::OPTIMIZED_FUNCTION: return "*";
+    default: return "";
+  }
+}
+#endif
+
+
+void Logger::CodeCreateEvent(LogEventsAndTags tag,
+                             Code* code,
+                             SharedFunctionInfo *shared,
+                             String* name) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log_code) return;
+  if (code == Builtins::builtin(Builtins::LazyCompile)) return;

[Vitaly Repeshko, 2011/02/22 15:11:19]

Can we make the caller do this check for us? (I think it should only matter for
calls made from compiler.cc.)

[mnaganov (inactive), 2011/02/22 16:18:22]

Good idea. BTW, I forgot to add a similar check to cpu-profiler, so your
suggestion eliminates an issue ;)

LazyCompile builtins can only be passed from Compiler::RecordFunctionCompilation
and Logger::LogCompiledFunctions, so I moved checks there.

   LogMessageBuilder msg;
   SmartPointer<char> str =
       name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
   msg.Append("%s,%s,",
              kLogEventsNames[CODE_CREATION_EVENT],
              kLogEventsNames[tag]);
   msg.AppendAddress(code->address());
-  msg.Append(",%d,\"%s%s\"", code->ExecutableSize(), ComputeMarker(code), *str);
+  msg.Append(",%d,\"%s\",", code->ExecutableSize(), *str);
+  msg.AppendAddress(shared->address());
+  msg.Append(",%s", ComputeMarker(code));
   LowLevelCodeCreateEvent(code, &msg);
   msg.Append('\n');
   msg.WriteToLogFile();
 #endif
 }
 
 
+// Although, it is possible to extract source and line from
+// the SharedFunctionInfo object, we left it to caller
+// to leave logging functions free from heap allocations.
 void Logger::CodeCreateEvent(LogEventsAndTags tag,
-                             Code* code, String* name,
+                             Code* code,
+                             SharedFunctionInfo *shared,

[Vitaly Repeshko, 2011/02/22 15:11:19]

Same nit.

[mnaganov (inactive), 2011/02/22 16:18:22]

Done.

                              String* source, int line) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log_code) return;
+  if (code == Builtins::builtin(Builtins::LazyCompile)) return;
   LogMessageBuilder msg;
-  SmartPointer<char> str =
-      name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
+  SmartPointer<char> name =
+      shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
   SmartPointer<char> sourcestr =
       source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
   msg.Append("%s,%s,",
              kLogEventsNames[CODE_CREATION_EVENT],
              kLogEventsNames[tag]);
   msg.AppendAddress(code->address());
-  msg.Append(",%d,\"%s%s %s:%d\"",
+  msg.Append(",%d,\"%s %s:%d\",",
              code->ExecutableSize(),
-             ComputeMarker(code),
-             *str,
+             *name,
              *sourcestr,
              line);
+  msg.AppendAddress(shared->address());
+  msg.Append(",%s", ComputeMarker(code));
   LowLevelCodeCreateEvent(code, &msg);
   msg.Append('\n');
   msg.WriteToLogFile();
 #endif
 }
 
 
 void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log_code) return;
@@ skipping 59 matching lines @@
   LogMessageBuilder msg;
   msg.Append("%s,", kLogEventsNames[SNAPSHOT_POSITION_EVENT]);
   msg.AppendAddress(addr);
   msg.Append(",%d", pos);
   msg.Append('\n');
   msg.WriteToLogFile();
 #endif
 }
 
 
-void Logger::FunctionCreateEvent(JSFunction* function) {
+void Logger::SFIMoveEvent(Address from, Address to) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
-  // This function can be called from GC iterators (during Scavenge,
-  // MC, and MS), so marking bits can be set on objects. That's
-  // why unchecked accessors are used here.
-  if (!Log::IsEnabled() || !FLAG_log_code) return;
-  LogMessageBuilder msg;
-  msg.Append("%s,", kLogEventsNames[FUNCTION_CREATION_EVENT]);
-  msg.AppendAddress(function->address());
-  msg.Append(',');
-  msg.AppendAddress(function->unchecked_code()->address());
-  msg.Append('\n');
-  msg.WriteToLogFile();
+  MoveEventInternal(SFI_MOVE_EVENT, from, to);
 #endif
 }
 
-
-void Logger::FunctionCreateEventFromMove(JSFunction* function) {
-#ifdef ENABLE_LOGGING_AND_PROFILING
-  if (function->unchecked_code() != Builtins::builtin(Builtins::LazyCompile)) {
-    FunctionCreateEvent(function);
-  }
-#endif
-}
-
-
-void Logger::FunctionMoveEvent(Address from, Address to) {
-#ifdef ENABLE_LOGGING_AND_PROFILING
-  MoveEventInternal(FUNCTION_MOVE_EVENT, from, to);
-#endif
-}
-
-
-void Logger::FunctionDeleteEvent(Address from) {
-#ifdef ENABLE_LOGGING_AND_PROFILING
-  DeleteEventInternal(FUNCTION_DELETE_EVENT, from);
-#endif
-}
-
 
 #ifdef ENABLE_LOGGING_AND_PROFILING
 void Logger::MoveEventInternal(LogEventsAndTags event,
                                Address from,
                                Address to) {
   if (!Log::IsEnabled() || !FLAG_log_code) return;
   LogMessageBuilder msg;
   msg.Append("%s,", kLogEventsNames[event]);
   msg.AppendAddress(from);
   msg.Append(',');
@@ skipping 265 matching lines @@
     UncheckedIntEvent("open-tag", tag);
   }
   if (profiler_ != NULL && (flags & PROFILER_MODULE_CPU)) {
     if (cpu_profiler_nesting_++ == 0) {
       ++logging_nesting_;
       if (FLAG_prof_lazy) {
         profiler_->Engage();
         LOG(UncheckedStringEvent("profiler", "resume"));
         FLAG_log_code = true;
         LogCompiledFunctions();
-        LogFunctionObjects();
         LogAccessorCallbacks();
         if (!FLAG_sliding_state_window && !ticker_->IsActive()) {
           ticker_->Start();
         }
       }
       profiler_->resume();
     }
   }
   if (flags &
       (PROFILER_MODULE_HEAP_STATS | PROFILER_MODULE_JS_CONSTRUCTORS)) {
@@ skipping 181 matching lines @@
   HandleScope scope;
   const int compiled_funcs_count = EnumerateCompiledFunctions(NULL, NULL);
   ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count);
   ScopedVector< Handle<Code> > code_objects(compiled_funcs_count);
   EnumerateCompiledFunctions(sfis.start(), code_objects.start());
 
   // During iteration, there can be heap allocation due to
   // GetScriptLineNumber call.
   for (int i = 0; i < compiled_funcs_count; ++i) {
     Handle<SharedFunctionInfo> shared = sfis[i];
-    Handle<String> name(String::cast(shared->name()));
-    Handle<String> func_name(name->length() > 0 ?
-                             *name : shared->inferred_name());
+    Handle<String> func_name(shared->DebugName());
     if (shared->script()->IsScript()) {
       Handle<Script> script(Script::cast(shared->script()));
       if (script->name()->IsString()) {
         Handle<String> script_name(String::cast(script->name()));
         int line_num = GetScriptLineNumber(script, shared->start_position());
         if (line_num > 0) {
           PROFILE(CodeCreateEvent(
               Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
-              *code_objects[i], *func_name,
+              *code_objects[i], *shared,
               *script_name, line_num + 1));
         } else {
           // Can't distinguish eval and script here, so always use Script.
           PROFILE(CodeCreateEvent(
               Logger::ToNativeByScript(Logger::SCRIPT_TAG, *script),
-              *code_objects[i], *script_name));
+              *code_objects[i], *shared, *script_name));
         }
       } else {
         PROFILE(CodeCreateEvent(
             Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
-            *code_objects[i], *func_name));
+            *code_objects[i], *shared, *func_name));
       }
     } else if (shared->IsApiFunction()) {
       // API function.
       FunctionTemplateInfo* fun_data = shared->get_api_func_data();
       Object* raw_call_data = fun_data->call_code();
       if (!raw_call_data->IsUndefined()) {
         CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data);
         Object* callback_obj = call_data->callback();
         Address entry_point = v8::ToCData<Address>(callback_obj);
         PROFILE(CallbackEvent(*func_name, entry_point));
       }
     } else {
       PROFILE(CodeCreateEvent(
-          Logger::LAZY_COMPILE_TAG, *code_objects[i], *func_name));
+          Logger::LAZY_COMPILE_TAG, *code_objects[i], *shared, *func_name));
     }
   }
 }
 
 
-void Logger::LogFunctionObjects() {
-  AssertNoAllocation no_alloc;
-  HeapIterator iterator;
-  for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
-    if (!obj->IsJSFunction()) continue;
-    JSFunction* jsf = JSFunction::cast(obj);
-    if (!jsf->is_compiled()) continue;
-    PROFILE(FunctionCreateEvent(jsf));
-  }
-}
-
-
 void Logger::LogAccessorCallbacks() {
   AssertNoAllocation no_alloc;
   HeapIterator iterator;
   for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) {
     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) {
@@ skipping 172 matching lines @@
   }
   // Otherwise, if the sliding state window computation has not been
   // started we do it now.
   if (sliding_state_window_ == NULL) {
     sliding_state_window_ = new SlidingStateWindow();
   }
 #endif
 }
 
 } }  // namespace v8::internal