From 4e439deb0b6fb83449ab1a16c9761926ac0f65dc Mon Sep 17 00:00:00 2001 From: "jarin@chromium.org" Date: Mon, 25 Nov 2013 06:44:23 +0000 Subject: [PATCH] Support for the Linux 'perf report' and 'perf annotate' tools. In this change, the support comes in two flavours: --perf_jit_prof - outputs the files in a new perf format that only works with a patched perf tool (patch obtained from Stephane Eranian). Both 'perf report' and 'perf annotate' are supported (the file format also contains the machine code). --perf_basic_prof - outputs the files in a format that the existing perf tool can consume. Only 'perf report' is supported. In both cases, we have to disable code compaction because the perf tool does not understand code relocation. (We are told that code relocation should be supported soon.) Usage: perf record -g d8 --perf_jit_prof --no_compact_code_space my.js perf report The change itself is straightforward - we simply listen to code events and write an entry to a log file for every new piece of code. I am not yet sure whether we should keep both versions or just one (and which one). My hope is the reviewers can help here. R=danno@chromium.org BUG= Review URL: https://codereview.chromium.org/70013002 git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@18034 ce2b1a6d-e550-0410-aec6-3dcde31c8c00 --- src/flag-definitions.h | 4 + src/isolate.cc | 12 +- src/log-utils.h | 3 +- src/log.cc | 250 +++++++++++++++++++++++++++++++++++++++++ src/log.h | 4 + 5 files changed, 271 insertions(+), 2 deletions(-) diff --git a/src/flag-definitions.h b/src/flag-definitions.h index 1c958856cf..61e545f909 100644 --- a/src/flag-definitions.h +++ b/src/flag-definitions.h @@ -785,6 +785,10 @@ DEFINE_bool(log_regexp, false, "Log regular expression execution.") DEFINE_string(logfile, "v8.log", "Specify the name of the log file.") DEFINE_bool(logfile_per_isolate, true, "Separate log files for each isolate.") DEFINE_bool(ll_prof, false, "Enable low-level linux profiler.") +DEFINE_bool(perf_basic_prof, false, + "Enable perf linux profiler (basic support).") +DEFINE_bool(perf_jit_prof, false, + "Enable perf linux profiler (experimental annotate support).") DEFINE_string(gc_fake_mmap, "/tmp/__v8_gc__", "Specify the name of the file for fake gc mmap used in ll_prof") DEFINE_bool(log_internal_timer_events, false, "Time internal events.") diff --git a/src/isolate.cc b/src/isolate.cc index 2acc59ab47..941ac42d21 100644 --- a/src/isolate.cc +++ b/src/isolate.cc @@ -2059,12 +2059,22 @@ bool Isolate::Init(Deserializer* des) { // If we are deserializing, log non-function code objects and compiled // functions found in the snapshot. if (!create_heap_objects && - (FLAG_log_code || FLAG_ll_prof || logger_->is_logging_code_events())) { + (FLAG_log_code || + FLAG_ll_prof || + FLAG_perf_jit_prof || + FLAG_perf_basic_prof || + logger_->is_logging_code_events())) { HandleScope scope(this); LOG(this, LogCodeObjects()); LOG(this, LogCompiledFunctions()); } + // If we are profiling with the Linux perf tool, we need to disable + // code relocation. + if (FLAG_perf_jit_prof || FLAG_perf_basic_prof) { + FLAG_compact_code_space = false; + } + CHECK_EQ(static_cast(OFFSET_OF(Isolate, embedder_data_)), Internals::kIsolateEmbedderDataOffset); CHECK_EQ(static_cast(OFFSET_OF(Isolate, heap_.roots_)), diff --git a/src/log-utils.h b/src/log-utils.h index ec8415e4b6..f1a21e2cc1 100644 --- a/src/log-utils.h +++ b/src/log-utils.h @@ -47,7 +47,8 @@ class Log { static bool InitLogAtStart() { return FLAG_log || FLAG_log_runtime || FLAG_log_api || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect - || FLAG_log_regexp || FLAG_ll_prof || FLAG_log_internal_timer_events; + || FLAG_log_regexp || FLAG_ll_prof || FLAG_perf_basic_prof + || FLAG_perf_jit_prof || FLAG_log_internal_timer_events; } // Frees all resources acquired in Initialize and Open... functions. diff --git a/src/log.cc b/src/log.cc index b353f548fb..e123231292 100644 --- a/src/log.cc +++ b/src/log.cc @@ -246,6 +246,231 @@ void CodeEventLogger::RegExpCodeCreateEvent(Code* code, String* source) { } +// Linux perf tool logging support +class PerfBasicLogger : public CodeEventLogger { + public: + PerfBasicLogger(); + 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 perf_dump_name(bufferSize); + int size = OS::SNPrintF( + perf_dump_name, + kFilenameFormatString, + OS::GetCurrentProcessId()); + CHECK_NE(size, -1); + perf_output_handle_ = OS::FOpen(perf_dump_name.start(), OS::LogFileOpenMode); + CHECK_NE(perf_output_handle_, NULL); + 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", + reinterpret_cast(code->instruction_start()), + code->instruction_size(), + length, name); +} + + +// Linux perf tool logging support +class PerfJitLogger : public CodeEventLogger { + public: + PerfJitLogger(); + 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 perf_dump_name(bufferSize); + int size = OS::SNPrintF( + perf_dump_name, + kFilenameFormatString, + OS::GetCurrentProcessId()); + CHECK_NE(size, -1); + perf_output_handle_ = OS::FOpen(perf_dump_name.start(), OS::LogFileOpenMode); + CHECK_NE(perf_output_handle_, NULL); + setvbuf(perf_output_handle_, NULL, _IOFBF, kLogBufferSize); + + LogWriteHeader(); +} + + +PerfJitLogger::~PerfJitLogger() { + fclose(perf_output_handle_); + perf_output_handle_ = NULL; +} + + +void PerfJitLogger::LogRecordedBuffer(Code* code, + SharedFunctionInfo*, + 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(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 = + static_cast(OS::TimeCurrentMillis() * 1000.0); + code_load.vma = 0x0; // Our addresses are absolute. + code_load.code_addr = reinterpret_cast(code->instruction_start()); + code_load.code_size = code_size; + code_load.align = 0; + + LogWriteBytes(reinterpret_cast(&code_load), sizeof(code_load)); + LogWriteBytes(code_name, length); + LogWriteBytes(string_terminator, 1); + LogWriteBytes(reinterpret_cast(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) == rv); + 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 = static_cast(OS::TimeCurrentMillis() * 1000.0); + LogWriteBytes(reinterpret_cast(&header), sizeof(header)); +} + + // Low-level logging support. #define LL_LOG(Call) if (ll_logger_) ll_logger_->Call; @@ -711,6 +936,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 +2071,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 +2144,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_; diff --git a/src/log.h b/src/log.h index c0efd6504d..e53551d8f4 100644 --- a/src/log.h +++ b/src/log.h @@ -154,7 +154,9 @@ struct TickSample; class JitLogger; +class PerfBasicLogger; class LowLevelLogger; +class PerfJitLogger; class Sampler; class Logger { @@ -437,6 +439,8 @@ class Logger { bool is_logging_; Log* log_; + PerfBasicLogger* perf_basic_logger_; + PerfJitLogger* perf_jit_logger_; LowLevelLogger* ll_logger_; JitLogger* jit_logger_; List listeners_;