Support profiling based on linux kernel performance events.

Since 2.6.31 perf_events interface has been available in the
kernel. There's a nice tool called "perf" (linux-2.6/tools/perf) that
uses this interface and provides capabilities similar to oprofile. The
simplest form of its usage is just dumping the raw log (trace) of
events generated by the kernel. In this patch I'm adding a script
(tools/ll_prof.py) to build profiles based on perf trace and our code
log. All the heavy-lifting is done by perf. Compared to oprofile agent
this approach does not require recompilation and supports code moving
garbage collections.

Expected usage is documented in the ll_prof's help. Basically one
should run V8 under perf passing --ll-prof flag and then the produced
logs can be analyzed by tools/ll_prof.py.

The new --ll-prof flag enables logging of generated code object
locations and names (like --log-code), and also of their bodies, which
can be later disassembled and annotated by the script.

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

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

src/cpu-profiler.h

@@ -251,6 +251,7 @@ class CpuProfiler {
                               String* source, int line);
   static void CodeCreateEvent(Logger::LogEventsAndTags tag,
                               Code* code, int args_count);
+  static void CodeMovingGCEvent() {}
   static void CodeMoveEvent(Address from, Address to);
   static void CodeDeleteEvent(Address from);
   static void FunctionCreateEvent(JSFunction* function);

src/flag-definitions.h

@@ -412,6 +412,7 @@ DEFINE_bool(sliding_state_window, false,
             "Update sliding state window counters.")
 DEFINE_string(logfile, "v8.log", "Specify the name of the log file.")
 DEFINE_bool(oprofile, false, "Enable JIT agent for OProfile.")
+DEFINE_bool(ll_prof, false, "Enable low-level linux profiler.")
 
 //
 // Heap protection flags

src/heap.cc

@@ -662,6 +662,10 @@ void Heap::UpdateSurvivalRateTrend(int start_new_space_size) {
 void Heap::PerformGarbageCollection(GarbageCollector collector,
                                     GCTracer* tracer,
                                     CollectionPolicy collectionPolicy) {
+  if (collector != SCAVENGER) {
+    PROFILE(CodeMovingGCEvent());
+  }
+
   VerifySymbolTable();
   if (collector == MARK_COMPACTOR && global_gc_prologue_callback_) {
     ASSERT(!allocation_allowed_);

src/log-utils.cc

@@ -122,6 +122,7 @@ int LogDynamicBuffer::WriteInternal(const char* data, int data_size) {
 bool Log::is_stopped_ = false;
 Log::WritePtr Log::Write = NULL;
 FILE* Log::output_handle_ = NULL;
+FILE* Log::output_code_handle_ = NULL;
 LogDynamicBuffer* Log::output_buffer_ = NULL;
 // Must be the same message as in Logger::PauseProfiler.
 const char* Log::kDynamicBufferSeal = "profiler,\"pause\"\n";
@@ -143,9 +144,21 @@ void Log::OpenStdout() {
 }
 
 
+static const char kCodeLogExt[] = ".code";
+
+
 void Log::OpenFile(const char* name) {
   ASSERT(!IsEnabled());
   output_handle_ = OS::FOpen(name, OS::LogFileOpenMode);
+  if (FLAG_ll_prof) {
+    // Open a file for logging the contents of code objects so that
+    // they can be disassembled later.
+    size_t name_len = strlen(name);
+    ScopedVector<char> code_name(name_len + sizeof(kCodeLogExt));
+    memcpy(code_name.start(), name, name_len);
+    memcpy(code_name.start() + name_len, kCodeLogExt, sizeof(kCodeLogExt));
+    output_code_handle_ = OS::FOpen(code_name.start(), OS::LogFileOpenMode);
+  }
   Write = WriteToFile;
   Init();
 }
@@ -165,6 +178,8 @@ void Log::Close() {
   if (Write == WriteToFile) {
     if (output_handle_ != NULL) fclose(output_handle_);
     output_handle_ = NULL;
+    if (output_code_handle_ != NULL) fclose(output_code_handle_);
+    output_code_handle_ = NULL;
   } else if (Write == WriteToMemory) {
     delete output_buffer_;
     output_buffer_ = NULL;

src/log-utils.h

@@ -152,6 +152,9 @@ class Log : public AllStatic {
   // mutex_ should be acquired before using output_handle_ or output_buffer_.
   static FILE* output_handle_;
 
+  // Used when low-level profiling is active to save code object contents.
+  static FILE* output_code_handle_;
+
   static LogDynamicBuffer* output_buffer_;
 
   // Size of dynamic buffer block (and dynamic buffer initial size).
@@ -171,6 +174,7 @@ class Log : public AllStatic {
   // mutex_ should be acquired before using it.
   static char* message_buffer_;
 
+  friend class Logger;
   friend class LogMessageBuilder;
   friend class LogRecordCompressor;
 };

src/log.cc

@@ -766,6 +766,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag,
     msg.Append(*p);
   }
   msg.Append('"');
+  LowLevelCodeCreateEvent(code, &msg);
   if (FLAG_compress_log) {
     ASSERT(compression_helper_ != NULL);
     if (!compression_helper_->HandleMessage(&msg)) return;
@@ -785,6 +786,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name) {
   msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
   msg.AppendAddress(code->address());
   msg.Append(",%d,\"%s\"", code->ExecutableSize(), *str);
+  LowLevelCodeCreateEvent(code, &msg);
   if (FLAG_compress_log) {
     ASSERT(compression_helper_ != NULL);
     if (!compression_helper_->HandleMessage(&msg)) return;
@@ -809,6 +811,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag,
   msg.AppendAddress(code->address());
   msg.Append(",%d,\"%s %s:%d\"",
              code->ExecutableSize(), *str, *sourcestr, line);
+  LowLevelCodeCreateEvent(code, &msg);
   if (FLAG_compress_log) {
     ASSERT(compression_helper_ != NULL);
     if (!compression_helper_->HandleMessage(&msg)) return;
@@ -826,6 +829,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
   msg.Append("%s,%s,", log_events_[CODE_CREATION_EVENT], log_events_[tag]);
   msg.AppendAddress(code->address());
   msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
+  LowLevelCodeCreateEvent(code, &msg);
   if (FLAG_compress_log) {
     ASSERT(compression_helper_ != NULL);
     if (!compression_helper_->HandleMessage(&msg)) return;
@@ -836,6 +840,17 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
 }
 
 
+void Logger::CodeMovingGCEvent() {
+#ifdef ENABLE_LOGGING_AND_PROFILING
+  if (!Log::IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
+  LogMessageBuilder msg;
+  msg.Append("%s\n", log_events_[CODE_MOVING_GC]);
+  msg.WriteToLogFile();
+  OS::SignalCodeMovingGC();
+#endif
+}
+
+
 void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (!Log::IsEnabled() || !FLAG_log_code) return;
@@ -846,6 +861,7 @@ void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
   msg.Append(",%d,\"", code->ExecutableSize());
   msg.AppendDetailed(source, false);
   msg.Append('\"');
+  LowLevelCodeCreateEvent(code, &msg);
   if (FLAG_compress_log) {
     ASSERT(compression_helper_ != NULL);
     if (!compression_helper_->HandleMessage(&msg)) return;
@@ -1341,6 +1357,34 @@ void Logger::LogCodeObject(Object* object) {
 }
 
 
+void Logger::LogCodeInfo() {
+#ifdef ENABLE_LOGGING_AND_PROFILING
+  if (!Log::IsEnabled() || !FLAG_log_code || !FLAG_ll_prof) return;
+#if V8_TARGET_ARCH_IA32
+  const char arch[] = "ia32";
+#elif V8_TARGET_ARCH_X64
+  const char arch[] = "x64";
+#elif V8_TARGET_ARCH_ARM
+  const char arch[] = "arm";
+#else
+  const char arch[] = "unknown";
+#endif
+  LogMessageBuilder msg;
+  msg.Append("code-info,%s,%d\n", arch, Code::kHeaderSize);
+  msg.WriteToLogFile();
+#endif  // ENABLE_LOGGING_AND_PROFILING
+}
+
+
+void Logger::LowLevelCodeCreateEvent(Code* code, LogMessageBuilder* msg) {
+  if (!FLAG_ll_prof || Log::output_code_handle_ == NULL) return;
+  int pos = static_cast<int>(ftell(Log::output_code_handle_));
+  fwrite(code->instruction_start(), 1, code->instruction_size(),
+         Log::output_code_handle_);
+  msg->Append(",%d", pos);
+}
+
+
 void Logger::LogCodeObjects() {
   AssertNoAllocation no_alloc;
   HeapIterator iterator;
@@ -1452,6 +1496,12 @@ bool Logger::Setup() {
   // --prof implies --log-code.
   if (FLAG_prof) FLAG_log_code = true;
 
+  // --ll-prof implies --log-code and --log-snapshot-positions.
+  if (FLAG_ll_prof) {
+    FLAG_log_code = true;
+    FLAG_log_snapshot_positions = true;
+  }
+
   // --prof_lazy controls --log-code, implies --noprof_auto.
   if (FLAG_prof_lazy) {
     FLAG_log_code = false;
@@ -1513,6 +1563,8 @@ bool Logger::Setup() {
 
   ASSERT(VMState::is_outermost_external());
 
+  if (FLAG_ll_prof) LogCodeInfo();
+
   ticker_ = new Ticker(kSamplingIntervalMs);
 
   if (FLAG_sliding_state_window && sliding_state_window_ == NULL) {

src/log.h

@@ -91,6 +91,7 @@ class CompressionHelper;
   V(CODE_CREATION_EVENT,            "code-creation",          "cc")       \
   V(CODE_MOVE_EVENT,                "code-move",              "cm")       \
   V(CODE_DELETE_EVENT,              "code-delete",            "cd")       \
+  V(CODE_MOVING_GC,                 "code-moving-gc",         "cg")       \
   V(FUNCTION_CREATION_EVENT,        "function-creation",      "fc")       \
   V(FUNCTION_MOVE_EVENT,            "function-move",          "fm")       \
   V(FUNCTION_DELETE_EVENT,          "function-delete",        "fd")       \
@@ -209,6 +210,7 @@ class Logger {
   static void CodeCreateEvent(LogEventsAndTags tag, Code* code, String* name,
                               String* source, int line);
   static void CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count);
+  static void CodeMovingGCEvent();
   // Emits a code create event for a RegExp.
   static void RegExpCodeCreateEvent(Code* code, String* source);
   // Emits a code move event.
@@ -317,6 +319,12 @@ class Logger {
   // Used for logging stubs found in the snapshot.
   static void LogCodeObject(Object* code_object);
 
+  // Emits general information about generated code.
+  static void LogCodeInfo();
+
+  // Handles code creation when low-level profiling is active.
+  static void LowLevelCodeCreateEvent(Code* code, LogMessageBuilder* msg);
+
   // Emits a profiler tick event. Used by the profiler thread.
   static void TickEvent(TickSample* sample, bool overflow);
 

src/platform-freebsd.cc

@@ -291,6 +291,10 @@ void OS::LogSharedLibraryAddresses() {
 }
 
 
+void OS::SignalCodeMovingGC() {
+}
+
+
 int OS::StackWalk(Vector<OS::StackFrame> frames) {
   int frames_size = frames.length();
   ScopedVector<void*> addresses(frames_size);

src/platform-linux.cc

@@ -397,6 +397,30 @@ void OS::LogSharedLibraryAddresses() {
 }
 
 
+static const char kGCFakeMmap[] = "/tmp/__v8_gc__";
+
+
+void OS::SignalCodeMovingGC() {
+#ifdef ENABLE_LOGGING_AND_PROFILING
+  // Support for ll_prof.py.
+  //
+  // The Linux profiler built into the kernel logs all mmap's with
+  // PROT_EXEC so that analysis tools can properly attribute ticks. We
+  // do a mmap with a name known by ll_prof.py and immediately munmap
+  // it. This injects a GC marker into the stream of events generated
+  // by the kernel and allows us to synchronize V8 code log and the
+  // kernel log.
+  int size = sysconf(_SC_PAGESIZE);
+  FILE* f = fopen(kGCFakeMmap, "w+");
+  void* addr = mmap(NULL, size, PROT_READ | PROT_EXEC, MAP_PRIVATE,
+                    fileno(f), 0);
+  ASSERT(addr != MAP_FAILED);
+  munmap(addr, size);
+  fclose(f);
+#endif
+}
+
+
 int OS::StackWalk(Vector<OS::StackFrame> frames) {
   // backtrace is a glibc extension.
 #ifdef __GLIBC__

src/platform-macos.cc

@@ -245,6 +245,10 @@ void OS::LogSharedLibraryAddresses() {
 }
 
 
+void OS::SignalCodeMovingGC() {
+}
+
+
 uint64_t OS::CpuFeaturesImpliedByPlatform() {
   // MacOSX requires all these to install so we can assume they are present.
   // These constants are defined by the CPUid instructions.

src/platform-nullos.cc

@@ -240,6 +240,11 @@ void OS::LogSharedLibraryAddresses() {
 }
 
 
+void OS::SignalCodeMovingGC() {
+  UNIMPLEMENTED();
+}
+
+
 int OS::StackWalk(Vector<OS::StackFrame> frames) {
   UNIMPLEMENTED();
   return 0;

src/platform-openbsd.cc

@@ -289,6 +289,10 @@ void OS::LogSharedLibraryAddresses() {
 }
 
 
+void OS::SignalCodeMovingGC() {
+}
+
+
 int OS::StackWalk(Vector<OS::StackFrame> frames) {
   UNIMPLEMENTED();
   return 1;

src/platform-solaris.cc

@@ -256,6 +256,10 @@ void OS::LogSharedLibraryAddresses() {
 }
 
 
+void OS::SignalCodeMovingGC() {
+}
+
+
 struct StackWalker {
   Vector<OS::StackFrame>& frames;
   int index;

src/platform-win32.cc

@@ -1218,6 +1218,10 @@ void OS::LogSharedLibraryAddresses() {
 }
 
 
+void OS::SignalCodeMovingGC() {
+}
+
+
 // Walk the stack using the facilities in dbghelp.dll and tlhelp32.dll
 
 // Switch off warning 4748 (/GS can not protect parameters and local variables

src/platform.h

@@ -257,11 +257,16 @@ class OS {
   static char* StrChr(char* str, int c);
   static void StrNCpy(Vector<char> dest, const char* src, size_t n);
 
-  // Support for profiler.  Can do nothing, in which case ticks
-  // occuring in shared libraries will not be properly accounted
-  // for.
+  // Support for the profiler.  Can do nothing, in which case ticks
+  // occuring in shared libraries will not be properly accounted for.
   static void LogSharedLibraryAddresses();
 
+  // Support for the profiler.  Notifies the external profiling
+  // process that a code moving garbage collection starts.  Can do
+  // nothing, in which case the code objects must not move (e.g., by
+  // using --never-compact) if accurate profiling is desired.
+  static void SignalCodeMovingGC();
+
   // The return value indicates the CPU features we are sure of because of the
   // OS.  For example MacOSX doesn't run on any x86 CPUs that don't have SSE2
   // instructions.