Support for the Linux 'perf report' and 'perf annotate' tools.

src/log.cc

Index: src/log.cc
diff --git a/src/log.cc b/src/log.cc
index b353f548fb78b88d212b24b86391ccc08fb9c655..7440b14750f714c6539ef78e74466771b58286bb 100644
--- a/src/log.cc
+++ b/src/log.cc
@@ -246,6 +246,228 @@ void CodeEventLogger::RegExpCodeCreateEvent(Code* code, String* source) {
 }
 
 
+// Linux perf tool logging support
+class PerfBasicLogger : public CodeEventLogger {
+ public:
+  explicit PerfBasicLogger();

[danno, 2013/11/13 17:18:10]

Don't need explicit here, only for single argument constructors.

+  virtual ~PerfBasicLogger();
+
+  virtual void CodeMoveEvent(Address from, Address to) { }
+  virtual void CodeDeleteEvent(Address from) { }
+
+ private:
+  virtual void LogRecordedBuffer(Code* code,
+                                 SharedFunctionInfo* shared,
+                                 const char* name,
+                                 int length);
+
+  // Extension added to V8 log file name to get the low-level log name.
+  static const char kFilenameFormatString[];
+  static const int kFilenameBufferPadding;
+
+  // File buffer size of the low-level log. We don't use the default to
+  // minimize the associated overhead.
+  static const int kLogBufferSize = 2 * MB;
+
+  FILE* perf_output_handle_;
+};
+
+const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map";
+// Extra space for the PID in the filename
+const int PerfBasicLogger::kFilenameBufferPadding = 16;
+
+PerfBasicLogger::PerfBasicLogger()
+    : perf_output_handle_(NULL) {
+  // Open the perf JIT dump file.
+  int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
+  ScopedVector<char> perf_dump_name(bufferSize);
+  int size = OS::SNPrintF(
+    perf_dump_name,

[danno, 2013/11/13 17:18:10]

nit: 4 char indent

+    kFilenameFormatString,
+    OS::GetCurrentProcessId());
+  CHECK_NE(size, -1);
+  perf_output_handle_ = OS::FOpen(perf_dump_name.start(), OS::LogFileOpenMode);

[bnoordhuis, 2013/11/13 23:40:52]

This should check for NULL, shouldn't it?  Calling setvbuf() or fclose() on a
NULL stream will segfault.

+  setvbuf(perf_output_handle_, NULL, _IOFBF, kLogBufferSize);
+}
+
+
+PerfBasicLogger::~PerfBasicLogger() {
+  fclose(perf_output_handle_);
+  perf_output_handle_ = NULL;
+}
+
+
+void PerfBasicLogger::LogRecordedBuffer(Code* code,
+                                       SharedFunctionInfo*,
+                                       const char* name,
+                                       int length) {
+  ASSERT(code->instruction_start() == code->address() + Code::kHeaderSize);
+
+  OS::FPrint(perf_output_handle_, "%llx %x %.*s\n",
+    (uint64_t)code->instruction_start(),

[danno, 2013/11/13 17:18:10]

nit: 4 char indent (2 is for nested scopes only)

[bnoordhuis, 2013/11/13 23:40:52]

static_cast?  (Here and in a few other places.)

+    code->instruction_size(),
+    length, name);
+}
+
+
+// Linux perf tool logging support
+class PerfJitLogger : public CodeEventLogger {
+ public:
+  explicit PerfJitLogger();

[danno, 2013/11/13 17:18:10]

Don't need explicit here, only for single argument constructor.

+  virtual ~PerfJitLogger();
+
+  virtual void CodeMoveEvent(Address from, Address to) { }
+  virtual void CodeDeleteEvent(Address from) { }
+
+ private:
+  virtual void LogRecordedBuffer(Code* code,
+                                 SharedFunctionInfo* shared,
+                                 const char* name,
+                                 int length);
+
+  // Extension added to V8 log file name to get the low-level log name.
+  static const char kFilenameFormatString[];
+  static const int kFilenameBufferPadding;
+
+  // File buffer size of the low-level log. We don't use the default to
+  // minimize the associated overhead.
+  static const int kLogBufferSize = 2 * MB;
+
+  void LogWriteBytes(const char* bytes, int size);
+  void LogWriteHeader();
+
+  static const uint32_t kJitHeaderMagic = 0x4F74496A;
+  static const uint32_t kJitHeaderVersion = 0x2;
+  static const uint32_t kElfMachIA32 = 3;
+  static const uint32_t kElfMachX64 = 62;
+  static const uint32_t kElfMachARM = 40;
+  static const uint32_t kElfMachMIPS = 10;
+
+  struct jitheader {
+    uint32_t magic;
+    uint32_t version;
+    uint32_t total_size;
+    uint32_t elf_mach;
+    uint32_t pad1;
+    uint32_t pid;
+    uint64_t timestamp;
+  };
+
+  enum jit_record_type {
+    JIT_CODE_LOAD = 0
+    // JIT_CODE_UNLOAD = 1,
+    // JIT_CODE_CLOSE = 2,
+    // JIT_CODE_DEBUG_INFO = 3,
+    // JIT_CODE_PAGE_MAP = 4,
+    // JIT_CODE_MAX = 5
+  };
+
+  struct jr_code_load {
+    uint32_t id;
+    uint32_t total_size;
+    uint64_t timestamp;
+    uint64_t vma;
+    uint64_t code_addr;
+    uint32_t code_size;
+    uint32_t align;
+  };
+
+  uint32_t GetElfMach() {
+#if V8_TARGET_ARCH_IA32
+    return kElfMachIA32;
+#elif V8_TARGET_ARCH_X64
+    return kElfMachX64;
+#elif V8_TARGET_ARCH_ARM
+    return kElfMachARM;
+#elif V8_TARGET_ARCH_MIPS
+    return kElfMachMIPS;
+#else
+    UNIMPLEMENTED();
+    return 0;
+#endif
+  }
+
+  FILE* perf_output_handle_;
+};
+
+const char PerfJitLogger::kFilenameFormatString[] = "/tmp/jit-%d.dump";
+
+// Extra padding for the PID in the filename
+const int PerfJitLogger::kFilenameBufferPadding = 16;
+
+PerfJitLogger::PerfJitLogger()
+    : perf_output_handle_(NULL) {
+  // Open the perf JIT dump file.
+  int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
+  ScopedVector<char> perf_dump_name(bufferSize);
+  int size = OS::SNPrintF(
+    perf_dump_name,

[danno, 2013/11/13 17:18:10]

Indent 4 characters on line continuations

+    kFilenameFormatString,
+    OS::GetCurrentProcessId());
+  CHECK_NE(size, -1);
+  perf_output_handle_ = OS::FOpen(perf_dump_name.start(), OS::LogFileOpenMode);
+  setvbuf(perf_output_handle_, NULL, _IOFBF, kLogBufferSize);
+
+  LogWriteHeader();
+}
+
+
+PerfJitLogger::~PerfJitLogger() {
+  fclose(perf_output_handle_);
+  perf_output_handle_ = NULL;
+}
+
+
+void PerfJitLogger::LogRecordedBuffer(Code* code,
+                                       SharedFunctionInfo*,

[danno, 2013/11/13 17:18:10]

nit: indentation one char too many on this line and below.

+                                       const char* name,
+                                       int length) {
+  ASSERT(code->instruction_start() == code->address() + Code::kHeaderSize);
+  ASSERT(perf_output_handle_ != NULL);
+
+  const char* code_name = name;
+  uint8_t* code_pointer = reinterpret_cast<uint8_t*>(code->instruction_start());
+  uint32_t code_size = code->instruction_size();
+
+  static const char string_terminator[] = "\0";
+
+  jr_code_load code_load;
+  code_load.id = JIT_CODE_LOAD;
+  code_load.total_size = sizeof(code_load) + length + 1 + code_size;
+  code_load.timestamp =  (uint64_t)(OS::TimeCurrentMillis() * 1000.0);
+  code_load.vma = 0x0;  //  Our addresses are absolute.
+  code_load.code_addr = reinterpret_cast<uint64_t>(code->instruction_start());
+  code_load.code_size = code_size;
+  code_load.align = 0;
+
+  LogWriteBytes(reinterpret_cast<const char*>(&code_load), sizeof(code_load));
+  LogWriteBytes(code_name, length);
+  LogWriteBytes(string_terminator, 1);
+  LogWriteBytes(reinterpret_cast<const char*>(code_pointer), code_size);
+}
+
+
+void PerfJitLogger::LogWriteBytes(const char* bytes, int size) {
+  size_t rv = fwrite(bytes, 1, size, perf_output_handle_);
+  ASSERT(static_cast<size_t>(size) == rv);

[bnoordhuis, 2013/11/13 23:40:52]

I don't think that's a safe assumption to make.  fwrite() can (and will)
sometimes write fewer bytes than requested, e.g. when the write() system call
got interrupted by a signal.

Minor nit: you probably meant `ssize_t` one line up.

+  USE(rv);
+}
+
+
+void PerfJitLogger::LogWriteHeader() {
+  ASSERT(perf_output_handle_ != NULL);
+  jitheader header;
+  header.magic = kJitHeaderMagic;
+  header.version = kJitHeaderVersion;
+  header.total_size = sizeof(jitheader);
+  header.pad1 = 0xdeadbeef;
+  header.elf_mach = GetElfMach();
+  header.pid = OS::GetCurrentProcessId();
+  header.timestamp = (uint64_t)(OS::TimeCurrentMillis() * 1000.0);
+  LogWriteBytes(reinterpret_cast<const char*>(&header), sizeof(header));
+}
+
+
 // Low-level logging support.
 #define LL_LOG(Call) if (ll_logger_) ll_logger_->Call;
 
@@ -711,6 +933,8 @@ Logger::Logger(Isolate* isolate)
     log_events_(NULL),
     is_logging_(false),
     log_(new Log(this)),
+    perf_basic_logger_(NULL),
+    perf_jit_logger_(NULL),
     ll_logger_(NULL),
     jit_logger_(NULL),
     listeners_(5),
@@ -1844,6 +2068,17 @@ bool Logger::SetUp(Isolate* isolate) {
       PrepareLogFileName(isolate, FLAG_logfile);
   log_->Initialize(*log_file_name);
 
+
+  if (FLAG_perf_basic_prof) {
+    perf_basic_logger_ = new PerfBasicLogger();
+    addCodeEventListener(perf_basic_logger_);
+  }
+
+  if (FLAG_perf_jit_prof) {
+    perf_jit_logger_ = new PerfJitLogger();
+    addCodeEventListener(perf_jit_logger_);
+  }
+
   if (FLAG_ll_prof) {
     ll_logger_ = new LowLevelLogger(*log_file_name);
     addCodeEventListener(ll_logger_);
@@ -1906,6 +2141,18 @@ FILE* Logger::TearDown() {
   delete ticker_;
   ticker_ = NULL;
 
+  if (perf_basic_logger_) {
+    removeCodeEventListener(perf_basic_logger_);
+    delete perf_basic_logger_;
+    perf_basic_logger_ = NULL;
+  }
+
+  if (perf_jit_logger_) {
+    removeCodeEventListener(perf_jit_logger_);
+    delete perf_jit_logger_;
+    perf_jit_logger_ = NULL;
+  }
+
   if (ll_logger_) {
     removeCodeEventListener(ll_logger_);
     delete ll_logger_;