// 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 #include "include/v8-locker.h" #include "src/api/api-inl.h" #include "src/base/functional.h" #include "src/base/platform/mutex.h" #include "src/base/platform/platform.h" #include "src/base/platform/wrappers.h" #include "src/builtins/profile-data-reader.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/v8threads.h" #include "src/execution/vm-state-inl.h" #include "src/handles/global-handles.h" #include "src/heap/combined-heap.h" #include "src/heap/heap-inl.h" #include "src/init/bootstrapper.h" #include "src/interpreter/bytecodes.h" #include "src/interpreter/interpreter.h" #include "src/libsampler/sampler.h" #include "src/logging/code-events.h" #include "src/logging/counters.h" #include "src/logging/log-file.h" #include "src/logging/log-inl.h" #include "src/objects/api-callbacks.h" #include "src/objects/code-kind.h" #include "src/objects/code.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/utils/version.h" #ifdef ENABLE_GDB_JIT_INTERFACE #include "src/diagnostics/gdb-jit.h" #endif // ENABLE_GDB_JIT_INTERFACE #if V8_ENABLE_WEBASSEMBLY #include "src/wasm/wasm-code-manager.h" #include "src/wasm/wasm-engine.h" #include "src/wasm/wasm-objects-inl.h" #endif // V8_ENABLE_WEBASSEMBLY #if V8_OS_WIN #if defined(V8_ENABLE_ETW_STACK_WALKING) #include "src/diagnostics/etw-jit-win.h" #endif #endif // V8_OS_WIN namespace v8 { namespace internal { static const char* kLogEventsNames[] = { #define DECLARE_EVENT(ignore1, name) name, LOG_EVENT_LIST(DECLARE_EVENT) #undef DECLARE_EVENT }; static const char* kCodeTagNames[] = { #define DECLARE_EVENT(ignore1, name) #name, CODE_TYPE_LIST(DECLARE_EVENT) #undef DECLARE_EVENT }; std::ostream& operator<<(std::ostream& os, LogEventListener::CodeTag tag) { os << kCodeTagNames[static_cast(tag)]; return os; } std::ostream& operator<<(std::ostream& os, LogEventListener::Event event) { os << kLogEventsNames[static_cast(event)]; return os; } namespace { v8::CodeEventType GetCodeEventTypeForTag(LogEventListener::CodeTag tag) { switch (tag) { case LogEventListener::CodeTag::kLength: // Manually create this switch, since v8::CodeEventType is API expose and // cannot be easily modified. case LogEventListener::CodeTag::kBuiltin: return v8::CodeEventType::kBuiltinType; case LogEventListener::CodeTag::kCallback: return v8::CodeEventType::kCallbackType; case LogEventListener::CodeTag::kEval: return v8::CodeEventType::kEvalType; case LogEventListener::CodeTag::kNativeFunction: case LogEventListener::CodeTag::kFunction: return v8::CodeEventType::kFunctionType; case LogEventListener::CodeTag::kHandler: return v8::CodeEventType::kHandlerType; case LogEventListener::CodeTag::kBytecodeHandler: return v8::CodeEventType::kBytecodeHandlerType; case LogEventListener::CodeTag::kRegExp: return v8::CodeEventType::kRegExpType; case LogEventListener::CodeTag::kNativeScript: case LogEventListener::CodeTag::kScript: return v8::CodeEventType::kScriptType; case LogEventListener::CodeTag::kStub: return v8::CodeEventType::kStubType; } UNREACHABLE(); } #define CALL_CODE_EVENT_HANDLER(Call) \ if (listener_) { \ listener_->Call; \ } else { \ PROFILE(isolate_, Call); \ } const char* ComputeMarker(SharedFunctionInfo shared, AbstractCode code) { PtrComprCageBase cage_base = GetPtrComprCageBase(shared); CodeKind kind = code.kind(cage_base); // We record interpreter trampoline builtin copies as having the // "interpreted" marker. if (v8_flags.interpreted_frames_native_stack && kind == CodeKind::BUILTIN && !code.is_off_heap_trampoline(cage_base)) { DCHECK_EQ(code.builtin_id(cage_base), Builtin::kInterpreterEntryTrampoline); kind = CodeKind::INTERPRETED_FUNCTION; } if (shared.optimization_disabled() && kind == CodeKind::INTERPRETED_FUNCTION) { return ""; } return CodeKindToMarker(kind); } #if V8_ENABLE_WEBASSEMBLY const char* ComputeMarker(const wasm::WasmCode* code) { switch (code->kind()) { case wasm::WasmCode::kWasmFunction: return code->is_liftoff() ? "" : "*"; default: return ""; } } #endif // V8_ENABLE_WEBASSEMBLY } // namespace class CodeEventLogger::NameBuffer { public: NameBuffer() { Reset(); } void Reset() { utf8_pos_ = 0; } void Init(CodeTag tag) { Reset(); AppendBytes(kCodeTagNames[static_cast(tag)]); AppendByte(':'); } void AppendName(Name name) { if (name.IsString()) { AppendString(String::cast(name)); } else { Symbol symbol = Symbol::cast(name); AppendBytes("symbol("); if (!symbol.description().IsUndefined()) { AppendBytes("\""); AppendString(String::cast(symbol.description())); 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 = std::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; base::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; base::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 = 4096; static const int kUtf16BufferSize = kUtf8BufferSize; int utf8_pos_; char utf8_buffer_[kUtf8BufferSize]; }; CodeEventLogger::CodeEventLogger(Isolate* isolate) : isolate_(isolate), name_buffer_(std::make_unique()) {} CodeEventLogger::~CodeEventLogger() = default; void CodeEventLogger::CodeCreateEvent(CodeTag tag, Handle code, const char* comment) { DCHECK(is_listening_to_code_events()); name_buffer_->Init(tag); name_buffer_->AppendBytes(comment); LogRecordedBuffer(code, MaybeHandle(), name_buffer_->get(), name_buffer_->size()); } void CodeEventLogger::CodeCreateEvent(CodeTag tag, Handle code, Handle name) { DCHECK(is_listening_to_code_events()); name_buffer_->Init(tag); name_buffer_->AppendName(*name); LogRecordedBuffer(code, MaybeHandle(), name_buffer_->get(), name_buffer_->size()); } void CodeEventLogger::CodeCreateEvent(CodeTag tag, Handle code, Handle shared, Handle script_name) { DCHECK(is_listening_to_code_events()); name_buffer_->Init(tag); name_buffer_->AppendBytes(ComputeMarker(*shared, *code)); name_buffer_->AppendByte(' '); name_buffer_->AppendName(*script_name); LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size()); } void CodeEventLogger::CodeCreateEvent(CodeTag tag, Handle code, Handle shared, Handle script_name, int line, int column) { DCHECK(is_listening_to_code_events()); name_buffer_->Init(tag); name_buffer_->AppendBytes(ComputeMarker(*shared, *code)); name_buffer_->AppendBytes(shared->DebugNameCStr().get()); name_buffer_->AppendByte(' '); if (script_name->IsString()) { name_buffer_->AppendString(String::cast(*script_name)); } else { name_buffer_->AppendBytes("symbol(hash "); name_buffer_->AppendHex(Name::cast(*script_name).hash()); name_buffer_->AppendByte(')'); } name_buffer_->AppendByte(':'); name_buffer_->AppendInt(line); name_buffer_->AppendByte(':'); name_buffer_->AppendInt(column); LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size()); } #if V8_ENABLE_WEBASSEMBLY void CodeEventLogger::CodeCreateEvent(CodeTag tag, const wasm::WasmCode* code, wasm::WasmName name, const char* source_url, int /*code_offset*/, int /*script_id*/) { DCHECK(is_listening_to_code_events()); name_buffer_->Init(tag); DCHECK(!name.empty()); name_buffer_->AppendBytes(name.begin(), name.length()); name_buffer_->AppendByte('-'); if (code->IsAnonymous()) { name_buffer_->AppendBytes(""); } else { name_buffer_->AppendInt(code->index()); } name_buffer_->AppendByte('-'); name_buffer_->AppendBytes(ExecutionTierToString(code->tier())); LogRecordedBuffer(code, name_buffer_->get(), name_buffer_->size()); } #endif // V8_ENABLE_WEBASSEMBLY void CodeEventLogger::RegExpCodeCreateEvent(Handle code, Handle source) { DCHECK(is_listening_to_code_events()); name_buffer_->Init(LogEventListener::CodeTag::kRegExp); name_buffer_->AppendString(*source); LogRecordedBuffer(code, MaybeHandle(), name_buffer_->get(), name_buffer_->size()); } // Linux perf tool logging support. #if V8_OS_LINUX class LinuxPerfBasicLogger : public CodeEventLogger { public: explicit LinuxPerfBasicLogger(Isolate* isolate); ~LinuxPerfBasicLogger() override; void CodeMoveEvent(AbstractCode from, AbstractCode to) override {} void CodeDisableOptEvent(Handle code, Handle shared) override {} private: void LogRecordedBuffer(Handle code, MaybeHandle maybe_shared, const char* name, int length) override; #if V8_ENABLE_WEBASSEMBLY void LogRecordedBuffer(const wasm::WasmCode* code, const char* name, int length) override; #endif // V8_ENABLE_WEBASSEMBLY 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; // Per-process singleton file. We assume that there is one main isolate // to determine when it goes away, we keep the reference count. static base::LazyRecursiveMutex file_mutex_; static FILE* perf_output_handle_; static uint64_t reference_count_; }; const char LinuxPerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map"; // Extra space for the PID in the filename const int LinuxPerfBasicLogger::kFilenameBufferPadding = 16; base::LazyRecursiveMutex LinuxPerfBasicLogger::file_mutex_; // The following static variables are protected by // LinuxPerfBasicLogger::file_mutex_. uint64_t LinuxPerfBasicLogger::reference_count_ = 0; FILE* LinuxPerfBasicLogger::perf_output_handle_ = nullptr; LinuxPerfBasicLogger::LinuxPerfBasicLogger(Isolate* isolate) : CodeEventLogger(isolate) { base::LockGuard guard_file(file_mutex_.Pointer()); int process_id_ = base::OS::GetCurrentProcessId(); reference_count_++; // If this is the first logger, open the file. if (reference_count_ == 1) { CHECK_NULL(perf_output_handle_); // Open the perf JIT dump file. int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding; base::ScopedVector perf_dump_name(bufferSize); int size = SNPrintF(perf_dump_name, kFilenameFormatString, process_id_); 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); } } LinuxPerfBasicLogger::~LinuxPerfBasicLogger() { base::LockGuard guard_file(file_mutex_.Pointer()); reference_count_--; // If this was the last logger, close the file. if (reference_count_ == 0) { CHECK_NOT_NULL(perf_output_handle_); base::Fclose(perf_output_handle_); perf_output_handle_ = nullptr; } } void LinuxPerfBasicLogger::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 LinuxPerfBasicLogger::LogRecordedBuffer(Handle code, MaybeHandle, const char* name, int length) { PtrComprCageBase cage_base(isolate_); if (v8_flags.perf_basic_prof_only_functions && CodeKindIsBuiltinOrJSFunction(code->kind(cage_base))) { return; } WriteLogRecordedBuffer( static_cast(code->InstructionStart(cage_base)), code->InstructionSize(cage_base), name, length); } #if V8_ENABLE_WEBASSEMBLY void LinuxPerfBasicLogger::LogRecordedBuffer(const wasm::WasmCode* code, const char* name, int length) { WriteLogRecordedBuffer(static_cast(code->instruction_start()), code->instructions().length(), name, length); } #endif // V8_ENABLE_WEBASSEMBLY #endif // V8_OS_LINUX // External LogEventListener ExternalLogEventListener::ExternalLogEventListener(Isolate* isolate) : is_listening_(false), isolate_(isolate), code_event_handler_(nullptr) {} ExternalLogEventListener::~ExternalLogEventListener() { if (is_listening_) { StopListening(); } } void ExternalLogEventListener::LogExistingCode() { HandleScope scope(isolate_); ExistingCodeLogger logger(isolate_, this); logger.LogBuiltins(); logger.LogCodeObjects(); logger.LogCompiledFunctions(); } void ExternalLogEventListener::StartListening( CodeEventHandler* code_event_handler) { if (is_listening_ || code_event_handler == nullptr) { return; } code_event_handler_ = code_event_handler; is_listening_ = isolate_->logger()->AddListener(this); if (is_listening_) { LogExistingCode(); } } void ExternalLogEventListener::StopListening() { if (!is_listening_) { return; } isolate_->logger()->RemoveListener(this); is_listening_ = false; } void ExternalLogEventListener::CodeCreateEvent(CodeTag tag, Handle code, const char* comment) { PtrComprCageBase cage_base(isolate_); CodeEvent code_event; code_event.code_start_address = static_cast(code->InstructionStart(cage_base)); code_event.code_size = static_cast(code->InstructionSize(cage_base)); 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 ExternalLogEventListener::CodeCreateEvent(CodeTag tag, Handle code, Handle name) { Handle name_string = Name::ToFunctionName(isolate_, name).ToHandleChecked(); PtrComprCageBase cage_base(isolate_); CodeEvent code_event; code_event.code_start_address = static_cast(code->InstructionStart(cage_base)); code_event.code_size = static_cast(code->InstructionSize(cage_base)); 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 ExternalLogEventListener::CodeCreateEvent( CodeTag tag, Handle code, Handle shared, Handle name) { Handle name_string = Name::ToFunctionName(isolate_, name).ToHandleChecked(); PtrComprCageBase cage_base(isolate_); CodeEvent code_event; code_event.code_start_address = static_cast(code->InstructionStart(cage_base)); code_event.code_size = static_cast(code->InstructionSize(cage_base)); 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 ExternalLogEventListener::CodeCreateEvent( CodeTag tag, Handle code, Handle shared, Handle source, int line, int column) { Handle name_string = Name::ToFunctionName(isolate_, handle(shared->Name(), isolate_)) .ToHandleChecked(); Handle source_string = Name::ToFunctionName(isolate_, source).ToHandleChecked(); PtrComprCageBase cage_base(isolate_); CodeEvent code_event; code_event.code_start_address = static_cast(code->InstructionStart(cage_base)); code_event.code_size = static_cast(code->InstructionSize(cage_base)); 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)); } #if V8_ENABLE_WEBASSEMBLY void ExternalLogEventListener::CodeCreateEvent(CodeTag tag, const wasm::WasmCode* code, wasm::WasmName name, const char* source_url, int code_offset, int script_id) { // TODO(mmarchini): handle later } #endif // V8_ENABLE_WEBASSEMBLY void ExternalLogEventListener::RegExpCodeCreateEvent(Handle code, Handle source) { PtrComprCageBase cage_base(isolate_); CodeEvent code_event; code_event.code_start_address = static_cast(code->InstructionStart(cage_base)); code_event.code_size = static_cast(code->InstructionSize(cage_base)); code_event.function_name = source; code_event.script_name = isolate_->factory()->empty_string(); code_event.script_line = 0; code_event.script_column = 0; code_event.code_type = GetCodeEventTypeForTag(LogEventListener::CodeTag::kRegExp); code_event.comment = ""; code_event_handler_->Handle(reinterpret_cast(&code_event)); } void ExternalLogEventListener::CodeMoveEvent(AbstractCode from, AbstractCode to) { PtrComprCageBase cage_base(isolate_); CodeEvent code_event; code_event.previous_code_start_address = static_cast(from.InstructionStart(cage_base)); code_event.code_start_address = static_cast(to.InstructionStart(cage_base)); code_event.code_size = static_cast(to.InstructionSize(cage_base)); 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 = v8::CodeEventType::kRelocationType; 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(Handle code, Handle shared) override {} void SnapshotPositionEvent(HeapObject obj, int pos); void CodeMovingGCEvent() override; private: void LogRecordedBuffer(Handle code, MaybeHandle maybe_shared, const char* name, int length) override; #if V8_ENABLE_WEBASSEMBLY void LogRecordedBuffer(const wasm::WasmCode* code, const char* name, int length) override; #endif // V8_ENABLE_WEBASSEMBLY // 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); base::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() { base::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_PPC64 const char arch[] = "ppc64"; #elif V8_TARGET_ARCH_LOONG64 const char arch[] = "loong64"; #elif V8_TARGET_ARCH_ARM64 const char arch[] = "arm64"; #elif V8_TARGET_ARCH_S390 const char arch[] = "s390"; #elif V8_TARGET_ARCH_RISCV64 const char arch[] = "riscv64"; #elif V8_TARGET_ARCH_RISCV32 const char arch[] = "riscv32"; #else const char arch[] = "unknown"; #endif LogWriteBytes(arch, sizeof(arch)); } void LowLevelLogger::LogRecordedBuffer(Handle code, MaybeHandle, const char* name, int length) { PtrComprCageBase cage_base(isolate_); CodeCreateStruct event; event.name_size = length; event.code_address = code->InstructionStart(cage_base); event.code_size = code->InstructionSize(cage_base); LogWriteStruct(event); LogWriteBytes(name, length); LogWriteBytes( reinterpret_cast(code->InstructionStart(cage_base)), code->InstructionSize(cage_base)); } #if V8_ENABLE_WEBASSEMBLY 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()); } #endif // V8_ENABLE_WEBASSEMBLY void LowLevelLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) { PtrComprCageBase cage_base(isolate_); CodeMoveStruct event; event.from_address = from.InstructionStart(cage_base); event.to_address = to.InstructionStart(cage_base); 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(Handle code, Handle shared) override {} void AddCodeLinePosInfoEvent(void* jit_handler_data, int pc_offset, int position, JitCodeEvent::PositionType position_type, JitCodeEvent::CodeType code_type); void* StartCodePosInfoEvent(JitCodeEvent::CodeType code_type); void EndCodePosInfoEvent(Address start_address, void* jit_handler_data, JitCodeEvent::CodeType code_type); private: void LogRecordedBuffer(Handle code, MaybeHandle maybe_shared, const char* name, int length) override; #if V8_ENABLE_WEBASSEMBLY void LogRecordedBuffer(const wasm::WasmCode* code, const char* name, int length) override; #endif // V8_ENABLE_WEBASSEMBLY JitCodeEventHandler code_event_handler_; base::Mutex logger_mutex_; }; JitLogger::JitLogger(Isolate* isolate, JitCodeEventHandler code_event_handler) : CodeEventLogger(isolate), code_event_handler_(code_event_handler) { DCHECK_NOT_NULL(code_event_handler); } void JitLogger::LogRecordedBuffer(Handle code, MaybeHandle maybe_shared, const char* name, int length) { PtrComprCageBase cage_base(isolate_); JitCodeEvent event; event.type = JitCodeEvent::CODE_ADDED; event.code_start = reinterpret_cast(code->InstructionStart(cage_base)); event.code_type = code->IsCode(cage_base) ? JitCodeEvent::JIT_CODE : JitCodeEvent::BYTE_CODE; event.code_len = code->InstructionSize(cage_base); Handle shared; if (maybe_shared.ToHandle(&shared) && shared->script(cage_base).IsScript(cage_base)) { event.script = ToApiHandle(shared); } else { event.script = Local(); } event.name.str = name; event.name.len = length; event.isolate = reinterpret_cast(isolate_); code_event_handler_(&event); } #if V8_ENABLE_WEBASSEMBLY void JitLogger::LogRecordedBuffer(const wasm::WasmCode* code, const char* name, int length) { JitCodeEvent event; event.type = JitCodeEvent::CODE_ADDED; event.code_type = JitCodeEvent::WASM_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_); wasm::WasmModuleSourceMap* source_map = code->native_module()->GetWasmSourceMap(); wasm::WireBytesRef code_ref = code->native_module()->module()->functions[code->index()].code; uint32_t code_offset = code_ref.offset(); uint32_t code_end_offset = code_ref.end_offset(); std::vector mapping_info; std::string filename; std::unique_ptr wasm_source_info; if (source_map && source_map->IsValid() && source_map->HasSource(code_offset, code_end_offset)) { size_t last_line_number = 0; for (SourcePositionTableIterator iterator(code->source_positions()); !iterator.done(); iterator.Advance()) { uint32_t offset = iterator.source_position().ScriptOffset() + code_offset; if (!source_map->HasValidEntry(code_offset, offset)) continue; if (filename.empty()) { filename = source_map->GetFilename(offset); } mapping_info.push_back({static_cast(iterator.code_offset()), last_line_number, JitCodeEvent::POSITION}); last_line_number = source_map->GetSourceLine(offset) + 1; } wasm_source_info = std::make_unique(); wasm_source_info->filename = filename.c_str(); wasm_source_info->filename_size = filename.size(); wasm_source_info->line_number_table_size = mapping_info.size(); wasm_source_info->line_number_table = mapping_info.data(); event.wasm_source_info = wasm_source_info.get(); } code_event_handler_(&event); } #endif // V8_ENABLE_WEBASSEMBLY void JitLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) { base::MutexGuard guard(&logger_mutex_); PtrComprCageBase cage_base(isolate_); JitCodeEvent event; event.type = JitCodeEvent::CODE_MOVED; event.code_type = from.IsCode(cage_base) ? JitCodeEvent::JIT_CODE : JitCodeEvent::BYTE_CODE; event.code_start = reinterpret_cast(from.InstructionStart(cage_base)); event.code_len = from.InstructionSize(cage_base); event.new_code_start = reinterpret_cast(to.InstructionStart(cage_base)); 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::CodeType code_type) { JitCodeEvent event; event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO; event.code_type = code_type; 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::CodeType code_type) { JitCodeEvent event; event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING; event.code_type = code_type; event.isolate = reinterpret_cast(isolate_); code_event_handler_(&event); return event.user_data; } void JitLogger::EndCodePosInfoEvent(Address start_address, void* jit_handler_data, JitCodeEvent::CodeType code_type) { JitCodeEvent event; event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING; event.code_type = code_type; 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_; }; #if defined(V8_OS_WIN) && defined(V8_ENABLE_ETW_STACK_WALKING) class ETWJitLogger : public JitLogger { public: explicit ETWJitLogger(Isolate* isolate) : JitLogger(isolate, i::ETWJITInterface::EventHandler) {} }; #endif // 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(TickSample* sample) { if (Succ(head_) == static_cast(base::Acquire_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(TickSample* sample) { buffer_semaphore_.Wait(); // Wait for an element. *sample = buffer_[base::Relaxed_Load(&tail_)]; bool result = overflow_; base::Release_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; 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_( std::make_unique(this, interval_microseconds)), perThreadData_(isolate->FindPerThreadDataForThisThread()) {} ~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()); if (isolate->was_locker_ever_used() && (!isolate->thread_manager()->IsLockedByThread( perThreadData_->thread_id()) || perThreadData_->thread_state() != nullptr)) return; #if V8_HEAP_USE_PKU_JIT_WRITE_PROTECT i::RwxMemoryWriteScope::SetDefaultPermissionsForSignalHandler(); #endif TickSample sample; sample.Init(isolate, state, TickSample::kIncludeCEntryFrame, true); profiler_->Insert(&sample); } private: Profiler* profiler_ = nullptr; std::unique_ptr sampling_thread_; Isolate::PerIsolateThreadData* perThreadData_; }; // // 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)); } LOG(isolate_, SharedLibraryEnd()); // Start thread processing the profiler buffer. base::Relaxed_Store(&running_, 1); CHECK(Start()); // Register to get ticks. V8FileLogger* logger = isolate_->v8_file_logger(); logger->ticker_->SetProfiler(this); LOG(isolate_, ProfilerBeginEvent()); } void Profiler::Disengage() { // Stop receiving ticks. isolate_->v8_file_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); TickSample sample; Insert(&sample); Join(); LOG(isolate_, UncheckedStringEvent("profiler", "end")); } void Profiler::Run() { TickSample sample; bool overflow = Remove(&sample); while (base::Relaxed_Load(&running_)) { LOG(isolate_, TickEvent(&sample, overflow)); overflow = Remove(&sample); } } // // V8FileLogger class implementation. // #define MSG_BUILDER() \ std::unique_ptr msg_ptr = \ log_->NewMessageBuilder(); \ if (!msg_ptr) return; \ LogFile::MessageBuilder& msg = *msg_ptr.get(); V8FileLogger::V8FileLogger(Isolate* isolate) : isolate_(isolate), is_logging_(false), is_initialized_(false), existing_code_logger_(isolate) {} V8FileLogger::~V8FileLogger() = default; const LogSeparator V8FileLogger::kNext = LogSeparator::kSeparator; int64_t V8FileLogger::Time() { if (v8_flags.verify_predictable) { return isolate_->heap()->MonotonicallyIncreasingTimeInMs() * 1000; } return timer_.Elapsed().InMicroseconds(); } void V8FileLogger::AddLogEventListener(LogEventListener* listener) { bool result = isolate_->logger()->AddListener(listener); CHECK(result); } void V8FileLogger::RemoveLogEventListener(LogEventListener* listener) { isolate_->logger()->RemoveListener(listener); } void V8FileLogger::ProfilerBeginEvent() { MSG_BUILDER(); msg << "profiler" << kNext << "begin" << kNext << v8_flags.prof_sampling_interval; msg.WriteToLogFile(); } void V8FileLogger::StringEvent(const char* name, const char* value) { if (v8_flags.log) UncheckedStringEvent(name, value); } void V8FileLogger::UncheckedStringEvent(const char* name, const char* value) { MSG_BUILDER(); msg << name << kNext << value; msg.WriteToLogFile(); } void V8FileLogger::IntPtrTEvent(const char* name, intptr_t value) { if (!v8_flags.log) return; MSG_BUILDER(); msg << name << kNext; msg.AppendFormatString("%" V8PRIdPTR, value); msg.WriteToLogFile(); } void V8FileLogger::SharedLibraryEvent(const std::string& library_path, uintptr_t start, uintptr_t end, intptr_t aslr_slide) { if (!v8_flags.prof_cpp) return; MSG_BUILDER(); msg << "shared-library" << kNext << library_path.c_str() << kNext << reinterpret_cast(start) << kNext << reinterpret_cast(end) << kNext << aslr_slide; msg.WriteToLogFile(); } void V8FileLogger::SharedLibraryEnd() { if (!v8_flags.prof_cpp) return; MSG_BUILDER(); msg << "shared-library-end"; msg.WriteToLogFile(); } void V8FileLogger::CurrentTimeEvent() { DCHECK(v8_flags.log_internal_timer_events); MSG_BUILDER(); msg << "current-time" << kNext << Time(); msg.WriteToLogFile(); } void V8FileLogger::TimerEvent(v8::LogEventStatus se, const char* name) { MSG_BUILDER(); switch (se) { case kStart: msg << "timer-event-start"; break; case kEnd: msg << "timer-event-end"; break; case kStamp: msg << "timer-event"; } msg << kNext << name << kNext << Time(); msg.WriteToLogFile(); } bool V8FileLogger::is_logging() { // Disable logging while the CPU profiler is running. if (isolate_->is_profiling()) return false; return is_logging_.load(std::memory_order_relaxed); } // Instantiate template methods. #define V(TimerName, expose) \ template void TimerEventScope::LogTimerEvent( \ v8::LogEventStatus se); TIMER_EVENTS_LIST(V) #undef V void V8FileLogger::NewEvent(const char* name, void* object, size_t size) { if (!v8_flags.log) return; MSG_BUILDER(); msg << "new" << kNext << name << kNext << object << kNext << static_cast(size); msg.WriteToLogFile(); } void V8FileLogger::DeleteEvent(const char* name, void* object) { if (!v8_flags.log) return; MSG_BUILDER(); msg << "delete" << kNext << name << kNext << object; msg.WriteToLogFile(); } namespace { void AppendCodeCreateHeader(LogFile::MessageBuilder& msg, LogEventListener::CodeTag tag, CodeKind kind, uint8_t* address, int size, uint64_t time) { msg << LogEventListener::Event::kCodeCreation << V8FileLogger::kNext << tag << V8FileLogger::kNext << static_cast(kind) << V8FileLogger::kNext << time << V8FileLogger::kNext << reinterpret_cast(address) << V8FileLogger::kNext << size << V8FileLogger::kNext; } void AppendCodeCreateHeader(Isolate* isolate, LogFile::MessageBuilder& msg, LogEventListener::CodeTag tag, AbstractCode code, uint64_t time) { PtrComprCageBase cage_base(isolate); AppendCodeCreateHeader( msg, tag, code.kind(cage_base), reinterpret_cast(code.InstructionStart(cage_base)), code.InstructionSize(cage_base), time); } } // namespace // We log source code information in the form: // // code-source-info ,