| // 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/log.h" |
| |
| #include <cstdarg> |
| #include <memory> |
| #include <sstream> |
| |
| #include "src/bailout-reason.h" |
| #include "src/base/platform/platform.h" |
| #include "src/bootstrapper.h" |
| #include "src/code-stubs.h" |
| #include "src/counters.h" |
| #include "src/deoptimizer.h" |
| #include "src/global-handles.h" |
| #include "src/interpreter/bytecodes.h" |
| #include "src/interpreter/interpreter.h" |
| #include "src/libsampler/sampler.h" |
| #include "src/log-inl.h" |
| #include "src/log-utils.h" |
| #include "src/macro-assembler.h" |
| #include "src/perf-jit.h" |
| #include "src/profiler/profiler-listener.h" |
| #include "src/profiler/tick-sample.h" |
| #include "src/runtime-profiler.h" |
| #include "src/source-position-table.h" |
| #include "src/string-stream.h" |
| #include "src/tracing/tracing-category-observer.h" |
| #include "src/vm-state-inl.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 const char* ComputeMarker(SharedFunctionInfo* shared, |
| AbstractCode* code) { |
| switch (code->kind()) { |
| case AbstractCode::FUNCTION: |
| case AbstractCode::INTERPRETED_FUNCTION: |
| return shared->optimization_disabled() ? "" : "~"; |
| case AbstractCode::OPTIMIZED_FUNCTION: |
| 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(symbol->GetIsolate())) { |
| 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<char>(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_); |
| 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) { |
| int space = kUtf8BufferSize - utf8_pos_; |
| if (space <= 0) return; |
| Vector<char> 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<char> 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]; |
| uc16 utf16_buffer[kUtf16BufferSize]; |
| }; |
| |
| |
| CodeEventLogger::CodeEventLogger() : 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, NULL, 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, NULL, 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_->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(CodeEventListener::LogEventsAndTags tag, |
| AbstractCode* 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(AbstractCode* code, |
| String* source) { |
| name_buffer_->Init(CodeEventListener::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(); |
| ~PerfBasicLogger() override; |
| |
| void CodeMoveEvent(AbstractCode* from, Address to) override {} |
| void CodeDisableOptEvent(AbstractCode* code, |
| SharedFunctionInfo* shared) override {} |
| |
| private: |
| void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared, |
| const char* name, int length) override; |
| |
| // 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() |
| : perf_output_handle_(NULL) { |
| // Open the perf JIT dump file. |
| int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding; |
| ScopedVector<char> 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.start(), base::OS::LogFileOpenMode); |
| CHECK_NOT_NULL(perf_output_handle_); |
| setvbuf(perf_output_handle_, NULL, _IOLBF, 0); |
| } |
| |
| |
| PerfBasicLogger::~PerfBasicLogger() { |
| fclose(perf_output_handle_); |
| perf_output_handle_ = NULL; |
| } |
| |
| void PerfBasicLogger::LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo*, |
| const char* name, int length) { |
| if (FLAG_perf_basic_prof_only_functions && |
| (code->kind() != AbstractCode::FUNCTION && |
| code->kind() != AbstractCode::INTERPRETED_FUNCTION && |
| code->kind() != AbstractCode::OPTIMIZED_FUNCTION)) { |
| return; |
| } |
| |
| // 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", |
| reinterpret_cast<uintptr_t>(code->instruction_start()), |
| code->instruction_size(), length, name); |
| } |
| |
| // 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); |
| ~LowLevelLogger() override; |
| |
| void CodeMoveEvent(AbstractCode* from, Address 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; |
| |
| // 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 <typename T> |
| void LogWriteStruct(const T& s) { |
| char tag = T::kTag; |
| LogWriteBytes(reinterpret_cast<const char*>(&tag), sizeof(tag)); |
| LogWriteBytes(reinterpret_cast<const char*>(&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<char> ll_name(static_cast<int>(len + sizeof(kLogExt))); |
| MemCopy(ll_name.start(), name, len); |
| MemCopy(ll_name.start() + len, kLogExt, sizeof(kLogExt)); |
| ll_output_handle_ = |
| base::OS::FOpen(ll_name.start(), base::OS::LogFileOpenMode); |
| setvbuf(ll_output_handle_, NULL, _IOLBF, 0); |
| |
| 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 && V8_TARGET_ARCH_64_BIT |
| const char arch[] = "x64"; |
| #elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_32_BIT |
| const char arch[] = "x32"; |
| #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_X87 |
| const char arch[] = "x87"; |
| #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->instruction_start(); |
| event.code_size = code->instruction_size(); |
| LogWriteStruct(event); |
| LogWriteBytes(name, length); |
| LogWriteBytes( |
| reinterpret_cast<const char*>(code->instruction_start()), |
| code->instruction_size()); |
| } |
| |
| void LowLevelLogger::CodeMoveEvent(AbstractCode* from, Address to) { |
| CodeMoveStruct event; |
| event.from_address = from->instruction_start(); |
| size_t header_size = from->instruction_start() - from->address(); |
| event.to_address = to + header_size; |
| LogWriteStruct(event); |
| } |
| |
| |
| void LowLevelLogger::LogWriteBytes(const char* bytes, int size) { |
| size_t rv = fwrite(bytes, 1, size, ll_output_handle_); |
| DCHECK(static_cast<size_t>(size) == rv); |
| USE(rv); |
| } |
| |
| |
| void LowLevelLogger::CodeMovingGCEvent() { |
| const char tag = kCodeMovingGCTag; |
| |
| LogWriteBytes(&tag, sizeof(tag)); |
| } |
| |
| class JitLogger : public CodeEventLogger { |
| public: |
| explicit JitLogger(JitCodeEventHandler code_event_handler); |
| |
| void CodeMoveEvent(AbstractCode* from, Address 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(AbstractCode* code, void* jit_handler_data); |
| |
| private: |
| void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared, |
| const char* name, int length) override; |
| |
| JitCodeEventHandler code_event_handler_; |
| base::Mutex logger_mutex_; |
| }; |
| |
| |
| JitLogger::JitLogger(JitCodeEventHandler code_event_handler) |
| : code_event_handler_(code_event_handler) { |
| } |
| |
| void JitLogger::LogRecordedBuffer(AbstractCode* 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<SharedFunctionInfo> shared_function_handle; |
| if (shared && shared->script()->IsScript()) { |
| shared_function_handle = Handle<SharedFunctionInfo>(shared); |
| } |
| event.script = ToApiHandle<v8::UnboundScript>(shared_function_handle); |
| event.name.str = name; |
| event.name.len = length; |
| code_event_handler_(&event); |
| } |
| |
| void JitLogger::CodeMoveEvent(AbstractCode* from, Address to) { |
| base::LockGuard<base::Mutex> guard(&logger_mutex_); |
| |
| JitCodeEvent event; |
| event.type = JitCodeEvent::CODE_MOVED; |
| event.code_start = from->instruction_start(); |
| event.code_len = from->instruction_size(); |
| |
| // Calculate the header size. |
| const size_t header_size = from->instruction_start() - from->address(); |
| |
| // Calculate the new start address of the instructions. |
| event.new_code_start = to + header_size; |
| |
| code_event_handler_(&event); |
| } |
| |
| void JitLogger::AddCodeLinePosInfoEvent( |
| void* jit_handler_data, |
| int pc_offset, |
| int position, |
| JitCodeEvent::PositionType position_type) { |
| JitCodeEvent event; |
| memset(&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; |
| |
| code_event_handler_(&event); |
| } |
| |
| |
| void* JitLogger::StartCodePosInfoEvent() { |
| JitCodeEvent event; |
| memset(&event, 0, sizeof(event)); |
| event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING; |
| |
| code_event_handler_(&event); |
| return event.user_data; |
| } |
| |
| void JitLogger::EndCodePosInfoEvent(AbstractCode* code, |
| void* jit_handler_data) { |
| JitCodeEvent event; |
| memset(&event, 0, sizeof(event)); |
| event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING; |
| event.code_start = code->instruction_start(); |
| event.user_data = jit_handler_data; |
| |
| 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) |
| : base::Thread(base::Thread::Options("SamplingThread", |
| kSamplingThreadStackSize)), |
| sampler_(sampler), |
| interval_(interval) {} |
| void Run() override { |
| while (sampler_->IsProfiling()) { |
| sampler_->DoSample(); |
| base::OS::Sleep(base::TimeDelta::FromMilliseconds(interval_)); |
| } |
| } |
| |
| private: |
| sampler::Sampler* sampler_; |
| const int interval_; |
| }; |
| |
| |
| // 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 (paused_) |
| return; |
| |
| if (Succ(head_) == static_cast<int>(base::NoBarrier_Load(&tail_))) { |
| overflow_ = true; |
| } else { |
| buffer_[head_] = *sample; |
| head_ = Succ(head_); |
| buffer_semaphore_.Signal(); // Tell we have an element. |
| } |
| } |
| |
| virtual void Run(); |
| |
| // Pause and Resume TickSample data collection. |
| void pause() { paused_ = true; } |
| void resume() { paused_ = false; } |
| |
| private: |
| // Waits for a signal and removes profiling data. |
| bool Remove(v8::TickSample* sample) { |
| buffer_semaphore_.Wait(); // Wait for an element. |
| *sample = buffer_[base::NoBarrier_Load(&tail_)]; |
| bool result = overflow_; |
| base::NoBarrier_Store(&tail_, static_cast<base::Atomic32>( |
| Succ(base::NoBarrier_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. |
| // Sempahore used for buffer synchronization. |
| base::Semaphore buffer_semaphore_; |
| |
| // Tells whether profiler is engaged, that is, processing thread is stated. |
| bool engaged_; |
| |
| // Tells whether worker thread should continue running. |
| base::Atomic32 running_; |
| |
| // Tells whether we are currently recording tick samples. |
| bool paused_; |
| }; |
| |
| |
| // |
| // Ticker used to provide ticks to the profiler and the sliding state |
| // window. |
| // |
| class Ticker: public sampler::Sampler { |
| public: |
| Ticker(Isolate* isolate, int interval) |
| : sampler::Sampler(reinterpret_cast<v8::Isolate*>(isolate)), |
| profiler_(nullptr), |
| sampling_thread_(new SamplingThread(this, interval)) {} |
| |
| ~Ticker() { |
| if (IsActive()) Stop(); |
| delete sampling_thread_; |
| } |
| |
| void SetProfiler(Profiler* profiler) { |
| DCHECK(profiler_ == nullptr); |
| profiler_ = profiler; |
| IncreaseProfilingDepth(); |
| if (!IsActive()) Start(); |
| sampling_thread_->StartSynchronously(); |
| } |
| |
| void ClearProfiler() { |
| profiler_ = nullptr; |
| if (IsActive()) Stop(); |
| DecreaseProfilingDepth(); |
| sampling_thread_->Join(); |
| } |
| |
| void SampleStack(const v8::RegisterState& state) override { |
| if (!profiler_) return; |
| Isolate* isolate = reinterpret_cast<Isolate*>(this->isolate()); |
| TickSample sample; |
| sample.Init(isolate, state, TickSample::kIncludeCEntryFrame, true); |
| profiler_->Insert(&sample); |
| } |
| |
| private: |
| Profiler* profiler_; |
| SamplingThread* sampling_thread_; |
| }; |
| |
| |
| // |
| // Profiler implementation. |
| // |
| Profiler::Profiler(Isolate* isolate) |
| : base::Thread(Options("v8:Profiler")), |
| isolate_(isolate), |
| head_(0), |
| overflow_(false), |
| buffer_semaphore_(0), |
| engaged_(false), |
| paused_(false) { |
| base::NoBarrier_Store(&tail_, 0); |
| base::NoBarrier_Store(&running_, 0); |
| } |
| |
| |
| void Profiler::Engage() { |
| if (engaged_) return; |
| engaged_ = true; |
| |
| std::vector<base::OS::SharedLibraryAddress> addresses = |
| base::OS::GetSharedLibraryAddresses(); |
| for (size_t i = 0; i < addresses.size(); ++i) { |
| LOG(isolate_, |
| SharedLibraryEvent(addresses[i].library_path, addresses[i].start, |
| addresses[i].end, addresses[i].aslr_slide)); |
| } |
| |
| // Start thread processing the profiler buffer. |
| base::NoBarrier_Store(&running_, 1); |
| Start(); |
| |
| // Register to get ticks. |
| Logger* logger = isolate_->logger(); |
| logger->ticker_->SetProfiler(this); |
| |
| logger->ProfilerBeginEvent(); |
| } |
| |
| |
| void Profiler::Disengage() { |
| if (!engaged_) return; |
| |
| // 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::NoBarrier_Store(&running_, 0); |
| v8::TickSample sample; |
| // Reset 'paused_' flag, otherwise semaphore may not be signalled. |
| resume(); |
| Insert(&sample); |
| Join(); |
| |
| LOG(isolate_, UncheckedStringEvent("profiler", "end")); |
| } |
| |
| |
| void Profiler::Run() { |
| v8::TickSample sample; |
| bool overflow = Remove(&sample); |
| while (base::NoBarrier_Load(&running_)) { |
| LOG(isolate_, TickEvent(&sample, overflow)); |
| overflow = Remove(&sample); |
| } |
| } |
| |
| |
| // |
| // Logger class implementation. |
| // |
| |
| Logger::Logger(Isolate* isolate) |
| : isolate_(isolate), |
| ticker_(NULL), |
| profiler_(NULL), |
| 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), |
| is_initialized_(false) {} |
| |
| Logger::~Logger() { |
| delete log_; |
| } |
| |
| void Logger::addCodeEventListener(CodeEventListener* listener) { |
| bool result = isolate_->code_event_dispatcher()->AddListener(listener); |
| USE(result); |
| DCHECK(result); |
| } |
| |
| void Logger::removeCodeEventListener(CodeEventListener* listener) { |
| isolate_->code_event_dispatcher()->RemoveListener(listener); |
| } |
| |
| void Logger::ProfilerBeginEvent() { |
| if (!log_->IsEnabled()) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("profiler,\"begin\",%d", kSamplingIntervalMs); |
| 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.Append("%s,\"%s\"", name, value); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::IntEvent(const char* name, int value) { |
| if (FLAG_log) UncheckedIntEvent(name, value); |
| } |
| |
| |
| void Logger::IntPtrTEvent(const char* name, intptr_t value) { |
| if (FLAG_log) UncheckedIntPtrTEvent(name, value); |
| } |
| |
| |
| void Logger::UncheckedIntEvent(const char* name, int value) { |
| if (!log_->IsEnabled()) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("%s,%d", name, value); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) { |
| if (!log_->IsEnabled()) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("%s,%" V8PRIdPTR, name, value); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::HandleEvent(const char* name, Object** location) { |
| if (!log_->IsEnabled() || !FLAG_log_handles) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("%s,%p", name, static_cast<void*>(location)); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| // ApiEvent is private so all the calls come from the Logger class. It is the |
| // caller's responsibility to ensure that log is enabled and that |
| // FLAG_log_api is true. |
| void Logger::ApiEvent(const char* format, ...) { |
| DCHECK(log_->IsEnabled() && FLAG_log_api); |
| Log::MessageBuilder msg(log_); |
| va_list ap; |
| va_start(ap, format); |
| msg.AppendVA(format, ap); |
| va_end(ap); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::ApiSecurityCheck() { |
| if (!log_->IsEnabled() || !FLAG_log_api) return; |
| ApiEvent("api,check-security"); |
| } |
| |
| 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.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR |
| ",%" V8PRIdPTR, |
| library_path.c_str(), start, end, aslr_slide); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::CodeDeoptEvent(Code* code, Address pc, int fp_to_sp_delta) { |
| if (!log_->IsEnabled() || !FLAG_log_internal_timer_events) return; |
| Log::MessageBuilder msg(log_); |
| int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds()); |
| msg.Append("code-deopt,%d,%d", since_epoch, code->CodeSize()); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::CurrentTimeEvent() { |
| if (!log_->IsEnabled()) return; |
| DCHECK(FLAG_log_timer_events || FLAG_prof_cpp); |
| Log::MessageBuilder msg(log_); |
| int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds()); |
| msg.Append("current-time,%d", since_epoch); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::TimerEvent(Logger::StartEnd se, const char* name) { |
| if (!log_->IsEnabled()) return; |
| DCHECK(FLAG_log_internal_timer_events); |
| Log::MessageBuilder msg(log_); |
| int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds()); |
| const char* format = (se == START) ? "timer-event-start,\"%s\",%ld" |
| : "timer-event-end,\"%s\",%ld"; |
| msg.Append(format, name, since_epoch); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::EnterExternal(Isolate* isolate) { |
| LOG(isolate, TimerEvent(START, TimerEventExternal::name())); |
| DCHECK(isolate->current_vm_state() == JS); |
| isolate->set_current_vm_state(EXTERNAL); |
| } |
| |
| |
| void Logger::LeaveExternal(Isolate* isolate) { |
| LOG(isolate, TimerEvent(END, TimerEventExternal::name())); |
| DCHECK(isolate->current_vm_state() == EXTERNAL); |
| isolate->set_current_vm_state(JS); |
| } |
| |
| // Instantiate template methods. |
| #define V(TimerName, expose) \ |
| template void TimerEventScope<TimerEvent##TimerName>::LogTimerEvent( \ |
| Logger::StartEnd se); |
| TIMER_EVENTS_LIST(V) |
| #undef V |
| |
| void Logger::ApiNamedPropertyAccess(const char* tag, |
| JSObject* holder, |
| Object* name) { |
| DCHECK(name->IsName()); |
| if (!log_->IsEnabled() || !FLAG_log_api) return; |
| String* class_name_obj = holder->class_name(); |
| std::unique_ptr<char[]> class_name = |
| class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
| if (name->IsString()) { |
| std::unique_ptr<char[]> property_name = |
| String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
| ApiEvent("api,%s,\"%s\",\"%s\"", tag, class_name.get(), |
| property_name.get()); |
| } else { |
| Symbol* symbol = Symbol::cast(name); |
| uint32_t hash = symbol->Hash(); |
| if (symbol->name()->IsUndefined(symbol->GetIsolate())) { |
| ApiEvent("api,%s,\"%s\",symbol(hash %x)", tag, class_name.get(), hash); |
| } else { |
| std::unique_ptr<char[]> str = |
| String::cast(symbol->name()) |
| ->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
| ApiEvent("api,%s,\"%s\",symbol(\"%s\" hash %x)", tag, class_name.get(), |
| str.get(), hash); |
| } |
| } |
| } |
| |
| void Logger::ApiIndexedPropertyAccess(const char* tag, |
| JSObject* holder, |
| uint32_t index) { |
| if (!log_->IsEnabled() || !FLAG_log_api) return; |
| String* class_name_obj = holder->class_name(); |
| std::unique_ptr<char[]> class_name = |
| class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
| ApiEvent("api,%s,\"%s\",%u", tag, class_name.get(), index); |
| } |
| |
| |
| void Logger::ApiObjectAccess(const char* tag, JSObject* object) { |
| if (!log_->IsEnabled() || !FLAG_log_api) return; |
| String* class_name_obj = object->class_name(); |
| std::unique_ptr<char[]> class_name = |
| class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
| ApiEvent("api,%s,\"%s\"", tag, class_name.get()); |
| } |
| |
| |
| void Logger::ApiEntryCall(const char* name) { |
| if (!log_->IsEnabled() || !FLAG_log_api) return; |
| ApiEvent("api,%s", name); |
| } |
| |
| |
| void Logger::NewEvent(const char* name, void* object, size_t size) { |
| if (!log_->IsEnabled() || !FLAG_log) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("new,%s,%p,%u", name, object, static_cast<unsigned int>(size)); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::DeleteEvent(const char* name, void* object) { |
| if (!log_->IsEnabled() || !FLAG_log) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("delete,%s,%p", name, 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.Append("%s,%s,-2,", |
| kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT], |
| kLogEventsNames[CodeEventListener::CALLBACK_TAG]); |
| msg.AppendAddress(entry_point); |
| if (name->IsString()) { |
| std::unique_ptr<char[]> str = |
| String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
| msg.Append(",1,\"%s%s\"", prefix, str.get()); |
| } else { |
| Symbol* symbol = Symbol::cast(name); |
| if (symbol->name()->IsUndefined(symbol->GetIsolate())) { |
| msg.Append(",1,symbol(hash %x)", symbol->Hash()); |
| } else { |
| std::unique_ptr<char[]> str = |
| String::cast(symbol->name()) |
| ->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
| msg.Append(",1,symbol(\"%s%s\" hash %x)", prefix, str.get(), |
| symbol->Hash()); |
| } |
| } |
| 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); |
| } |
| |
| static void AppendCodeCreateHeader(Log::MessageBuilder* msg, |
| CodeEventListener::LogEventsAndTags tag, |
| AbstractCode* code) { |
| DCHECK(msg); |
| msg->Append("%s,%s,%d,", |
| kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT], |
| kLogEventsNames[tag], code->kind()); |
| msg->AppendAddress(code->address()); |
| msg->Append(",%d,", code->ExecutableSize()); |
| } |
| |
| void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, |
| AbstractCode* code, const char* comment) { |
| if (!is_logging_code_events()) return; |
| if (!FLAG_log_code || !log_->IsEnabled()) return; |
| Log::MessageBuilder msg(log_); |
| AppendCodeCreateHeader(&msg, tag, code); |
| msg.AppendDoubleQuotedString(comment); |
| msg.WriteToLogFile(); |
| } |
| |
| void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, |
| AbstractCode* code, Name* name) { |
| if (!is_logging_code_events()) return; |
| if (!FLAG_log_code || !log_->IsEnabled()) return; |
| Log::MessageBuilder msg(log_); |
| AppendCodeCreateHeader(&msg, tag, code); |
| if (name->IsString()) { |
| msg.Append('"'); |
| msg.AppendDetailed(String::cast(name), false); |
| msg.Append('"'); |
| } else { |
| msg.AppendSymbolName(Symbol::cast(name)); |
| } |
| msg.WriteToLogFile(); |
| } |
| |
| void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, |
| AbstractCode* code, SharedFunctionInfo* shared, |
| Name* name) { |
| if (!is_logging_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); |
| if (name->IsString()) { |
| std::unique_ptr<char[]> str = |
| String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
| msg.Append("\"%s\"", str.get()); |
| } else { |
| msg.AppendSymbolName(Symbol::cast(name)); |
| } |
| msg.Append(','); |
| msg.AppendAddress(shared->address()); |
| msg.Append(",%s", ComputeMarker(shared, 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_logging_code_events()) return; |
| if (!FLAG_log_code || !log_->IsEnabled()) return; |
| Log::MessageBuilder msg(log_); |
| AppendCodeCreateHeader(&msg, tag, code); |
| std::unique_ptr<char[]> name = |
| shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
| msg.Append("\"%s ", name.get()); |
| if (source->IsString()) { |
| std::unique_ptr<char[]> sourcestr = String::cast(source)->ToCString( |
| DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
| msg.Append("%s", sourcestr.get()); |
| } else { |
| msg.AppendSymbolName(Symbol::cast(source)); |
| } |
| msg.Append(":%d:%d\",", line, column); |
| msg.AppendAddress(shared->address()); |
| msg.Append(",%s", ComputeMarker(shared, code)); |
| msg.WriteToLogFile(); |
| } |
| |
| void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, |
| AbstractCode* code, int args_count) { |
| if (!is_logging_code_events()) return; |
| if (!FLAG_log_code || !log_->IsEnabled()) return; |
| Log::MessageBuilder msg(log_); |
| AppendCodeCreateHeader(&msg, tag, code); |
| msg.Append("\"args_count: %d\"", args_count); |
| msg.WriteToLogFile(); |
| } |
| |
| void Logger::CodeDisableOptEvent(AbstractCode* code, |
| SharedFunctionInfo* shared) { |
| if (!is_logging_code_events()) return; |
| if (!FLAG_log_code || !log_->IsEnabled()) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("%s,", kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT]); |
| std::unique_ptr<char[]> name = |
| shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
| msg.Append("\"%s\",", name.get()); |
| msg.Append("\"%s\"", GetBailoutReason(shared->disable_optimization_reason())); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::CodeMovingGCEvent() { |
| if (!is_logging_code_events()) return; |
| if (!log_->IsEnabled() || !FLAG_ll_prof) return; |
| base::OS::SignalCodeMovingGC(); |
| } |
| |
| void Logger::RegExpCodeCreateEvent(AbstractCode* code, String* source) { |
| if (!is_logging_code_events()) return; |
| if (!FLAG_log_code || !log_->IsEnabled()) return; |
| Log::MessageBuilder msg(log_); |
| AppendCodeCreateHeader(&msg, CodeEventListener::REG_EXP_TAG, code); |
| msg.Append('"'); |
| msg.AppendDetailed(source, false); |
| msg.Append('"'); |
| msg.WriteToLogFile(); |
| } |
| |
| void Logger::CodeMoveEvent(AbstractCode* from, Address to) { |
| if (!is_logging_code_events()) return; |
| MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from->address(), to); |
| } |
| |
| void Logger::CodeLinePosInfoRecordEvent(AbstractCode* code, |
| ByteArray* source_position_table) { |
| if (jit_logger_) { |
| void* jit_handler_data = jit_logger_->StartCodePosInfoEvent(); |
| for (SourcePositionTableIterator iter(source_position_table); !iter.done(); |
| iter.Advance()) { |
| if (iter.is_statement()) { |
| jit_logger_->AddCodeLinePosInfoEvent( |
| jit_handler_data, iter.code_offset(), |
| iter.source_position().ScriptOffset(), |
| JitCodeEvent::STATEMENT_POSITION); |
| } |
| jit_logger_->AddCodeLinePosInfoEvent( |
| jit_handler_data, iter.code_offset(), |
| iter.source_position().ScriptOffset(), JitCodeEvent::POSITION); |
| } |
| jit_logger_->EndCodePosInfoEvent(code, jit_handler_data); |
| } |
| } |
| |
| void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) { |
| if (code_name == NULL) return; // Not a code object. |
| Log::MessageBuilder msg(log_); |
| msg.Append("%s,%d,", |
| kLogEventsNames[CodeEventListener::SNAPSHOT_CODE_NAME_EVENT], pos); |
| msg.AppendDoubleQuotedString(code_name); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) { |
| if (!is_logging_code_events()) return; |
| MoveEventInternal(CodeEventListener::SHARED_FUNC_MOVE_EVENT, from, to); |
| } |
| |
| void Logger::MoveEventInternal(CodeEventListener::LogEventsAndTags event, |
| Address from, Address to) { |
| if (!FLAG_log_code || !log_->IsEnabled()) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("%s,", kLogEventsNames[event]); |
| msg.AppendAddress(from); |
| msg.Append(','); |
| msg.AppendAddress(to); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::ResourceEvent(const char* name, const char* tag) { |
| if (!log_->IsEnabled() || !FLAG_log) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("%s,%s,", name, tag); |
| |
| uint32_t sec, usec; |
| if (base::OS::GetUserTime(&sec, &usec) != -1) { |
| msg.Append("%d,%d,", sec, usec); |
| } |
| msg.Append("%.0f", base::OS::TimeCurrentMillis()); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::SuspectReadEvent(Name* name, Object* obj) { |
| if (!log_->IsEnabled() || !FLAG_log_suspect) return; |
| Log::MessageBuilder msg(log_); |
| String* class_name = obj->IsJSObject() |
| ? JSObject::cast(obj)->class_name() |
| : isolate_->heap()->empty_string(); |
| msg.Append("suspect-read,"); |
| msg.Append(class_name); |
| msg.Append(','); |
| if (name->IsString()) { |
| msg.Append('"'); |
| msg.Append(String::cast(name)); |
| msg.Append('"'); |
| } else { |
| msg.AppendSymbolName(Symbol::cast(name)); |
| } |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::HeapSampleBeginEvent(const char* space, const char* kind) { |
| if (!log_->IsEnabled() || !FLAG_log_gc) return; |
| Log::MessageBuilder msg(log_); |
| // Using non-relative system time in order to be able to synchronize with |
| // external memory profiling events (e.g. DOM memory size). |
| msg.Append("heap-sample-begin,\"%s\",\"%s\",%.0f", space, kind, |
| base::OS::TimeCurrentMillis()); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::HeapSampleEndEvent(const char* space, const char* kind) { |
| if (!log_->IsEnabled() || !FLAG_log_gc) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("heap-sample-end,\"%s\",\"%s\"", space, kind); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::HeapSampleItemEvent(const char* type, int number, int bytes) { |
| if (!log_->IsEnabled() || !FLAG_log_gc) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("heap-sample-item,%s,%d,%d", type, number, bytes); |
| msg.WriteToLogFile(); |
| } |
| |
| |
| void Logger::RuntimeCallTimerEvent() { |
| RuntimeCallStats* stats = isolate_->counters()->runtime_call_stats(); |
| RuntimeCallTimer* timer = stats->current_timer(); |
| if (timer == nullptr) return; |
| RuntimeCallCounter* counter = timer->counter(); |
| if (counter == nullptr) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("active-runtime-timer,"); |
| msg.AppendDoubleQuotedString(counter->name()); |
| msg.WriteToLogFile(); |
| } |
| |
| void Logger::TickEvent(v8::TickSample* sample, bool overflow) { |
| if (!log_->IsEnabled() || !FLAG_prof_cpp) return; |
| if (V8_UNLIKELY(FLAG_runtime_stats == |
| v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE)) { |
| RuntimeCallTimerEvent(); |
| } |
| Log::MessageBuilder msg(log_); |
| msg.Append("%s,", kLogEventsNames[CodeEventListener::TICK_EVENT]); |
| msg.AppendAddress(reinterpret_cast<Address>(sample->pc)); |
| msg.Append(",%d", static_cast<int>(timer_.Elapsed().InMicroseconds())); |
| if (sample->has_external_callback) { |
| msg.Append(",1,"); |
| msg.AppendAddress( |
| reinterpret_cast<Address>(sample->external_callback_entry)); |
| } else { |
| msg.Append(",0,"); |
| msg.AppendAddress(reinterpret_cast<Address>(sample->tos)); |
| } |
| msg.Append(",%d", static_cast<int>(sample->state)); |
| if (overflow) { |
| msg.Append(",overflow"); |
| } |
| for (unsigned i = 0; i < sample->frames_count; ++i) { |
| msg.Append(','); |
| msg.AppendAddress(reinterpret_cast<Address>(sample->stack[i])); |
| } |
| msg.WriteToLogFile(); |
| } |
| |
| void Logger::ICEvent(const char* type, bool keyed, const Address pc, int line, |
| int column, Map* map, Object* key, char old_state, |
| char new_state, const char* modifier, |
| const char* slow_stub_reason) { |
| if (!log_->IsEnabled() || !FLAG_trace_ic) return; |
| Log::MessageBuilder msg(log_); |
| if (keyed) msg.Append("Keyed"); |
| msg.Append("%s,", type); |
| msg.AppendAddress(pc); |
| msg.Append(",%d,%d,", line, column); |
| msg.Append(old_state); |
| msg.Append(","); |
| msg.Append(new_state); |
| msg.Append(","); |
| msg.AppendAddress(reinterpret_cast<Address>(map)); |
| msg.Append(","); |
| if (key->IsSmi()) { |
| msg.Append("%d", Smi::cast(key)->value()); |
| } else if (key->IsNumber()) { |
| msg.Append("%lf", key->Number()); |
| } else if (key->IsString()) { |
| msg.AppendDetailed(String::cast(key), false); |
| } else if (key->IsSymbol()) { |
| msg.AppendSymbolName(Symbol::cast(key)); |
| } |
| msg.Append(",%s,", modifier); |
| if (slow_stub_reason != nullptr) { |
| msg.AppendDoubleQuotedString(slow_stub_reason); |
| } |
| msg.WriteToLogFile(); |
| } |
| |
| void Logger::CompareIC(const Address pc, int line, int column, Code* stub, |
| const char* op, const char* old_left, |
| const char* old_right, const char* old_state, |
| const char* new_left, const char* new_right, |
| const char* new_state) { |
| if (!log_->IsEnabled() || !FLAG_trace_ic) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("CompareIC,"); |
| msg.AppendAddress(pc); |
| msg.Append(",%d,%d,", line, column); |
| msg.AppendAddress(reinterpret_cast<Address>(stub)); |
| msg.Append(",%s,%s,%s,%s,%s,%s,%s", op, old_left, old_right, old_state, |
| new_left, new_right, new_state); |
| msg.WriteToLogFile(); |
| } |
| |
| void Logger::BinaryOpIC(const Address pc, int line, int column, Code* stub, |
| const char* old_state, const char* new_state, |
| AllocationSite* allocation_site) { |
| if (!log_->IsEnabled() || !FLAG_trace_ic) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("BinaryOpIC,"); |
| msg.AppendAddress(pc); |
| msg.Append(",%d,%d,", line, column); |
| msg.AppendAddress(reinterpret_cast<Address>(stub)); |
| msg.Append(",%s,%s,", old_state, new_state); |
| if (allocation_site != nullptr) { |
| msg.AppendAddress(reinterpret_cast<Address>(allocation_site)); |
| } |
| msg.WriteToLogFile(); |
| } |
| |
| void Logger::ToBooleanIC(const Address pc, int line, int column, Code* stub, |
| const char* old_state, const char* new_state) { |
| if (!log_->IsEnabled() || !FLAG_trace_ic) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("ToBooleanIC,"); |
| msg.AppendAddress(pc); |
| msg.Append(",%d,%d,", line, column); |
| msg.AppendAddress(reinterpret_cast<Address>(stub)); |
| msg.Append(",%s,%s,", old_state, new_state); |
| msg.WriteToLogFile(); |
| } |
| |
| void Logger::PatchIC(const Address pc, const Address test, int delta) { |
| if (!log_->IsEnabled() || !FLAG_trace_ic) return; |
| Log::MessageBuilder msg(log_); |
| msg.Append("PatchIC,"); |
| msg.AppendAddress(pc); |
| msg.Append(","); |
| msg.AppendAddress(test); |
| msg.Append(","); |
| msg.Append("%d,", delta); |
| msg.WriteToLogFile(); |
| } |
| |
| void Logger::StopProfiler() { |
| if (!log_->IsEnabled()) return; |
| if (profiler_ != NULL) { |
| profiler_->pause(); |
| is_logging_ = false; |
| removeCodeEventListener(this); |
| } |
| } |
| |
| |
| // This function can be called when Log's mutex is acquired, |
| // either from main or Profiler's thread. |
| void Logger::LogFailure() { |
| StopProfiler(); |
| } |
| |
| static void AddFunctionAndCode(SharedFunctionInfo* sfi, |
| AbstractCode* code_object, |
| Handle<SharedFunctionInfo>* sfis, |
| Handle<AbstractCode>* code_objects, int offset) { |
| if (sfis != NULL) { |
| sfis[offset] = Handle<SharedFunctionInfo>(sfi); |
| } |
| if (code_objects != NULL) { |
| code_objects[offset] = Handle<AbstractCode>(code_object); |
| } |
| } |
| |
| class EnumerateOptimizedFunctionsVisitor: public OptimizedFunctionVisitor { |
| public: |
| EnumerateOptimizedFunctionsVisitor(Handle<SharedFunctionInfo>* sfis, |
| Handle<AbstractCode>* code_objects, |
| int* count) |
| : sfis_(sfis), code_objects_(code_objects), count_(count) {} |
| |
| virtual void EnterContext(Context* context) {} |
| virtual void LeaveContext(Context* context) {} |
| |
| virtual void VisitFunction(JSFunction* function) { |
| SharedFunctionInfo* sfi = SharedFunctionInfo::cast(function->shared()); |
| Object* maybe_script = sfi->script(); |
| if (maybe_script->IsScript() |
| && !Script::cast(maybe_script)->HasValidSource()) return; |
| |
| DCHECK(function->abstract_code()->kind() == |
| AbstractCode::OPTIMIZED_FUNCTION); |
| AddFunctionAndCode(sfi, function->abstract_code(), sfis_, code_objects_, |
| *count_); |
| *count_ = *count_ + 1; |
| } |
| |
| private: |
| Handle<SharedFunctionInfo>* sfis_; |
| Handle<AbstractCode>* code_objects_; |
| int* count_; |
| }; |
| |
| static int EnumerateCompiledFunctions(Heap* heap, |
| Handle<SharedFunctionInfo>* sfis, |
| Handle<AbstractCode>* code_objects) { |
| HeapIterator iterator(heap); |
| DisallowHeapAllocation no_gc; |
| int compiled_funcs_count = 0; |
| |
| // Iterate the heap to find shared function info objects and record |
| // the unoptimized code for them. |
| for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) { |
| if (!obj->IsSharedFunctionInfo()) continue; |
| SharedFunctionInfo* sfi = SharedFunctionInfo::cast(obj); |
| if (sfi->is_compiled() |
| && (!sfi->script()->IsScript() |
| || Script::cast(sfi->script())->HasValidSource())) { |
| // In some cases, an SFI might have (and have executing!) both bytecode |
| // and baseline code, so check for both and add them both if needed. |
| if (sfi->HasBytecodeArray()) { |
| AddFunctionAndCode(sfi, AbstractCode::cast(sfi->bytecode_array()), sfis, |
| code_objects, compiled_funcs_count); |
| ++compiled_funcs_count; |
| } |
| |
| if (!sfi->IsInterpreted()) { |
| AddFunctionAndCode(sfi, AbstractCode::cast(sfi->code()), sfis, |
| code_objects, compiled_funcs_count); |
| ++compiled_funcs_count; |
| } |
| } |
| } |
| |
| // Iterate all optimized functions in all contexts. |
| EnumerateOptimizedFunctionsVisitor visitor(sfis, |
| code_objects, |
| &compiled_funcs_count); |
| Deoptimizer::VisitAllOptimizedFunctions(heap->isolate(), &visitor); |
| |
| return compiled_funcs_count; |
| } |
| |
| |
| void Logger::LogCodeObject(Object* object) { |
| AbstractCode* code_object = AbstractCode::cast(object); |
| CodeEventListener::LogEventsAndTags tag = CodeEventListener::STUB_TAG; |
| const char* description = "Unknown code from the snapshot"; |
| switch (code_object->kind()) { |
| case AbstractCode::FUNCTION: |
| case AbstractCode::INTERPRETED_FUNCTION: |
| case AbstractCode::OPTIMIZED_FUNCTION: |
| return; // We log this later using LogCompiledFunctions. |
| case AbstractCode::BYTECODE_HANDLER: |
| return; // We log it later by walking the dispatch table. |
| case AbstractCode::BINARY_OP_IC: // fall through |
| case AbstractCode::COMPARE_IC: // fall through |
| case AbstractCode::TO_BOOLEAN_IC: // fall through |
| |
| case AbstractCode::STUB: |
| description = |
| CodeStub::MajorName(CodeStub::GetMajorKey(code_object->GetCode())); |
| if (description == NULL) |
| description = "A stub from the snapshot"; |
| tag = CodeEventListener::STUB_TAG; |
| break; |
| case AbstractCode::REGEXP: |
| description = "Regular expression code"; |
| tag = CodeEventListener::REG_EXP_TAG; |
| break; |
| case AbstractCode::BUILTIN: |
| description = |
| isolate_->builtins()->name(code_object->GetCode()->builtin_index()); |
| tag = CodeEventListener::BUILTIN_TAG; |
| break; |
| case AbstractCode::HANDLER: |
| description = "An IC handler from the snapshot"; |
| tag = CodeEventListener::HANDLER_TAG; |
| break; |
| case AbstractCode::KEYED_LOAD_IC: |
| description = "A keyed load IC from the snapshot"; |
| tag = CodeEventListener::KEYED_LOAD_IC_TAG; |
| break; |
| case AbstractCode::LOAD_IC: |
| description = "A load IC from the snapshot"; |
| tag = CodeEventListener::LOAD_IC_TAG; |
| break; |
| case AbstractCode::LOAD_GLOBAL_IC: |
| description = "A load global IC from the snapshot"; |
| tag = Logger::LOAD_GLOBAL_IC_TAG; |
| break; |
| case AbstractCode::STORE_IC: |
| description = "A store IC from the snapshot"; |
| tag = CodeEventListener::STORE_IC_TAG; |
| break; |
| case AbstractCode::KEYED_STORE_IC: |
| description = "A keyed store IC from the snapshot"; |
| tag = CodeEventListener::KEYED_STORE_IC_TAG; |
| break; |
| case AbstractCode::WASM_FUNCTION: |
| description = "A Wasm function"; |
| tag = CodeEventListener::STUB_TAG; |
| break; |
| case AbstractCode::JS_TO_WASM_FUNCTION: |
| description = "A JavaScript to Wasm adapter"; |
| tag = CodeEventListener::STUB_TAG; |
| break; |
| case AbstractCode::WASM_TO_JS_FUNCTION: |
| description = "A Wasm to JavaScript adapter"; |
| tag = CodeEventListener::STUB_TAG; |
| break; |
| case AbstractCode::WASM_INTERPRETER_ENTRY: |
| description = "A Wasm to Interpreter adapter"; |
| tag = CodeEventListener::STUB_TAG; |
| break; |
| case AbstractCode::NUMBER_OF_KINDS: |
| UNIMPLEMENTED(); |
| } |
| PROFILE(isolate_, CodeCreateEvent(tag, code_object, description)); |
| } |
| |
| |
| void Logger::LogCodeObjects() { |
| Heap* heap = isolate_->heap(); |
| HeapIterator iterator(heap); |
| DisallowHeapAllocation no_gc; |
| for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) { |
| if (obj->IsCode()) LogCodeObject(obj); |
| if (obj->IsBytecodeArray()) LogCodeObject(obj); |
| } |
| } |
| |
| void Logger::LogBytecodeHandlers() { |
| const interpreter::OperandScale kOperandScales[] = { |
| #define VALUE(Name, _) interpreter::OperandScale::k##Name, |
| OPERAND_SCALE_LIST(VALUE) |
| #undef VALUE |
| }; |
| |
| const int last_index = static_cast<int>(interpreter::Bytecode::kLast); |
| interpreter::Interpreter* interpreter = isolate_->interpreter(); |
| for (auto operand_scale : kOperandScales) { |
| for (int index = 0; index <= last_index; ++index) { |
| interpreter::Bytecode bytecode = interpreter::Bytecodes::FromByte(index); |
| if (interpreter::Bytecodes::BytecodeHasHandler(bytecode, operand_scale)) { |
| Code* code = interpreter->GetBytecodeHandler(bytecode, operand_scale); |
| std::string bytecode_name = |
| interpreter::Bytecodes::ToString(bytecode, operand_scale); |
| PROFILE(isolate_, CodeCreateEvent( |
| CodeEventListener::BYTECODE_HANDLER_TAG, |
| AbstractCode::cast(code), bytecode_name.c_str())); |
| } |
| } |
| } |
| } |
| |
| void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared, |
| Handle<AbstractCode> code) { |
| if (shared->script()->IsScript()) { |
| Handle<Script> script(Script::cast(shared->script())); |
| int line_num = Script::GetLineNumber(script, shared->start_position()) + 1; |
| int column_num = |
| Script::GetColumnNumber(script, shared->start_position()) + 1; |
| if (script->name()->IsString()) { |
| Handle<String> script_name(String::cast(script->name())); |
| if (line_num > 0) { |
| PROFILE(isolate_, |
| CodeCreateEvent( |
| Logger::ToNativeByScript( |
| CodeEventListener::LAZY_COMPILE_TAG, *script), |
| *code, *shared, *script_name, line_num, column_num)); |
| } else { |
| // Can't distinguish eval and script here, so always use Script. |
| PROFILE(isolate_, |
| CodeCreateEvent(Logger::ToNativeByScript( |
| CodeEventListener::SCRIPT_TAG, *script), |
| *code, *shared, *script_name)); |
| } |
| } else { |
| PROFILE(isolate_, |
| CodeCreateEvent(Logger::ToNativeByScript( |
| CodeEventListener::LAZY_COMPILE_TAG, *script), |
| *code, *shared, isolate_->heap()->empty_string(), |
| line_num, column_num)); |
| } |
| } else if (shared->IsApiFunction()) { |
| // API function. |
| FunctionTemplateInfo* fun_data = shared->get_api_func_data(); |
| Object* raw_call_data = fun_data->call_code(); |
| if (!raw_call_data->IsUndefined(isolate_)) { |
| CallHandlerInfo* call_data = CallHandlerInfo::cast(raw_call_data); |
| Object* callback_obj = call_data->callback(); |
| Address entry_point = v8::ToCData<Address>(callback_obj); |
| #if USES_FUNCTION_DESCRIPTORS |
| entry_point = *FUNCTION_ENTRYPOINT_ADDRESS(entry_point); |
| #endif |
| PROFILE(isolate_, CallbackEvent(shared->DebugName(), entry_point)); |
| } |
| } else { |
| PROFILE(isolate_, |
| CodeCreateEvent(CodeEventListener::LAZY_COMPILE_TAG, *code, *shared, |
| isolate_->heap()->empty_string())); |
| } |
| } |
| |
| |
| void Logger::LogCompiledFunctions() { |
| Heap* heap = isolate_->heap(); |
| HandleScope scope(isolate_); |
| const int compiled_funcs_count = EnumerateCompiledFunctions(heap, NULL, NULL); |
| ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count); |
| ScopedVector<Handle<AbstractCode> > code_objects(compiled_funcs_count); |
| EnumerateCompiledFunctions(heap, sfis.start(), code_objects.start()); |
| |
| // During iteration, there can be heap allocation due to |
| // GetScriptLineNumber call. |
| for (int i = 0; i < compiled_funcs_count; ++i) { |
| if (code_objects[i].is_identical_to(isolate_->builtins()->CompileLazy())) |
| continue; |
| LogExistingFunction(sfis[i], code_objects[i]); |
| } |
| } |
| |
| |
| void Logger::LogAccessorCallbacks() { |
| Heap* heap = isolate_->heap(); |
| HeapIterator iterator(heap); |
| DisallowHeapAllocation no_gc; |
| for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) { |
| if (!obj->IsAccessorInfo()) continue; |
| AccessorInfo* ai = AccessorInfo::cast(obj); |
| if (!ai->name()->IsName()) continue; |
| Address getter_entry = v8::ToCData<Address>(ai->getter()); |
| Name* name = Name::cast(ai->name()); |
| if (getter_entry != 0) { |
| #if USES_FUNCTION_DESCRIPTORS |
| getter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(getter_entry); |
| #endif |
| PROFILE(isolate_, GetterCallbackEvent(name, getter_entry)); |
| } |
| Address setter_entry = v8::ToCData<Address>(ai->setter()); |
| if (setter_entry != 0) { |
| #if USES_FUNCTION_DESCRIPTORS |
| setter_entry = *FUNCTION_ENTRYPOINT_ADDRESS(setter_entry); |
| #endif |
| PROFILE(isolate_, SetterCallbackEvent(name, setter_entry)); |
| } |
| } |
| } |
| |
| |
| static void AddIsolateIdIfNeeded(std::ostream& os, // NOLINT |
| Isolate* isolate) { |
| if (FLAG_logfile_per_isolate) os << "isolate-" << isolate << "-"; |
| } |
| |
| |
| static void PrepareLogFileName(std::ostream& os, // NOLINT |
| Isolate* isolate, const char* file_name) { |
| int dir_separator_count = 0; |
| for (const char* p = file_name; *p; p++) { |
| if (base::OS::isDirectorySeparator(*p)) dir_separator_count++; |
| } |
| |
| for (const char* p = file_name; *p; p++) { |
| if (dir_separator_count == 0) { |
| AddIsolateIdIfNeeded(os, isolate); |
| dir_separator_count--; |
| } |
| if (*p == '%') { |
| p++; |
| switch (*p) { |
| case '\0': |
| // If there's a % at the end of the string we back up |
| // one character so we can escape the loop properly. |
| p--; |
| break; |
| case 'p': |
| os << base::OS::GetCurrentProcessId(); |
| break; |
| case 't': |
| // %t expands to the current time in milliseconds. |
| os << static_cast<int64_t>(base::OS::TimeCurrentMillis()); |
| break; |
| case '%': |
| // %% expands (contracts really) to %. |
| os << '%'; |
| break; |
| default: |
| // All other %'s expand to themselves. |
| os << '%' << *p; |
| break; |
| } |
| } else { |
| if (base::OS::isDirectorySeparator(*p)) dir_separator_count--; |
| os << *p; |
| } |
| } |
| } |
| |
| |
| bool Logger::SetUp(Isolate* isolate) { |
| // Tests and EnsureInitialize() can call this twice in a row. It's harmless. |
| if (is_initialized_) return true; |
| is_initialized_ = true; |
| |
| std::ostringstream log_file_name; |
| PrepareLogFileName(log_file_name, isolate, FLAG_logfile); |
| log_->Initialize(log_file_name.str().c_str()); |
| |
| if (FLAG_perf_basic_prof) { |
| perf_basic_logger_ = new PerfBasicLogger(); |
| addCodeEventListener(perf_basic_logger_); |
| } |
| |
| if (FLAG_perf_prof) { |
| perf_jit_logger_ = new PerfJitLogger(); |
| addCodeEventListener(perf_jit_logger_); |
| } |
| |
| if (FLAG_ll_prof) { |
| ll_logger_ = new LowLevelLogger(log_file_name.str().c_str()); |
| addCodeEventListener(ll_logger_); |
| } |
| |
| ticker_ = new Ticker(isolate, kSamplingIntervalMs); |
| |
| if (Log::InitLogAtStart()) { |
| is_logging_ = true; |
| } |
| |
| if (FLAG_log_internal_timer_events || FLAG_prof_cpp) timer_.Start(); |
| |
| if (FLAG_prof_cpp) { |
| profiler_ = new Profiler(isolate); |
| is_logging_ = true; |
| profiler_->Engage(); |
| } |
| |
| profiler_listener_.reset(); |
| |
| if (is_logging_) { |
| addCodeEventListener(this); |
| } |
| |
| return true; |
| } |
| |
| |
| void Logger::SetCodeEventHandler(uint32_t options, |
| JitCodeEventHandler event_handler) { |
| if (jit_logger_) { |
| removeCodeEventListener(jit_logger_); |
| delete jit_logger_; |
| jit_logger_ = NULL; |
| } |
| |
| if (event_handler) { |
| jit_logger_ = new JitLogger(event_handler); |
| addCodeEventListener(jit_logger_); |
| if (options & kJitCodeEventEnumExisting) { |
| HandleScope scope(isolate_); |
| LogCodeObjects(); |
| LogCompiledFunctions(); |
| } |
| } |
| } |
| |
| void Logger::SetUpProfilerListener() { |
| if (!is_initialized_) return; |
| if (profiler_listener_.get() == nullptr) { |
| profiler_listener_.reset(new ProfilerListener(isolate_)); |
| } |
| addCodeEventListener(profiler_listener_.get()); |
| } |
| |
| void Logger::TearDownProfilerListener() { |
| if (profiler_listener_->HasObservers()) return; |
| removeCodeEventListener(profiler_listener_.get()); |
| } |
| |
| sampler::Sampler* Logger::sampler() { |
| return ticker_; |
| } |
| |
| |
| FILE* Logger::TearDown() { |
| if (!is_initialized_) return NULL; |
| is_initialized_ = false; |
| |
| // Stop the profiler before closing the file. |
| if (profiler_ != NULL) { |
| profiler_->Disengage(); |
| delete profiler_; |
| profiler_ = NULL; |
| } |
| |
| 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_; |
| ll_logger_ = NULL; |
| } |
| |
| if (jit_logger_) { |
| removeCodeEventListener(jit_logger_); |
| delete jit_logger_; |
| jit_logger_ = NULL; |
| } |
| |
| if (profiler_listener_.get() != nullptr) { |
| removeCodeEventListener(profiler_listener_.get()); |
| } |
| |
| return log_->Close(); |
| } |
| |
| } // namespace internal |
| } // namespace v8 |