diff options
Diffstat (limited to 'deps/v8/src/log.cc')
| -rw-r--r-- | deps/v8/src/log.cc | 487 |
1 files changed, 241 insertions, 246 deletions
diff --git a/deps/v8/src/log.cc b/deps/v8/src/log.cc index da38d3e7f3..fc7fcb9ced 100644 --- a/deps/v8/src/log.cc +++ b/deps/v8/src/log.cc @@ -5,49 +5,38 @@ #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/cpu-profiler.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/vm-state-inl.h" namespace v8 { namespace internal { - #define DECLARE_EVENT(ignore1, name) name, -static const char* const kLogEventsNames[Logger::NUMBER_OF_LOG_EVENTS] = { - LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT) -}; +static const char* kLogEventsNames[CodeEventListener::NUMBER_OF_LOG_EVENTS] = { + LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)}; #undef DECLARE_EVENT - -#define CALL_LISTENERS(Call) \ -for (int i = 0; i < listeners_.length(); ++i) { \ - listeners_[i]->Call; \ -} - -#define PROFILER_LOG(Call) \ - do { \ - CpuProfiler* cpu_profiler = isolate_->cpu_profiler(); \ - if (cpu_profiler->is_profiling()) { \ - cpu_profiler->Call; \ - } \ - } while (false); - static const char* ComputeMarker(SharedFunctionInfo* shared, AbstractCode* code) { switch (code->kind()) { @@ -70,7 +59,7 @@ class CodeEventLogger::NameBuffer { utf8_pos_ = 0; } - void Init(Logger::LogEventsAndTags tag) { + void Init(CodeEventListener::LogEventsAndTags tag) { Reset(); AppendBytes(kLogEventsNames[tag]); AppendByte(':'); @@ -82,7 +71,7 @@ class CodeEventLogger::NameBuffer { } else { Symbol* symbol = Symbol::cast(name); AppendBytes("symbol("); - if (!symbol->name()->IsUndefined()) { + if (!symbol->name()->IsUndefined(symbol->GetIsolate())) { AppendBytes("\""); AppendString(String::cast(symbol->name())); AppendBytes("\" "); @@ -164,34 +153,32 @@ CodeEventLogger::CodeEventLogger() : name_buffer_(new NameBuffer) { } CodeEventLogger::~CodeEventLogger() { delete name_buffer_; } -void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, +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(Logger::LogEventsAndTags tag, +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(Logger::LogEventsAndTags tag, +void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, AbstractCode* code, - SharedFunctionInfo* shared, - CompilationInfo* info, Name* name) { + 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(Logger::LogEventsAndTags tag, +void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, AbstractCode* code, - SharedFunctionInfo* shared, - CompilationInfo* info, Name* source, + SharedFunctionInfo* shared, Name* source, int line, int column) { name_buffer_->Init(tag); name_buffer_->AppendBytes(ComputeMarker(shared, code)); @@ -209,7 +196,7 @@ void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size()); } -void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, +void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, AbstractCode* code, int args_count) { name_buffer_->Init(tag); name_buffer_->AppendInt(args_count); @@ -218,7 +205,7 @@ void CodeEventLogger::CodeCreateEvent(Logger::LogEventsAndTags tag, void CodeEventLogger::RegExpCodeCreateEvent(AbstractCode* code, String* source) { - name_buffer_->Init(Logger::REG_EXP_TAG); + name_buffer_->Init(CodeEventListener::REG_EXP_TAG); name_buffer_->AppendString(source); LogRecordedBuffer(code, NULL, name_buffer_->get(), name_buffer_->size()); } @@ -280,12 +267,17 @@ void PerfBasicLogger::LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo*, return; } - base::OS::FPrint(perf_output_handle_, "%llx %x %.*s\n", - reinterpret_cast<uint64_t>(code->instruction_start()), + // 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; @@ -424,10 +416,6 @@ void LowLevelLogger::CodeMovingGCEvent() { LogWriteBytes(&tag, sizeof(tag)); } - -#define JIT_LOG(Call) if (jit_logger_) jit_logger_->Call; - - class JitLogger : public CodeEventLogger { public: explicit JitLogger(JitCodeEventHandler code_event_handler); @@ -528,6 +516,31 @@ void JitLogger::EndCodePosInfoEvent(AbstractCode* code, } +// 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. @@ -540,7 +553,7 @@ class Profiler: public base::Thread { void Disengage(); // Inserts collected profiling data into buffer. - void Insert(TickSample* sample) { + void Insert(v8::TickSample* sample) { if (paused_) return; @@ -561,7 +574,7 @@ class Profiler: public base::Thread { private: // Waits for a signal and removes profiling data. - bool Remove(TickSample* sample) { + bool Remove(v8::TickSample* sample) { buffer_semaphore_.Wait(); // Wait for an element. *sample = buffer_[base::NoBarrier_Load(&tail_)]; bool result = overflow_; @@ -578,7 +591,7 @@ class Profiler: public base::Thread { // Cyclic buffer for communicating profiling samples // between the signal handler and the worker thread. static const int kBufferSize = 128; - TickSample buffer_[kBufferSize]; // Buffer storage. + 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. @@ -600,33 +613,44 @@ class Profiler: public base::Thread { // Ticker used to provide ticks to the profiler and the sliding state // window. // -class Ticker: public Sampler { +class Ticker: public sampler::Sampler { public: - Ticker(Isolate* isolate, int interval): - Sampler(isolate, interval), - profiler_(NULL) {} - - ~Ticker() { if (IsActive()) Stop(); } + Ticker(Isolate* isolate, int interval) + : sampler::Sampler(reinterpret_cast<v8::Isolate*>(isolate)), + profiler_(nullptr), + sampling_thread_(new SamplingThread(this, interval)) {} - virtual void Tick(TickSample* sample) { - if (profiler_) profiler_->Insert(sample); + ~Ticker() { + if (IsActive()) Stop(); + delete sampling_thread_; } void SetProfiler(Profiler* profiler) { - DCHECK(profiler_ == NULL); + DCHECK(profiler_ == nullptr); profiler_ = profiler; IncreaseProfilingDepth(); if (!IsActive()) Start(); + sampling_thread_->StartSynchronously(); } void ClearProfiler() { - profiler_ = NULL; + 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_; }; @@ -653,8 +677,9 @@ void Profiler::Engage() { 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)); + LOG(isolate_, + SharedLibraryEvent(addresses[i].library_path, addresses[i].start, + addresses[i].end, addresses[i].aslr_slide)); } // Start thread processing the profiler buffer. @@ -679,7 +704,7 @@ void Profiler::Disengage() { // inserting a fake element in the queue and then wait for // the thread to terminate. base::NoBarrier_Store(&running_, 0); - TickSample sample; + v8::TickSample sample; // Reset 'paused_' flag, otherwise semaphore may not be signalled. resume(); Insert(&sample); @@ -690,7 +715,7 @@ void Profiler::Disengage() { void Profiler::Run() { - TickSample sample; + v8::TickSample sample; bool overflow = Remove(&sample); while (base::NoBarrier_Load(&running_)) { LOG(isolate_, TickEvent(&sample, overflow)); @@ -721,24 +746,16 @@ Logger::~Logger() { delete log_; } - void Logger::addCodeEventListener(CodeEventListener* listener) { - DCHECK(!hasCodeEventListener(listener)); - listeners_.Add(listener); + bool result = isolate_->code_event_dispatcher()->AddListener(listener); + USE(result); + DCHECK(result); } - void Logger::removeCodeEventListener(CodeEventListener* listener) { - DCHECK(hasCodeEventListener(listener)); - listeners_.RemoveElement(listener); + isolate_->code_event_dispatcher()->RemoveListener(listener); } - -bool Logger::hasCodeEventListener(CodeEventListener* listener) { - return listeners_.Contains(listener); -} - - void Logger::ProfilerBeginEvent() { if (!log_->IsEnabled()) return; Log::MessageBuilder msg(log_); @@ -781,7 +798,7 @@ void Logger::UncheckedIntEvent(const char* name, int value) { void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) { if (!log_->IsEnabled()) return; Log::MessageBuilder msg(log_); - msg.Append("%s,%" V8_PTR_PREFIX "d", name, value); + msg.Append("%s,%" V8PRIdPTR, name, value); msg.WriteToLogFile(); } @@ -789,7 +806,7 @@ void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) { void Logger::HandleEvent(const char* name, Object** location) { if (!log_->IsEnabled() || !FLAG_log_handles) return; Log::MessageBuilder msg(log_); - msg.Append("%s,0x%" V8PRIxPTR, name, location); + msg.Append("%s,%p", name, static_cast<void*>(location)); msg.WriteToLogFile(); } @@ -813,24 +830,23 @@ void Logger::ApiSecurityCheck() { ApiEvent("api,check-security"); } - void Logger::SharedLibraryEvent(const std::string& library_path, - uintptr_t start, - uintptr_t end) { + 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, - library_path.c_str(), start, end); + 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) { - PROFILER_LOG(CodeDeoptEvent(code, pc, 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,%ld,%d", since_epoch, code->CodeSize()); + msg.Append("code-deopt,%d,%d", since_epoch, code->CodeSize()); msg.WriteToLogFile(); } @@ -840,7 +856,7 @@ void Logger::CurrentTimeEvent() { 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,%ld", since_epoch); + msg.Append("current-time,%d", since_epoch); msg.WriteToLogFile(); } @@ -870,14 +886,6 @@ void Logger::LeaveExternal(Isolate* isolate) { isolate->set_current_vm_state(JS); } - -template <class TimerEvent> -void TimerEventScope<TimerEvent>::LogTimerEvent(Logger::StartEnd se) { - Logger::CallEventLogger(isolate_, TimerEvent::name(), se, - TimerEvent::expose_to_api()); -} - - // Instantiate template methods. #define V(TimerName, expose) \ template void TimerEventScope<TimerEvent##TimerName>::LogTimerEvent( \ @@ -914,19 +922,19 @@ void LogRegExpSource(Handle<JSRegExp> regexp, Isolate* isolate, // global flag Handle<Object> global = JSReceiver::GetProperty(isolate, regexp, "global").ToHandleChecked(); - if (global->IsTrue()) { + if (global->IsTrue(isolate)) { msg->Append('g'); } // ignorecase flag Handle<Object> ignorecase = JSReceiver::GetProperty(isolate, regexp, "ignoreCase").ToHandleChecked(); - if (ignorecase->IsTrue()) { + if (ignorecase->IsTrue(isolate)) { msg->Append('i'); } // multiline flag Handle<Object> multiline = JSReceiver::GetProperty(isolate, regexp, "multiline").ToHandleChecked(); - if (multiline->IsTrue()) { + if (multiline->IsTrue(isolate)) { msg->Append('m'); } } @@ -949,20 +957,20 @@ void Logger::ApiNamedPropertyAccess(const char* tag, DCHECK(name->IsName()); if (!log_->IsEnabled() || !FLAG_log_api) return; String* class_name_obj = holder->class_name(); - base::SmartArrayPointer<char> class_name = + std::unique_ptr<char[]> class_name = class_name_obj->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); if (name->IsString()) { - base::SmartArrayPointer<char> property_name = + 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()) { + if (symbol->name()->IsUndefined(symbol->GetIsolate())) { ApiEvent("api,%s,\"%s\",symbol(hash %x)", tag, class_name.get(), hash); } else { - base::SmartArrayPointer<char> str = + 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(), @@ -976,7 +984,7 @@ void Logger::ApiIndexedPropertyAccess(const char* tag, uint32_t index) { if (!log_->IsEnabled() || !FLAG_log_api) return; String* class_name_obj = holder->class_name(); - base::SmartArrayPointer<char> 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); } @@ -985,7 +993,7 @@ void Logger::ApiIndexedPropertyAccess(const char* tag, void Logger::ApiObjectAccess(const char* tag, JSObject* object) { if (!log_->IsEnabled() || !FLAG_log_api) return; String* class_name_obj = object->class_name(); - base::SmartArrayPointer<char> 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()); } @@ -1000,8 +1008,7 @@ void Logger::ApiEntryCall(const char* 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,0x%" V8PRIxPTR ",%u", name, object, - static_cast<unsigned int>(size)); + msg.Append("new,%s,%p,%u", name, object, static_cast<unsigned int>(size)); msg.WriteToLogFile(); } @@ -1009,7 +1016,7 @@ void Logger::NewEvent(const char* name, void* object, size_t size) { void Logger::DeleteEvent(const char* name, void* object) { if (!log_->IsEnabled() || !FLAG_log) return; Log::MessageBuilder msg(log_); - msg.Append("delete,%s,0x%" V8PRIxPTR, name, object); + msg.Append("delete,%s,%p", name, object); msg.WriteToLogFile(); } @@ -1019,22 +1026,22 @@ void Logger::CallbackEventInternal(const char* prefix, Name* name, if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); msg.Append("%s,%s,-2,", - kLogEventsNames[CODE_CREATION_EVENT], - kLogEventsNames[CALLBACK_TAG]); + kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT], + kLogEventsNames[CodeEventListener::CALLBACK_TAG]); msg.AppendAddress(entry_point); if (name->IsString()) { - base::SmartArrayPointer<char> str = + 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()) { - msg.Append(",1,symbol(hash %x)", prefix, symbol->Hash()); + if (symbol->name()->IsUndefined(symbol->GetIsolate())) { + msg.Append(",1,symbol(hash %x)", symbol->Hash()); } else { - base::SmartArrayPointer<char> str = + std::unique_ptr<char[]> str = String::cast(symbol->name()) ->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); - msg.Append(",1,symbol(\"%s\" hash %x)", prefix, str.get(), + msg.Append(",1,symbol(\"%s%s\" hash %x)", prefix, str.get(), symbol->Hash()); } } @@ -1043,41 +1050,33 @@ void Logger::CallbackEventInternal(const char* prefix, Name* name, void Logger::CallbackEvent(Name* name, Address entry_point) { - PROFILER_LOG(CallbackEvent(name, entry_point)); CallbackEventInternal("", name, entry_point); } void Logger::GetterCallbackEvent(Name* name, Address entry_point) { - PROFILER_LOG(GetterCallbackEvent(name, entry_point)); CallbackEventInternal("get ", name, entry_point); } void Logger::SetterCallbackEvent(Name* name, Address entry_point) { - PROFILER_LOG(SetterCallbackEvent(name, entry_point)); CallbackEventInternal("set ", name, entry_point); } static void AppendCodeCreateHeader(Log::MessageBuilder* msg, - Logger::LogEventsAndTags tag, + CodeEventListener::LogEventsAndTags tag, AbstractCode* code) { DCHECK(msg); msg->Append("%s,%s,%d,", - kLogEventsNames[Logger::CODE_CREATION_EVENT], - kLogEventsNames[tag], - code->kind()); + kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT], + kLogEventsNames[tag], code->kind()); msg->AppendAddress(code->address()); msg->Append(",%d,", code->ExecutableSize()); } -void Logger::CodeCreateEvent(LogEventsAndTags tag, AbstractCode* code, - const char* comment) { - PROFILER_LOG(CodeCreateEvent(tag, code, comment)); - +void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, + AbstractCode* code, const char* comment) { if (!is_logging_code_events()) return; - CALL_LISTENERS(CodeCreateEvent(tag, code, comment)); - if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); AppendCodeCreateHeader(&msg, tag, code); @@ -1085,13 +1084,9 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, AbstractCode* code, msg.WriteToLogFile(); } -void Logger::CodeCreateEvent(LogEventsAndTags tag, AbstractCode* code, - Name* name) { - PROFILER_LOG(CodeCreateEvent(tag, code, name)); - +void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, + AbstractCode* code, Name* name) { if (!is_logging_code_events()) return; - CALL_LISTENERS(CodeCreateEvent(tag, code, name)); - if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); AppendCodeCreateHeader(&msg, tag, code); @@ -1105,14 +1100,10 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, AbstractCode* code, msg.WriteToLogFile(); } -void Logger::CodeCreateEvent(LogEventsAndTags tag, AbstractCode* code, - SharedFunctionInfo* shared, CompilationInfo* info, +void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, + AbstractCode* code, SharedFunctionInfo* shared, Name* name) { - PROFILER_LOG(CodeCreateEvent(tag, code, shared, info, name)); - if (!is_logging_code_events()) return; - CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, name)); - if (!FLAG_log_code || !log_->IsEnabled()) return; if (code == AbstractCode::cast( isolate_->builtins()->builtin(Builtins::kCompileLazy))) { @@ -1122,7 +1113,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, AbstractCode* code, Log::MessageBuilder msg(log_); AppendCodeCreateHeader(&msg, tag, code); if (name->IsString()) { - base::SmartArrayPointer<char> str = + std::unique_ptr<char[]> str = String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); msg.Append("\"%s\"", str.get()); } else { @@ -1138,23 +1129,18 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, AbstractCode* code, // 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(LogEventsAndTags tag, AbstractCode* code, - SharedFunctionInfo* shared, CompilationInfo* info, +void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, + AbstractCode* code, SharedFunctionInfo* shared, Name* source, int line, int column) { - PROFILER_LOG(CodeCreateEvent(tag, code, shared, info, source, line, column)); - if (!is_logging_code_events()) return; - CALL_LISTENERS(CodeCreateEvent(tag, code, shared, info, source, line, - column)); - if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); AppendCodeCreateHeader(&msg, tag, code); - base::SmartArrayPointer<char> name = + std::unique_ptr<char[]> name = shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); msg.Append("\"%s ", name.get()); if (source->IsString()) { - base::SmartArrayPointer<char> sourcestr = String::cast(source)->ToCString( + std::unique_ptr<char[]> sourcestr = String::cast(source)->ToCString( DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); msg.Append("%s", sourcestr.get()); } else { @@ -1166,13 +1152,9 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, AbstractCode* code, msg.WriteToLogFile(); } -void Logger::CodeCreateEvent(LogEventsAndTags tag, AbstractCode* code, - int args_count) { - PROFILER_LOG(CodeCreateEvent(tag, code, args_count)); - +void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, + AbstractCode* code, int args_count) { if (!is_logging_code_events()) return; - CALL_LISTENERS(CodeCreateEvent(tag, code, args_count)); - if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); AppendCodeCreateHeader(&msg, tag, code); @@ -1182,15 +1164,11 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, AbstractCode* code, void Logger::CodeDisableOptEvent(AbstractCode* code, SharedFunctionInfo* shared) { - PROFILER_LOG(CodeDisableOptEvent(code, shared)); - if (!is_logging_code_events()) return; - CALL_LISTENERS(CodeDisableOptEvent(code, shared)); - if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); - msg.Append("%s,", kLogEventsNames[CODE_DISABLE_OPT_EVENT]); - base::SmartArrayPointer<char> name = + 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())); @@ -1199,23 +1177,16 @@ void Logger::CodeDisableOptEvent(AbstractCode* code, void Logger::CodeMovingGCEvent() { - PROFILER_LOG(CodeMovingGCEvent()); - if (!is_logging_code_events()) return; if (!log_->IsEnabled() || !FLAG_ll_prof) return; - CALL_LISTENERS(CodeMovingGCEvent()); base::OS::SignalCodeMovingGC(); } void Logger::RegExpCodeCreateEvent(AbstractCode* code, String* source) { - PROFILER_LOG(RegExpCodeCreateEvent(code, source)); - if (!is_logging_code_events()) return; - CALL_LISTENERS(RegExpCodeCreateEvent(code, source)); - if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); - AppendCodeCreateHeader(&msg, REG_EXP_TAG, code); + AppendCodeCreateHeader(&msg, CodeEventListener::REG_EXP_TAG, code); msg.Append('"'); msg.AppendDetailed(source, false); msg.Append('"'); @@ -1223,48 +1194,34 @@ void Logger::RegExpCodeCreateEvent(AbstractCode* code, String* source) { } void Logger::CodeMoveEvent(AbstractCode* from, Address to) { - PROFILER_LOG(CodeMoveEvent(from, to)); - if (!is_logging_code_events()) return; - CALL_LISTENERS(CodeMoveEvent(from, to)); - MoveEventInternal(CODE_MOVE_EVENT, from->address(), to); -} - -void Logger::CodeLinePosInfoAddPositionEvent(void* jit_handler_data, - int pc_offset, int position) { - JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data, - pc_offset, - position, - JitCodeEvent::POSITION)); + MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from->address(), to); } - -void Logger::CodeLinePosInfoAddStatementPositionEvent(void* jit_handler_data, - int pc_offset, - int position) { - JIT_LOG(AddCodeLinePosInfoEvent(jit_handler_data, - pc_offset, - position, - JitCodeEvent::STATEMENT_POSITION)); -} - - -void Logger::CodeStartLinePosInfoRecordEvent(PositionsRecorder* pos_recorder) { - if (jit_logger_ != NULL) { - pos_recorder->AttachJITHandlerData(jit_logger_->StartCodePosInfoEvent()); +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(), + JitCodeEvent::STATEMENT_POSITION); + } + jit_logger_->AddCodeLinePosInfoEvent(jit_handler_data, iter.code_offset(), + iter.source_position(), + JitCodeEvent::POSITION); + } + jit_logger_->EndCodePosInfoEvent(code, jit_handler_data); } } -void Logger::CodeEndLinePosInfoRecordEvent(AbstractCode* code, - void* jit_handler_data) { - JIT_LOG(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[SNAPSHOT_CODE_NAME_EVENT], pos); + msg.Append("%s,%d,", + kLogEventsNames[CodeEventListener::SNAPSHOT_CODE_NAME_EVENT], pos); msg.AppendDoubleQuotedString(code_name); msg.WriteToLogFile(); } @@ -1272,13 +1229,11 @@ void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) { void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) { if (!is_logging_code_events()) return; - MoveEventInternal(SHARED_FUNC_MOVE_EVENT, from, to); + MoveEventInternal(CodeEventListener::SHARED_FUNC_MOVE_EVENT, from, to); } - -void Logger::MoveEventInternal(LogEventsAndTags event, - Address from, - Address 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]); @@ -1372,19 +1327,34 @@ void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) { 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(TickSample* sample, bool overflow) { +void Logger::TickEvent(v8::TickSample* sample, bool overflow) { if (!log_->IsEnabled() || !FLAG_prof_cpp) return; + if (FLAG_runtime_call_stats) { + RuntimeCallTimerEvent(); + } Log::MessageBuilder msg(log_); - msg.Append("%s,", kLogEventsNames[TICK_EVENT]); - msg.AppendAddress(sample->pc); - msg.Append(",%ld", static_cast<int>(timer_.Elapsed().InMicroseconds())); + 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(sample->external_callback_entry); + msg.AppendAddress( + reinterpret_cast<Address>(sample->external_callback_entry)); } else { msg.Append(",0,"); - msg.AppendAddress(sample->tos); + msg.AppendAddress(reinterpret_cast<Address>(sample->tos)); } msg.Append(",%d", static_cast<int>(sample->state)); if (overflow) { @@ -1392,7 +1362,7 @@ void Logger::TickEvent(TickSample* sample, bool overflow) { } for (unsigned i = 0; i < sample->frames_count; ++i) { msg.Append(','); - msg.AppendAddress(sample->stack[i]); + msg.AppendAddress(reinterpret_cast<Address>(sample->stack[i])); } msg.WriteToLogFile(); } @@ -1403,6 +1373,7 @@ void Logger::StopProfiler() { if (profiler_ != NULL) { profiler_->pause(); is_logging_ = false; + removeCodeEventListener(this); } } @@ -1484,7 +1455,7 @@ static int EnumerateCompiledFunctions(Heap* heap, void Logger::LogCodeObject(Object* object) { AbstractCode* code_object = AbstractCode::cast(object); - LogEventsAndTags tag = Logger::STUB_TAG; + CodeEventListener::LogEventsAndTags tag = CodeEventListener::STUB_TAG; const char* description = "Unknown code from the snapshot"; switch (code_object->kind()) { case AbstractCode::FUNCTION: @@ -1502,53 +1473,59 @@ void Logger::LogCodeObject(Object* object) { CodeStub::MajorName(CodeStub::GetMajorKey(code_object->GetCode())); if (description == NULL) description = "A stub from the snapshot"; - tag = Logger::STUB_TAG; + tag = CodeEventListener::STUB_TAG; break; case AbstractCode::REGEXP: description = "Regular expression code"; - tag = Logger::REG_EXP_TAG; + tag = CodeEventListener::REG_EXP_TAG; break; case AbstractCode::BUILTIN: description = isolate_->builtins()->name(code_object->GetCode()->builtin_index()); - tag = Logger::BUILTIN_TAG; + tag = CodeEventListener::BUILTIN_TAG; break; case AbstractCode::HANDLER: description = "An IC handler from the snapshot"; - tag = Logger::HANDLER_TAG; + tag = CodeEventListener::HANDLER_TAG; break; case AbstractCode::KEYED_LOAD_IC: description = "A keyed load IC from the snapshot"; - tag = Logger::KEYED_LOAD_IC_TAG; + tag = CodeEventListener::KEYED_LOAD_IC_TAG; break; case AbstractCode::LOAD_IC: description = "A load IC from the snapshot"; - tag = Logger::LOAD_IC_TAG; + 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::CALL_IC: description = "A call IC from the snapshot"; - tag = Logger::CALL_IC_TAG; + tag = CodeEventListener::CALL_IC_TAG; break; case AbstractCode::STORE_IC: description = "A store IC from the snapshot"; - tag = Logger::STORE_IC_TAG; + tag = CodeEventListener::STORE_IC_TAG; break; case AbstractCode::KEYED_STORE_IC: description = "A keyed store IC from the snapshot"; - tag = Logger::KEYED_STORE_IC_TAG; + tag = CodeEventListener::KEYED_STORE_IC_TAG; break; case AbstractCode::WASM_FUNCTION: description = "A Wasm function"; - tag = Logger::STUB_TAG; + tag = CodeEventListener::STUB_TAG; break; case AbstractCode::JS_TO_WASM_FUNCTION: description = "A JavaScript to Wasm adapter"; - tag = Logger::STUB_TAG; + tag = CodeEventListener::STUB_TAG; break; case AbstractCode::WASM_TO_JS_FUNCTION: description = "A Wasm to JavaScript adapter"; - tag = Logger::STUB_TAG; + tag = CodeEventListener::STUB_TAG; break; + case AbstractCode::NUMBER_OF_KINDS: + UNIMPLEMENTED(); } PROFILE(isolate_, CodeCreateEvent(tag, code_object, description)); } @@ -1556,8 +1533,6 @@ void Logger::LogCodeObject(Object* object) { void Logger::LogCodeObjects() { Heap* heap = isolate_->heap(); - heap->CollectAllGarbage(Heap::kMakeHeapIterableMask, - "Logger::LogCodeObjects"); HeapIterator iterator(heap); DisallowHeapAllocation no_gc; for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) { @@ -1569,20 +1544,24 @@ void Logger::LogCodeObjects() { void Logger::LogBytecodeHandlers() { if (!FLAG_ignition) return; - interpreter::Interpreter* interpreter = isolate_->interpreter(); + 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); - for (auto operand_scale = interpreter::OperandScale::kSingle; - operand_scale <= interpreter::OperandScale::kMaxValid; - operand_scale = - interpreter::Bytecodes::NextOperandScale(operand_scale)) { + 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); - CodeCreateEvent(Logger::BYTECODE_HANDLER_TAG, AbstractCode::cast(code), - bytecode_name.c_str()); + PROFILE(isolate_, CodeCreateEvent( + CodeEventListener::BYTECODE_HANDLER_TAG, + AbstractCode::cast(code), bytecode_name.c_str())); } } } @@ -1601,28 +1580,28 @@ void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared, if (line_num > 0) { PROFILE(isolate_, CodeCreateEvent( - Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script), - *code, *shared, NULL, - *script_name, line_num, column_num)); + 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(Logger::SCRIPT_TAG, *script), - *code, *shared, NULL, *script_name)); + CodeCreateEvent(Logger::ToNativeByScript( + CodeEventListener::SCRIPT_TAG, *script), + *code, *shared, *script_name)); } } else { PROFILE(isolate_, - CodeCreateEvent( - Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script), - *code, *shared, NULL, - isolate_->heap()->empty_string(), line_num, column_num)); + 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()) { + 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); @@ -1632,17 +1611,14 @@ void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared, PROFILE(isolate_, CallbackEvent(*func_name, entry_point)); } } else { - PROFILE(isolate_, - CodeCreateEvent( - Logger::LAZY_COMPILE_TAG, *code, *shared, NULL, *func_name)); + PROFILE(isolate_, CodeCreateEvent(CodeEventListener::LAZY_COMPILE_TAG, + *code, *shared, *func_name)); } } void Logger::LogCompiledFunctions() { Heap* heap = isolate_->heap(); - heap->CollectAllGarbage(Heap::kMakeHeapIterableMask, - "Logger::LogCompiledFunctions"); HandleScope scope(isolate_); const int compiled_funcs_count = EnumerateCompiledFunctions(heap, NULL, NULL); ScopedVector< Handle<SharedFunctionInfo> > sfis(compiled_funcs_count); @@ -1661,8 +1637,6 @@ void Logger::LogCompiledFunctions() { void Logger::LogAccessorCallbacks() { Heap* heap = isolate_->heap(); - heap->CollectAllGarbage(Heap::kMakeHeapIterableMask, - "Logger::LogAccessorCallbacks"); HeapIterator iterator(heap); DisallowHeapAllocation no_gc; for (HeapObject* obj = iterator.next(); obj != NULL; obj = iterator.next()) { @@ -1747,7 +1721,6 @@ bool Logger::SetUp(Isolate* isolate) { 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_); @@ -1777,6 +1750,12 @@ bool Logger::SetUp(Isolate* isolate) { profiler_->Engage(); } + profiler_listener_.reset(); + + if (is_logging_) { + addCodeEventListener(this); + } + return true; } @@ -1800,8 +1779,20 @@ void Logger::SetCodeEventHandler(uint32_t options, } } +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* Logger::sampler() { +sampler::Sampler* Logger::sampler() { return ticker_; } @@ -1844,6 +1835,10 @@ FILE* Logger::TearDown() { jit_logger_ = NULL; } + if (profiler_listener_.get() != nullptr) { + removeCodeEventListener(profiler_listener_.get()); + } + return log_->Close(); } |