// Copyright 2011 the V8 project authors. All rights reserved. // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. #include "src/logging/log.h" #include #include #include #include "src/api/api-inl.h" #include "src/base/platform/platform.h" #include "src/codegen/bailout-reason.h" #include "src/codegen/macro-assembler.h" #include "src/codegen/source-position-table.h" #include "src/deoptimizer/deoptimizer.h" #include "src/diagnostics/perf-jit.h" #include "src/execution/isolate.h" #include "src/execution/runtime-profiler.h" #include "src/execution/vm-state-inl.h" #include "src/handles/global-handles.h" #include "src/init/bootstrapper.h" #include "src/interpreter/bytecodes.h" #include "src/interpreter/interpreter.h" #include "src/libsampler/sampler.h" #include "src/logging/counters.h" #include "src/logging/log-inl.h" #include "src/logging/log-utils.h" #include "src/objects/api-callbacks.h" #include "src/profiler/tick-sample.h" #include "src/snapshot/embedded/embedded-data.h" #include "src/strings/string-stream.h" #include "src/strings/unicode-inl.h" #include "src/tracing/tracing-category-observer.h" #include "src/utils/memcopy.h" #include "src/wasm/wasm-code-manager.h" #include "src/wasm/wasm-objects-inl.h" #include "src/utils/version.h" namespace v8 { namespace internal { #define DECLARE_EVENT(ignore1, name) #name, static const char* kLogEventsNames[CodeEventListener::NUMBER_OF_LOG_EVENTS] = { LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)}; #undef DECLARE_EVENT static v8::CodeEventType GetCodeEventTypeForTag( CodeEventListener::LogEventsAndTags tag) { switch (tag) { case CodeEventListener::NUMBER_OF_LOG_EVENTS: #define V(Event, _) case CodeEventListener::Event: LOG_EVENTS_LIST(V) #undef V return v8::CodeEventType::kUnknownType; #define V(From, To) \ case CodeEventListener::From: \ return v8::CodeEventType::k##To##Type; TAGS_LIST(V) #undef V } // The execution should never pass here UNREACHABLE(); // NOTE(mmarchini): Workaround to fix a compiler failure on GCC 4.9 return v8::CodeEventType::kUnknownType; } #define CALL_CODE_EVENT_HANDLER(Call) \ if (listener_) { \ listener_->Call; \ } else { \ PROFILE(isolate_, Call); \ } static const char* ComputeMarker(SharedFunctionInfo shared, AbstractCode code) { switch (code.kind()) { case AbstractCode::INTERPRETED_FUNCTION: return shared.optimization_disabled() ? "" : "~"; case AbstractCode::OPTIMIZED_FUNCTION: return "*"; default: return ""; } } static const char* ComputeMarker(const wasm::WasmCode* code) { switch (code->kind()) { case wasm::WasmCode::kFunction: return code->is_liftoff() ? "" : "*"; case wasm::WasmCode::kInterpreterEntry: return "~"; default: return ""; } } class CodeEventLogger::NameBuffer { public: NameBuffer() { Reset(); } void Reset() { utf8_pos_ = 0; } void Init(CodeEventListener::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.is_null()) return; int length = 0; std::unique_ptr c_str = str.ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL, &length); AppendBytes(c_str.get(), length); } void AppendBytes(const char* bytes, int size) { size = Min(size, kUtf8BufferSize - utf8_pos_); MemCopy(utf8_buffer_ + utf8_pos_, bytes, size); utf8_pos_ += size; } void AppendBytes(const char* bytes) { size_t len = strlen(bytes); DCHECK_GE(kMaxInt, len); AppendBytes(bytes, static_cast(len)); } void AppendByte(char c) { if (utf8_pos_ >= kUtf8BufferSize) return; utf8_buffer_[utf8_pos_++] = c; } void AppendInt(int n) { int space = kUtf8BufferSize - utf8_pos_; if (space <= 0) return; Vector buffer(utf8_buffer_ + utf8_pos_, space); int size = SNPrintF(buffer, "%d", n); if (size > 0 && utf8_pos_ + size <= kUtf8BufferSize) { utf8_pos_ += size; } } void AppendHex(uint32_t n) { int space = kUtf8BufferSize - utf8_pos_; if (space <= 0) return; Vector buffer(utf8_buffer_ + utf8_pos_, space); int size = 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 = kUtf8BufferSize; int utf8_pos_; char utf8_buffer_[kUtf8BufferSize]; }; CodeEventLogger::CodeEventLogger(Isolate* isolate) : isolate_(isolate), name_buffer_(new NameBuffer) {} CodeEventLogger::~CodeEventLogger() { delete name_buffer_; } void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, AbstractCode code, const char* comment) { name_buffer_->Init(tag); name_buffer_->AppendBytes(comment); LogRecordedBuffer(code, SharedFunctionInfo(), name_buffer_->get(), name_buffer_->size()); } void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, AbstractCode code, Name name) { name_buffer_->Init(tag); name_buffer_->AppendName(name); LogRecordedBuffer(code, SharedFunctionInfo(), name_buffer_->get(), name_buffer_->size()); } void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, AbstractCode code, SharedFunctionInfo shared, Name name) { name_buffer_->Init(tag); name_buffer_->AppendBytes(ComputeMarker(shared, code)); name_buffer_->AppendByte(' '); name_buffer_->AppendName(name); LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size()); } void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, AbstractCode code, SharedFunctionInfo shared, Name source, int line, int column) { name_buffer_->Init(tag); name_buffer_->AppendBytes(ComputeMarker(shared, 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(LogEventsAndTags tag, const wasm::WasmCode* code, wasm::WasmName name) { name_buffer_->Init(tag); if (name.empty()) { name_buffer_->AppendBytes(""); } else { name_buffer_->AppendBytes(name.begin(), name.length()); } name_buffer_->AppendByte('-'); if (code->IsAnonymous()) { name_buffer_->AppendBytes(""); } else { name_buffer_->AppendInt(code->index()); } LogRecordedBuffer(code, name_buffer_->get(), name_buffer_->size()); } void CodeEventLogger::RegExpCodeCreateEvent(AbstractCode code, String source) { name_buffer_->Init(CodeEventListener::REG_EXP_TAG); name_buffer_->AppendString(source); LogRecordedBuffer(code, SharedFunctionInfo(), name_buffer_->get(), name_buffer_->size()); } // Linux perf tool logging support class PerfBasicLogger : public CodeEventLogger { public: explicit PerfBasicLogger(Isolate* isolate); ~PerfBasicLogger() override; void CodeMoveEvent(AbstractCode from, AbstractCode to) override {} void CodeDisableOptEvent(AbstractCode code, SharedFunctionInfo shared) override {} private: void LogRecordedBuffer(AbstractCode code, SharedFunctionInfo shared, const char* name, int length) override; void LogRecordedBuffer(const wasm::WasmCode* code, const char* name, int length) override; void WriteLogRecordedBuffer(uintptr_t address, int size, const char* name, int name_length); // Extension added to V8 log file name to get the low-level log name. static const char kFilenameFormatString[]; static const int kFilenameBufferPadding; 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(Isolate* isolate) : CodeEventLogger(isolate), perf_output_handle_(nullptr) { // Open the perf JIT dump file. int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding; ScopedVector perf_dump_name(bufferSize); int size = SNPrintF(perf_dump_name, kFilenameFormatString, base::OS::GetCurrentProcessId()); CHECK_NE(size, -1); perf_output_handle_ = base::OS::FOpen(perf_dump_name.begin(), base::OS::LogFileOpenMode); CHECK_NOT_NULL(perf_output_handle_); setvbuf(perf_output_handle_, nullptr, _IOLBF, 0); } PerfBasicLogger::~PerfBasicLogger() { fclose(perf_output_handle_); perf_output_handle_ = nullptr; } void PerfBasicLogger::WriteLogRecordedBuffer(uintptr_t address, int size, const char* name, int name_length) { // Linux perf expects hex literals without a leading 0x, while some // implementations of printf might prepend one when using the %p format // for pointers, leading to wrongly formatted JIT symbols maps. // // Instead, we use V8PRIxPTR format string and cast pointer to uintpr_t, // so that we have control over the exact output format. base::OS::FPrint(perf_output_handle_, "%" V8PRIxPTR " %x %.*s\n", address, size, name_length, name); } void PerfBasicLogger::LogRecordedBuffer(AbstractCode code, SharedFunctionInfo, const char* name, int length) { if (FLAG_perf_basic_prof_only_functions && (code.kind() != AbstractCode::INTERPRETED_FUNCTION && code.kind() != AbstractCode::BUILTIN && code.kind() != AbstractCode::OPTIMIZED_FUNCTION)) { return; } WriteLogRecordedBuffer(static_cast(code.InstructionStart()), code.InstructionSize(), name, length); } void PerfBasicLogger::LogRecordedBuffer(const wasm::WasmCode* code, const char* name, int length) { WriteLogRecordedBuffer(static_cast(code->instruction_start()), code->instructions().length(), name, length); } // External CodeEventListener ExternalCodeEventListener::ExternalCodeEventListener(Isolate* isolate) : is_listening_(false), isolate_(isolate), code_event_handler_(nullptr) {} ExternalCodeEventListener::~ExternalCodeEventListener() { if (is_listening_) { StopListening(); } } void ExternalCodeEventListener::LogExistingCode() { HandleScope scope(isolate_); ExistingCodeLogger logger(isolate_, this); logger.LogCodeObjects(); logger.LogCompiledFunctions(); } void ExternalCodeEventListener::StartListening( CodeEventHandler* code_event_handler) { if (is_listening_ || code_event_handler == nullptr) { return; } code_event_handler_ = code_event_handler; is_listening_ = isolate_->code_event_dispatcher()->AddListener(this); if (is_listening_) { LogExistingCode(); } } void ExternalCodeEventListener::StopListening() { if (!is_listening_) { return; } isolate_->code_event_dispatcher()->RemoveListener(this); is_listening_ = false; } void ExternalCodeEventListener::CodeCreateEvent( CodeEventListener::LogEventsAndTags tag, AbstractCode code, const char* comment) { CodeEvent code_event; code_event.code_start_address = static_cast(code.InstructionStart()); code_event.code_size = static_cast(code.InstructionSize()); code_event.function_name = isolate_->factory()->empty_string(); code_event.script_name = isolate_->factory()->empty_string(); code_event.script_line = 0; code_event.script_column = 0; code_event.code_type = GetCodeEventTypeForTag(tag); code_event.comment = comment; code_event_handler_->Handle(reinterpret_cast(&code_event)); } void ExternalCodeEventListener::CodeCreateEvent( CodeEventListener::LogEventsAndTags tag, AbstractCode code, Name name) { Handle name_string = Name::ToFunctionName(isolate_, Handle(name, isolate_)) .ToHandleChecked(); CodeEvent code_event; code_event.code_start_address = static_cast(code.InstructionStart()); code_event.code_size = static_cast(code.InstructionSize()); code_event.function_name = name_string; code_event.script_name = isolate_->factory()->empty_string(); code_event.script_line = 0; code_event.script_column = 0; code_event.code_type = GetCodeEventTypeForTag(tag); code_event.comment = ""; code_event_handler_->Handle(reinterpret_cast(&code_event)); } void ExternalCodeEventListener::CodeCreateEvent( CodeEventListener::LogEventsAndTags tag, AbstractCode code, SharedFunctionInfo shared, Name name) { Handle name_string = Name::ToFunctionName(isolate_, Handle(name, isolate_)) .ToHandleChecked(); CodeEvent code_event; code_event.code_start_address = static_cast(code.InstructionStart()); code_event.code_size = static_cast(code.InstructionSize()); code_event.function_name = name_string; code_event.script_name = isolate_->factory()->empty_string(); code_event.script_line = 0; code_event.script_column = 0; code_event.code_type = GetCodeEventTypeForTag(tag); code_event.comment = ""; code_event_handler_->Handle(reinterpret_cast(&code_event)); } void ExternalCodeEventListener::CodeCreateEvent( CodeEventListener::LogEventsAndTags tag, AbstractCode code, SharedFunctionInfo shared, Name source, int line, int column) { Handle name_string = Name::ToFunctionName(isolate_, Handle(shared.Name(), isolate_)) .ToHandleChecked(); Handle source_string = Name::ToFunctionName(isolate_, Handle(source, isolate_)) .ToHandleChecked(); CodeEvent code_event; code_event.code_start_address = static_cast(code.InstructionStart()); code_event.code_size = static_cast(code.InstructionSize()); code_event.function_name = name_string; code_event.script_name = source_string; code_event.script_line = line; code_event.script_column = column; code_event.code_type = GetCodeEventTypeForTag(tag); code_event.comment = ""; code_event_handler_->Handle(reinterpret_cast(&code_event)); } void ExternalCodeEventListener::CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code, wasm::WasmName name) { // TODO(mmarchini): handle later } void ExternalCodeEventListener::RegExpCodeCreateEvent(AbstractCode code, String source) { CodeEvent code_event; code_event.code_start_address = static_cast(code.InstructionStart()); code_event.code_size = static_cast(code.InstructionSize()); code_event.function_name = Handle(source, isolate_); code_event.script_name = isolate_->factory()->empty_string(); code_event.script_line = 0; code_event.script_column = 0; code_event.code_type = GetCodeEventTypeForTag(CodeEventListener::REG_EXP_TAG); code_event.comment = ""; code_event_handler_->Handle(reinterpret_cast(&code_event)); } // Low-level logging support. class LowLevelLogger : public CodeEventLogger { public: LowLevelLogger(Isolate* isolate, const char* file_name); ~LowLevelLogger() override; void CodeMoveEvent(AbstractCode from, AbstractCode to) override; void CodeDisableOptEvent(AbstractCode code, SharedFunctionInfo shared) override {} void SnapshotPositionEvent(HeapObject obj, int pos); void CodeMovingGCEvent() override; private: void LogRecordedBuffer(AbstractCode code, SharedFunctionInfo shared, const char* name, int length) override; void LogRecordedBuffer(const wasm::WasmCode* code, const char* name, int length) override; // 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; }; static const char kCodeMovingGCTag = 'G'; // Extension added to V8 log file name to get the low-level log name. static const char kLogExt[]; 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(Isolate* isolate, const char* name) : CodeEventLogger(isolate), ll_output_handle_(nullptr) { // Open the low-level log file. size_t len = strlen(name); ScopedVector ll_name(static_cast(len + sizeof(kLogExt))); MemCopy(ll_name.begin(), name, len); MemCopy(ll_name.begin() + len, kLogExt, sizeof(kLogExt)); ll_output_handle_ = base::OS::FOpen(ll_name.begin(), base::OS::LogFileOpenMode); setvbuf(ll_output_handle_, nullptr, _IOLBF, 0); LogCodeInfo(); } LowLevelLogger::~LowLevelLogger() { fclose(ll_output_handle_); ll_output_handle_ = nullptr; } void LowLevelLogger::LogCodeInfo() { #if V8_TARGET_ARCH_IA32 const char arch[] = "ia32"; #elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_64_BIT const char arch[] = "x64"; #elif V8_TARGET_ARCH_ARM const char arch[] = "arm"; #elif V8_TARGET_ARCH_PPC const char arch[] = "ppc"; #elif V8_TARGET_ARCH_MIPS const char arch[] = "mips"; #elif V8_TARGET_ARCH_ARM64 const char arch[] = "arm64"; #elif V8_TARGET_ARCH_S390 const char arch[] = "s390"; #else const char arch[] = "unknown"; #endif LogWriteBytes(arch, sizeof(arch)); } void LowLevelLogger::LogRecordedBuffer(AbstractCode code, SharedFunctionInfo, const char* name, int length) { CodeCreateStruct event; event.name_size = length; event.code_address = code.InstructionStart(); event.code_size = code.InstructionSize(); LogWriteStruct(event); LogWriteBytes(name, length); LogWriteBytes(reinterpret_cast(code.InstructionStart()), code.InstructionSize()); } void LowLevelLogger::LogRecordedBuffer(const wasm::WasmCode* code, const char* name, int length) { CodeCreateStruct event; event.name_size = length; event.code_address = code->instruction_start(); event.code_size = code->instructions().length(); LogWriteStruct(event); LogWriteBytes(name, length); LogWriteBytes(reinterpret_cast(code->instruction_start()), code->instructions().length()); } void LowLevelLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) { CodeMoveStruct event; event.from_address = from.InstructionStart(); event.to_address = to.InstructionStart(); LogWriteStruct(event); } void LowLevelLogger::LogWriteBytes(const char* bytes, int size) { size_t rv = fwrite(bytes, 1, size, ll_output_handle_); DCHECK(static_cast(size) == rv); USE(rv); } void LowLevelLogger::CodeMovingGCEvent() { const char tag = kCodeMovingGCTag; LogWriteBytes(&tag, sizeof(tag)); } class JitLogger : public CodeEventLogger { public: JitLogger(Isolate* isolate, JitCodeEventHandler code_event_handler); void CodeMoveEvent(AbstractCode from, AbstractCode to) override; void CodeDisableOptEvent(AbstractCode code, SharedFunctionInfo shared) override {} void AddCodeLinePosInfoEvent(void* jit_handler_data, int pc_offset, int position, JitCodeEvent::PositionType position_type); void* StartCodePosInfoEvent(); void EndCodePosInfoEvent(Address start_address, void* jit_handler_data); private: void LogRecordedBuffer(AbstractCode code, SharedFunctionInfo shared, const char* name, int length) override; void LogRecordedBuffer(const wasm::WasmCode* code, const char* name, int length) override; JitCodeEventHandler code_event_handler_; base::Mutex logger_mutex_; }; JitLogger::JitLogger(Isolate* isolate, JitCodeEventHandler code_event_handler) : CodeEventLogger(isolate), code_event_handler_(code_event_handler) {} void JitLogger::LogRecordedBuffer(AbstractCode code, SharedFunctionInfo shared, const char* name, int length) { JitCodeEvent event; memset(static_cast(&event), 0, sizeof(event)); event.type = JitCodeEvent::CODE_ADDED; event.code_start = reinterpret_cast(code.InstructionStart()); event.code_type = code.IsCode() ? JitCodeEvent::JIT_CODE : JitCodeEvent::BYTE_CODE; event.code_len = code.InstructionSize(); Handle shared_function_handle; if (!shared.is_null() && shared.script().IsScript()) { shared_function_handle = Handle(shared, shared.GetIsolate()); } event.script = ToApiHandle(shared_function_handle); event.name.str = name; event.name.len = length; event.isolate = reinterpret_cast(isolate_); code_event_handler_(&event); } void JitLogger::LogRecordedBuffer(const wasm::WasmCode* code, const char* name, int length) { JitCodeEvent event; memset(static_cast(&event), 0, sizeof(event)); event.type = JitCodeEvent::CODE_ADDED; event.code_type = JitCodeEvent::JIT_CODE; event.code_start = code->instructions().begin(); event.code_len = code->instructions().length(); event.name.str = name; event.name.len = length; event.isolate = reinterpret_cast(isolate_); code_event_handler_(&event); } void JitLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) { base::MutexGuard guard(&logger_mutex_); JitCodeEvent event; event.type = JitCodeEvent::CODE_MOVED; event.code_type = from.IsCode() ? JitCodeEvent::JIT_CODE : JitCodeEvent::BYTE_CODE; event.code_start = reinterpret_cast(from.InstructionStart()); event.code_len = from.InstructionSize(); event.new_code_start = reinterpret_cast(to.InstructionStart()); event.isolate = reinterpret_cast(isolate_); code_event_handler_(&event); } void JitLogger::AddCodeLinePosInfoEvent( void* jit_handler_data, int pc_offset, int position, JitCodeEvent::PositionType position_type) { JitCodeEvent event; memset(static_cast(&event), 0, sizeof(event)); event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO; event.user_data = jit_handler_data; event.line_info.offset = pc_offset; event.line_info.pos = position; event.line_info.position_type = position_type; event.isolate = reinterpret_cast(isolate_); code_event_handler_(&event); } void* JitLogger::StartCodePosInfoEvent() { JitCodeEvent event; memset(static_cast(&event), 0, sizeof(event)); event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING; event.isolate = reinterpret_cast(isolate_); code_event_handler_(&event); return event.user_data; } void JitLogger::EndCodePosInfoEvent(Address start_address, void* jit_handler_data) { JitCodeEvent event; memset(static_cast(&event), 0, sizeof(event)); event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING; event.code_start = reinterpret_cast(start_address); event.user_data = jit_handler_data; event.isolate = reinterpret_cast(isolate_); code_event_handler_(&event); } // TODO(lpy): Keeping sampling thread inside V8 is a workaround currently, // the reason is to reduce code duplication during migration to sampler library, // sampling thread, as well as the sampler, will be moved to D8 eventually. class SamplingThread : public base::Thread { public: static const int kSamplingThreadStackSize = 64 * KB; SamplingThread(sampler::Sampler* sampler, int interval_microseconds) : base::Thread( base::Thread::Options("SamplingThread", kSamplingThreadStackSize)), sampler_(sampler), interval_microseconds_(interval_microseconds) {} void Run() override { while (sampler_->IsActive()) { sampler_->DoSample(); base::OS::Sleep( base::TimeDelta::FromMicroseconds(interval_microseconds_)); } } private: sampler::Sampler* sampler_; const int interval_microseconds_; }; // The Profiler samples pc and sp values for the main thread. // Each sample is appended to a circular buffer. // An independent thread removes data and writes it to the log. // This design minimizes the time spent in the sampler. // class Profiler : public base::Thread { public: explicit Profiler(Isolate* isolate); void Engage(); void Disengage(); // Inserts collected profiling data into buffer. void Insert(v8::TickSample* sample) { if (Succ(head_) == static_cast(base::Relaxed_Load(&tail_))) { overflow_ = true; } else { buffer_[head_] = *sample; head_ = Succ(head_); buffer_semaphore_.Signal(); // Tell we have an element. } } void Run() override; private: // Waits for a signal and removes profiling data. bool Remove(v8::TickSample* sample) { buffer_semaphore_.Wait(); // Wait for an element. *sample = buffer_[base::Relaxed_Load(&tail_)]; bool result = overflow_; base::Relaxed_Store( &tail_, static_cast(Succ(base::Relaxed_Load(&tail_)))); overflow_ = false; return result; } // Returns the next index in the cyclic buffer. int Succ(int index) { return (index + 1) % kBufferSize; } Isolate* isolate_; // Cyclic buffer for communicating profiling samples // between the signal handler and the worker thread. static const int kBufferSize = 128; v8::TickSample buffer_[kBufferSize]; // Buffer storage. int head_; // Index to the buffer head. base::Atomic32 tail_; // Index to the buffer tail. bool overflow_; // Tell whether a buffer overflow has occurred. // Semaphore used for buffer synchronization. base::Semaphore buffer_semaphore_; // Tells whether worker thread should continue running. base::Atomic32 running_; }; // // Ticker used to provide ticks to the profiler and the sliding state // window. // class Ticker : public sampler::Sampler { public: Ticker(Isolate* isolate, int interval_microseconds) : sampler::Sampler(reinterpret_cast(isolate)), sampling_thread_( base::make_unique(this, interval_microseconds)) {} ~Ticker() override { if (IsActive()) Stop(); } void SetProfiler(Profiler* profiler) { DCHECK_NULL(profiler_); profiler_ = profiler; if (!IsActive()) Start(); sampling_thread_->StartSynchronously(); } void ClearProfiler() { profiler_ = nullptr; if (IsActive()) Stop(); sampling_thread_->Join(); } void SampleStack(const v8::RegisterState& state) override { if (!profiler_) return; Isolate* isolate = reinterpret_cast(this->isolate()); TickSample sample; sample.Init(isolate, state, TickSample::kIncludeCEntryFrame, true); profiler_->Insert(&sample); } private: Profiler* profiler_ = nullptr; std::unique_ptr sampling_thread_; }; // // Profiler implementation when invoking with --prof. // Profiler::Profiler(Isolate* isolate) : base::Thread(Options("v8:Profiler")), isolate_(isolate), head_(0), overflow_(false), buffer_semaphore_(0) { base::Relaxed_Store(&tail_, 0); base::Relaxed_Store(&running_, 0); } void Profiler::Engage() { std::vector addresses = base::OS::GetSharedLibraryAddresses(); for (const auto& address : addresses) { LOG(isolate_, SharedLibraryEvent(address.library_path, address.start, address.end, address.aslr_slide)); } // Start thread processing the profiler buffer. base::Relaxed_Store(&running_, 1); Start(); // Register to get ticks. Logger* logger = isolate_->logger(); logger->ticker_->SetProfiler(this); logger->ProfilerBeginEvent(); } void Profiler::Disengage() { // Stop receiving ticks. isolate_->logger()->ticker_->ClearProfiler(); // Terminate the worker thread by setting running_ to false, // inserting a fake element in the queue and then wait for // the thread to terminate. base::Relaxed_Store(&running_, 0); v8::TickSample sample; Insert(&sample); Join(); LOG(isolate_, UncheckedStringEvent("profiler", "end")); } void Profiler::Run() { v8::TickSample sample; bool overflow = Remove(&sample); while (base::Relaxed_Load(&running_)) { LOG(isolate_, TickEvent(&sample, overflow)); overflow = Remove(&sample); } } // // Logger class implementation. // Logger::Logger(Isolate* isolate) : isolate_(isolate), log_events_(nullptr), is_logging_(false), log_(nullptr), is_initialized_(false), existing_code_logger_(isolate) {} Logger::~Logger() { delete log_; } const LogSeparator Logger::kNext = LogSeparator::kSeparator; void Logger::AddCodeEventListener(CodeEventListener* listener) { bool result = isolate_->code_event_dispatcher()->AddListener(listener); CHECK(result); } void Logger::RemoveCodeEventListener(CodeEventListener* listener) { isolate_->code_event_dispatcher()->RemoveListener(listener); } void Logger::ProfilerBeginEvent() { if (!log_->IsEnabled()) return; Log::MessageBuilder msg(log_); msg << "profiler" << kNext << "begin" << kNext << FLAG_prof_sampling_interval; msg.WriteToLogFile(); } void Logger::StringEvent(const char* name, const char* value) { if (FLAG_log) UncheckedStringEvent(name, value); } void Logger::UncheckedStringEvent(const char* name, const char* value) { if (!log_->IsEnabled()) return; Log::MessageBuilder msg(log_); msg << name << kNext << value; msg.WriteToLogFile(); } void Logger::IntPtrTEvent(const char* name, intptr_t value) { if (FLAG_log) UncheckedIntPtrTEvent(name, value); } void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) { if (!log_->IsEnabled()) return; Log::MessageBuilder msg(log_); msg << name << kNext; msg.AppendFormatString("%" V8PRIdPTR, value); msg.WriteToLogFile(); } void Logger::HandleEvent(const char* name, Address* location) { if (!log_->IsEnabled() || !FLAG_log_handles) return; Log::MessageBuilder msg(log_); msg << name << kNext << reinterpret_cast(location); msg.WriteToLogFile(); } void Logger::ApiSecurityCheck() { if (!log_->IsEnabled() || !FLAG_log_api) return; Log::MessageBuilder msg(log_); msg << "api" << kNext << "check-security"; msg.WriteToLogFile(); } void Logger::SharedLibraryEvent(const std::string& library_path, uintptr_t start, uintptr_t end, intptr_t aslr_slide) { if (!log_->IsEnabled() || !FLAG_prof_cpp) return; Log::MessageBuilder msg(log_); msg << "shared-library" << kNext << library_path.c_str() << kNext << reinterpret_cast(start) << kNext << reinterpret_cast(end) << kNext << aslr_slide; msg.WriteToLogFile(); } void Logger::CodeDeoptEvent(Code code, DeoptimizeKind kind, Address pc, int fp_to_sp_delta) { if (!log_->IsEnabled()) return; Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(code, pc); Log::MessageBuilder msg(log_); msg << "code-deopt" << kNext << timer_.Elapsed().InMicroseconds() << kNext << code.CodeSize() << kNext << reinterpret_cast(code.InstructionStart()); // Deoptimization position. std::ostringstream deopt_location; int inlining_id = -1; int script_offset = -1; if (info.position.IsKnown()) { info.position.Print(deopt_location, code); inlining_id = info.position.InliningId(); script_offset = info.position.ScriptOffset(); } else { deopt_location << ""; } msg << kNext << inlining_id << kNext << script_offset << kNext; msg << Deoptimizer::MessageFor(kind) << kNext; msg << deopt_location.str().c_str() << kNext << DeoptimizeReasonToString(info.deopt_reason); msg.WriteToLogFile(); } void Logger::CurrentTimeEvent() { if (!log_->IsEnabled()) return; DCHECK(FLAG_log_internal_timer_events); Log::MessageBuilder msg(log_); msg << "current-time" << kNext << timer_.Elapsed().InMicroseconds(); msg.WriteToLogFile(); } void Logger::TimerEvent(Logger::StartEnd se, const char* name) { if (!log_->IsEnabled()) return; Log::MessageBuilder msg(log_); switch (se) { case START: msg << "timer-event-start"; break; case END: msg << "timer-event-end"; break; case STAMP: msg << "timer-event"; } msg << kNext << name << kNext << timer_.Elapsed().InMicroseconds(); msg.WriteToLogFile(); } bool Logger::is_logging() { // Disable logging while the CPU profiler is running. if (isolate_->is_profiling()) return false; return is_logging_; } // Instantiate template methods. #define V(TimerName, expose) \ template void TimerEventScope::LogTimerEvent( \ Logger::StartEnd se); TIMER_EVENTS_LIST(V) #undef V void Logger::ApiNamedPropertyAccess(const char* tag, JSObject holder, Object property_name) { DCHECK(property_name.IsName()); if (!log_->IsEnabled() || !FLAG_log_api) return; Log::MessageBuilder msg(log_); msg << "api" << kNext << tag << kNext << holder.class_name() << kNext << Name::cast(property_name); msg.WriteToLogFile(); } void Logger::ApiIndexedPropertyAccess(const char* tag, JSObject holder, uint32_t index) { if (!log_->IsEnabled() || !FLAG_log_api) return; Log::MessageBuilder msg(log_); msg << "api" << kNext << tag << kNext << holder.class_name() << kNext << index; msg.WriteToLogFile(); } void Logger::ApiObjectAccess(const char* tag, JSObject object) { if (!log_->IsEnabled() || !FLAG_log_api) return; Log::MessageBuilder msg(log_); msg << "api" << kNext << tag << kNext << object.class_name(); msg.WriteToLogFile(); } void Logger::ApiEntryCall(const char* name) { if (!log_->IsEnabled() || !FLAG_log_api) return; Log::MessageBuilder msg(log_); msg << "api" << kNext << name; msg.WriteToLogFile(); } void Logger::NewEvent(const char* name, void* object, size_t size) { if (!log_->IsEnabled() || !FLAG_log) return; Log::MessageBuilder msg(log_); msg << "new" << kNext << name << kNext << object << kNext << static_cast(size); msg.WriteToLogFile(); } void Logger::DeleteEvent(const char* name, void* object) { if (!log_->IsEnabled() || !FLAG_log) return; Log::MessageBuilder msg(log_); msg << "delete" << kNext << name << kNext << object; msg.WriteToLogFile(); } void Logger::CallbackEventInternal(const char* prefix, Name name, Address entry_point) { if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT] << kNext << kLogEventsNames[CodeEventListener::CALLBACK_TAG] << kNext << -2 << kNext << timer_.Elapsed().InMicroseconds() << kNext << reinterpret_cast(entry_point) << kNext << 1 << kNext << prefix << name; msg.WriteToLogFile(); } void Logger::CallbackEvent(Name name, Address entry_point) { CallbackEventInternal("", name, entry_point); } void Logger::GetterCallbackEvent(Name name, Address entry_point) { CallbackEventInternal("get ", name, entry_point); } void Logger::SetterCallbackEvent(Name name, Address entry_point) { CallbackEventInternal("set ", name, entry_point); } namespace { void AppendCodeCreateHeader( Log::MessageBuilder& msg, // NOLINT(runtime/references) CodeEventListener::LogEventsAndTags tag, AbstractCode::Kind kind, uint8_t* address, int size, base::ElapsedTimer* timer) { msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT] << Logger::kNext << kLogEventsNames[tag] << Logger::kNext << kind << Logger::kNext << timer->Elapsed().InMicroseconds() << Logger::kNext << reinterpret_cast(address) << Logger::kNext << size << Logger::kNext; } void AppendCodeCreateHeader( Log::MessageBuilder& msg, // NOLINT(runtime/references) CodeEventListener::LogEventsAndTags tag, AbstractCode code, base::ElapsedTimer* timer) { AppendCodeCreateHeader(msg, tag, code.kind(), reinterpret_cast(code.InstructionStart()), code.InstructionSize(), timer); } } // namespace void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, AbstractCode code, const char* comment) { if (!is_listening_to_code_events()) return; if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); AppendCodeCreateHeader(msg, tag, code, &timer_); msg << comment; msg.WriteToLogFile(); } void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, AbstractCode code, Name name) { if (!is_listening_to_code_events()) return; if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); AppendCodeCreateHeader(msg, tag, code, &timer_); msg << name; msg.WriteToLogFile(); } void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, AbstractCode code, SharedFunctionInfo shared, Name name) { if (!is_listening_to_code_events()) return; if (!FLAG_log_code || !log_->IsEnabled()) return; if (code == AbstractCode::cast( isolate_->builtins()->builtin(Builtins::kCompileLazy))) { return; } Log::MessageBuilder msg(log_); AppendCodeCreateHeader(msg, tag, code, &timer_); msg << name << kNext << reinterpret_cast(shared.address()) << kNext << ComputeMarker(shared, code); msg.WriteToLogFile(); } void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, const wasm::WasmCode* code, wasm::WasmName name) { if (!is_listening_to_code_events()) return; if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); AppendCodeCreateHeader(msg, tag, AbstractCode::Kind::WASM_FUNCTION, code->instructions().begin(), code->instructions().length(), &timer_); if (name.empty()) { msg << ""; } else { msg.AppendString(name); } // We have to add two extra fields that allow the tick processor to group // events for the same wasm function, even if it gets compiled again. For // normal JS functions, we use the shared function info. For wasm, the pointer // to the native module + function index works well enough. // TODO(herhut) Clean up the tick processor code instead. void* tag_ptr = reinterpret_cast(code->native_module()) + code->index(); msg << kNext << tag_ptr << kNext << ComputeMarker(code); msg.WriteToLogFile(); } // 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(CodeEventListener::LogEventsAndTags tag, AbstractCode code, SharedFunctionInfo shared, Name source, int line, int column) { if (!is_listening_to_code_events()) return; if (!FLAG_log_code || !log_->IsEnabled()) return; { Log::MessageBuilder msg(log_); AppendCodeCreateHeader(msg, tag, code, &timer_); msg << shared.DebugName() << " " << source << ":" << line << ":" << column << kNext << reinterpret_cast(shared.address()) << kNext << ComputeMarker(shared, code); msg.WriteToLogFile(); } if (!FLAG_log_source_code) return; Object script_object = shared.script(); if (!script_object.IsScript()) return; Script script = Script::cast(script_object); if (!EnsureLogScriptSource(script)) return; // We log source code information in the form: // // code-source-info ,