// Copyright 2011 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 // with the distribution. // * Neither the name of Google Inc. nor the names of its // contributors may be used to endorse or promote products derived // from this software without specific prior written permission. // // THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS // "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT // LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR // A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT // OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, // SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT // LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, // DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY // THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT // (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE // OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. #include #include "v8.h" #include "bootstrapper.h" #include "code-stubs.h" #include "cpu-profiler.h" #include "deoptimizer.h" #include "global-handles.h" #include "log.h" #include "log-utils.h" #include "macro-assembler.h" #include "platform.h" #include "runtime-profiler.h" #include "serialize.h" #include "string-stream.h" #include "vm-state-inl.h" namespace v8 { namespace internal { #define DECLARE_EVENT(ignore1, name) name, static const char* const kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = { LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT) }; #undef DECLARE_EVENT #define CALL_LISTENERS(Call) \ for (int i = 0; i < listeners_.length(); ++i) { \ listeners_[i]->Call; \ } #define PROFILER_LOG(Call) \ do { \ CpuProfiler* cpu_profiler = isolate_->cpu_profiler(); \ if (cpu_profiler->is_profiling()) { \ cpu_profiler->Call; \ } \ } while (false); // 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 ""; } } class CodeEventLogger::NameBuffer { public: NameBuffer() { Reset(); } void Reset() { utf8_pos_ = 0; } void Init(Logger::LogEventsAndTags tag) { Reset(); AppendBytes(kLogEventsNames[tag]); AppendByte(':'); } void AppendName(Name* name) { if (name->IsString()) { AppendString(String::cast(name)); } else { Symbol* symbol = Symbol::cast(name); AppendBytes("symbol("); if (!symbol->name()->IsUndefined()) { AppendBytes("\""); AppendString(String::cast(symbol->name())); AppendBytes("\" "); } AppendBytes("hash "); AppendHex(symbol->Hash()); AppendByte(')'); } } void AppendString(String* str) { if (str == NULL) return; int uc16_length = Min(str->length(), kUtf16BufferSize); String::WriteToFlat(str, utf16_buffer, 0, uc16_length); int previous = unibrow::Utf16::kNoPreviousCharacter; for (int i = 0; i < uc16_length && utf8_pos_ < kUtf8BufferSize; ++i) { uc16 c = utf16_buffer[i]; if (c <= unibrow::Utf8::kMaxOneByteChar) { utf8_buffer_[utf8_pos_++] = static_cast(c); } else { int char_length = unibrow::Utf8::Length(c, previous); if (utf8_pos_ + char_length > kUtf8BufferSize) break; unibrow::Utf8::Encode(utf8_buffer_ + utf8_pos_, c, previous); utf8_pos_ += char_length; } previous = c; } } void AppendBytes(const char* bytes, int size) { size = Min(size, kUtf8BufferSize - utf8_pos_); OS::MemCopy(utf8_buffer_ + utf8_pos_, bytes, size); utf8_pos_ += size; } void AppendBytes(const char* bytes) { AppendBytes(bytes, StrLength(bytes)); } void AppendByte(char c) { if (utf8_pos_ >= kUtf8BufferSize) return; utf8_buffer_[utf8_pos_++] = c; } void AppendInt(int n) { Vector buffer(utf8_buffer_ + utf8_pos_, kUtf8BufferSize - utf8_pos_); int size = OS::SNPrintF(buffer, "%d", n); if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) { utf8_pos_ += size; } } void AppendHex(uint32_t n) { Vector buffer(utf8_buffer_ + utf8_pos_, kUtf8BufferSize - utf8_pos_); int size = OS::SNPrintF(buffer, "%x", n); if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) { utf8_pos_ += size; } } const char* get() { return utf8_buffer_; } int size() const { return utf8_pos_; } private: static const int kUtf8BufferSize = 512; static const int kUtf16BufferSize = 128; int utf8_pos_; char utf8_buffer_[kUtf8BufferSize]; uc16 utf16_buffer[kUtf16BufferSize]; }; CodeEventLogger::CodeEventLogger() : name_buffer_(new NameBuffer) { } CodeEventLogger::~CodeEventLogger() { delete name_buffer_; } void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, Code* code, const char* comment) { name_buffer_->Init(tag); name_buffer_->AppendBytes(comment); LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size()); } void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, Code* code, Name* name) { name_buffer_->Init(tag); name_buffer_->AppendName(name); LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size()); } void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, Code* code, SharedFunctionInfo* shared, CompilationInfo* info, Name* name) { name_buffer_->Init(tag); name_buffer_->AppendBytes(ComputeMarker(code)); name_buffer_->AppendName(name); LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size()); } void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, Code* code, SharedFunctionInfo* shared, CompilationInfo* info, Name* source, int line, int column) { name_buffer_->Init(tag); name_buffer_->AppendBytes(ComputeMarker(code)); name_buffer_->AppendString(shared->DebugName()); name_buffer_->AppendByte(' '); if (source->IsString()) { name_buffer_->AppendString(String::cast(source)); } else { name_buffer_->AppendBytes("symbol(hash "); name_buffer_->AppendHex(Name::cast(source)->Hash()); name_buffer_->AppendByte(')'); } name_buffer_->AppendByte(':'); name_buffer_->AppendInt(line); LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size()); } void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, Code* code, int args_count) { name_buffer_->Init(tag); name_buffer_->AppendInt(args_count); LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size()); } void CodeEventLogger::RegExpCodeCreateEvent(Code* code, String* source) { name_buffer_->Init(Logger::REG_EXP_TAG); name_buffer_->AppendString(source); LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size()); } // 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; class LowLevelLogger : public CodeEventLogger { public: explicit LowLevelLogger(const char* file_name); virtual ~LowLevelLogger(); virtual void CodeMoveEvent(Address from, Address to); virtual void CodeDeleteEvent(Address from); virtual void SnapshotPositionEvent(Address addr, int pos); virtual void CodeMovingGCEvent(); private: virtual void LogRecordedBuffer(Code* code, SharedFunctionInfo* shared, const char* name, int length); // Low-level profiling event structures. struct CodeCreateStruct { static const char kTag = 'C'; int32_t name_size; Address code_address; int32_t code_size; }; struct CodeMoveStruct { static const char kTag = 'M'; Address from_address; Address to_address; }; struct CodeDeleteStruct { static const char kTag = 'D'; Address address; }; struct SnapshotPositionStruct { static const char kTag = 'P'; Address address; int32_t position; }; static const char kCodeMovingGCTag = 'G'; // Extension added to V8 log file name to get the low-level log name. static const char kLogExt[]; // 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 LogCodeInfo(); void LogWriteBytes(const char* bytes, int size); template void LogWriteStruct(const T& s) { char tag = T::kTag; LogWriteBytes(reinterpret_cast(&tag), sizeof(tag)); LogWriteBytes(reinterpret_cast(&s), sizeof(s)); } FILE* ll_output_handle_; }; const char LowLevelLogger::kLogExt[] = ".ll"; LowLevelLogger::LowLevelLogger(const char* name) : ll_output_handle_(NULL) { // Open the low-level log file. size_t len = strlen(name); ScopedVector ll_name(static_cast(len + sizeof(kLogExt))); OS::MemCopy(ll_name.start(), name, len); OS::MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt)); ll_output_handle_ = OS::FOpen(ll_name.start(), OS::LogFileOpenMode); setvbuf(ll_output_handle_, NULL, _IOFBF, kLogBufferSize); LogCodeInfo(); } LowLevelLogger::~LowLevelLogger() { fclose(ll_output_handle_); ll_output_handle_ = NULL; } void LowLevelLogger::LogCodeInfo() { #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"; #elif V8_TARGET_ARCH_MIPS const char arch[] = "mips"; #else const char arch[] = "unknown"; #endif LogWriteBytes(arch, sizeof(arch)); } void LowLevelLogger::LogRecordedBuffer(Code* code, SharedFunctionInfo*, const char* name, int length) { CodeCreateStruct event; event.name_size = length; event.code_address = code->instruction_start(); ASSERT(event.code_address == code->address() + Code::kHeaderSize); event.code_size = code->instruction_size(); LogWriteStruct(event); LogWriteBytes(name, length); LogWriteBytes( reinterpret_cast(code->instruction_start()), code->instruction_size()); } void LowLevelLogger::CodeMoveEvent(Address from, Address to) { CodeMoveStruct event; event.from_address = from + Code::kHeaderSize; event.to_address = to + Code::kHeaderSize; LogWriteStruct(event); } void LowLevelLogger::CodeDeleteEvent(Address from) { CodeDeleteStruct event; event.address = from + Code::kHeaderSize; LogWriteStruct(event); } void LowLevelLogger::SnapshotPositionEvent(Address addr, int pos) { SnapshotPositionStruct event; event.address = addr + Code::kHeaderSize; event.position = pos; LogWriteStruct(event); } void LowLevelLogger::LogWriteBytes(const char* bytes, int size) { size_t rv = fwrite(bytes, 1, size, ll_output_handle_); ASSERT(static_cast(size) == rv); USE(rv); } void LowLevelLogger::CodeMovingGCEvent() { const char tag = kCodeMovingGCTag; LogWriteBytes(&tag, sizeof(tag)); } #define JIT_LOG(Call) if (jit_logger_) jit_logger_->Call; class JitLogger : public CodeEventLogger { public: explicit JitLogger(JitCodeEventHandler code_event_handler); virtual void CodeMoveEvent(Address from, Address to); virtual void CodeDeleteEvent(Address from); virtual void AddCodeLinePosInfoEvent( void* jit_handler_data, int pc_offset, int position, JitCodeEvent::PositionType position_type); void* StartCodePosInfoEvent(); void EndCodePosInfoEvent(Code* code, void* jit_handler_data); private: virtual void LogRecordedBuffer(Code* code, SharedFunctionInfo* shared, const char* name, int length); JitCodeEventHandler code_event_handler_; }; JitLogger::JitLogger(JitCodeEventHandler code_event_handler) : code_event_handler_(code_event_handler) { } void JitLogger::LogRecordedBuffer(Code* code, SharedFunctionInfo* shared, const char* name, int length) { JitCodeEvent event; memset(&event, 0, sizeof(event)); event.type = JitCodeEvent::CODE_ADDED; event.code_start = code->instruction_start(); event.code_len = code->instruction_size(); Handle