38ddf33cab
All standard containers provide a method named {empty} to check whether the container is empty. On {base::Vector}, that method is named {is_empty}, while {empty} is an unused factory method for creating an empty {Vector}. This CL renames {is_empty} to {empty} and removes the unused factory method. R=leszeks@chromium.org Bug: v8:8834 Change-Id: I686bd07527801fbe783c412bc241221d8ec3660a Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/1547862 Commit-Queue: Clemens Hammacher <clemensh@chromium.org> Reviewed-by: Leszek Swirski <leszeks@chromium.org> Cr-Commit-Position: refs/heads/master@{#60584}
2132 lines
70 KiB
C++
2132 lines
70 KiB
C++
// 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/api-inl.h"
|
|
#include "src/bailout-reason.h"
|
|
#include "src/base/platform/platform.h"
|
|
#include "src/bootstrapper.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/isolate.h"
|
|
#include "src/libsampler/sampler.h"
|
|
#include "src/log-inl.h"
|
|
#include "src/log-utils.h"
|
|
#include "src/macro-assembler.h"
|
|
#include "src/memcopy.h"
|
|
#include "src/objects/api-callbacks.h"
|
|
#include "src/perf-jit.h"
|
|
#include "src/profiler/tick-sample.h"
|
|
#include "src/runtime-profiler.h"
|
|
#include "src/snapshot/embedded-data.h"
|
|
#include "src/source-position-table.h"
|
|
#include "src/string-stream.h"
|
|
#include "src/tracing/tracing-category-observer.h"
|
|
#include "src/unicode-inl.h"
|
|
#include "src/vm-state-inl.h"
|
|
#include "src/wasm/wasm-code-manager.h"
|
|
#include "src/wasm/wasm-objects-inl.h"
|
|
|
|
#include "src/version.h"
|
|
|
|
namespace v8 {
|
|
namespace internal {
|
|
|
|
#define DECLARE_EVENT(ignore1, name) #name,
|
|
static const char* kLogEventsNames[CodeEventListener::NUMBER_OF_LOG_EVENTS] = {
|
|
LOG_EVENTS_AND_TAGS_LIST(DECLARE_EVENT)};
|
|
#undef DECLARE_EVENT
|
|
|
|
static v8::CodeEventType GetCodeEventTypeForTag(
|
|
CodeEventListener::LogEventsAndTags tag) {
|
|
switch (tag) {
|
|
case CodeEventListener::NUMBER_OF_LOG_EVENTS:
|
|
#define V(Event, _) case CodeEventListener::Event:
|
|
LOG_EVENTS_LIST(V)
|
|
#undef V
|
|
return v8::CodeEventType::kUnknownType;
|
|
#define V(From, To) \
|
|
case CodeEventListener::From: \
|
|
return v8::CodeEventType::k##To##Type;
|
|
TAGS_LIST(V)
|
|
#undef V
|
|
}
|
|
// The execution should never pass here
|
|
UNREACHABLE();
|
|
// NOTE(mmarchini): Workaround to fix a compiler failure on GCC 4.9
|
|
return v8::CodeEventType::kUnknownType;
|
|
}
|
|
#define CALL_CODE_EVENT_HANDLER(Call) \
|
|
if (listener_) { \
|
|
listener_->Call; \
|
|
} else { \
|
|
PROFILE(isolate_, Call); \
|
|
}
|
|
|
|
static const char* ComputeMarker(SharedFunctionInfo shared, AbstractCode code) {
|
|
switch (code->kind()) {
|
|
case AbstractCode::INTERPRETED_FUNCTION:
|
|
return shared->optimization_disabled() ? "" : "~";
|
|
case AbstractCode::OPTIMIZED_FUNCTION:
|
|
return "*";
|
|
default:
|
|
return "";
|
|
}
|
|
}
|
|
|
|
static const char* ComputeMarker(const wasm::WasmCode* code) {
|
|
switch (code->kind()) {
|
|
case wasm::WasmCode::kFunction:
|
|
return code->is_liftoff() ? "" : "*";
|
|
case wasm::WasmCode::kInterpreterEntry:
|
|
return "~";
|
|
default:
|
|
return "";
|
|
}
|
|
}
|
|
|
|
class CodeEventLogger::NameBuffer {
|
|
public:
|
|
NameBuffer() { Reset(); }
|
|
|
|
void Reset() {
|
|
utf8_pos_ = 0;
|
|
}
|
|
|
|
void Init(CodeEventListener::LogEventsAndTags tag) {
|
|
Reset();
|
|
AppendBytes(kLogEventsNames[tag]);
|
|
AppendByte(':');
|
|
}
|
|
|
|
void AppendName(Name name) {
|
|
if (name->IsString()) {
|
|
AppendString(String::cast(name));
|
|
} else {
|
|
Symbol symbol = Symbol::cast(name);
|
|
AppendBytes("symbol(");
|
|
if (!symbol->name()->IsUndefined()) {
|
|
AppendBytes("\"");
|
|
AppendString(String::cast(symbol->name()));
|
|
AppendBytes("\" ");
|
|
}
|
|
AppendBytes("hash ");
|
|
AppendHex(symbol->Hash());
|
|
AppendByte(')');
|
|
}
|
|
}
|
|
|
|
void AppendString(String str) {
|
|
if (str.is_null()) return;
|
|
int length = 0;
|
|
std::unique_ptr<char[]> c_str =
|
|
str->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL, &length);
|
|
AppendBytes(c_str.get(), length);
|
|
}
|
|
|
|
void AppendBytes(const char* bytes, int size) {
|
|
size = Min(size, kUtf8BufferSize - utf8_pos_);
|
|
MemCopy(utf8_buffer_ + utf8_pos_, bytes, size);
|
|
utf8_pos_ += size;
|
|
}
|
|
|
|
void AppendBytes(const char* bytes) {
|
|
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];
|
|
};
|
|
|
|
CodeEventLogger::CodeEventLogger(Isolate* isolate)
|
|
: isolate_(isolate), name_buffer_(new NameBuffer) {}
|
|
|
|
CodeEventLogger::~CodeEventLogger() { delete name_buffer_; }
|
|
|
|
void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
|
|
AbstractCode code, const char* comment) {
|
|
name_buffer_->Init(tag);
|
|
name_buffer_->AppendBytes(comment);
|
|
LogRecordedBuffer(code, SharedFunctionInfo(), name_buffer_->get(),
|
|
name_buffer_->size());
|
|
}
|
|
|
|
void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
|
|
AbstractCode code, Name name) {
|
|
name_buffer_->Init(tag);
|
|
name_buffer_->AppendName(name);
|
|
LogRecordedBuffer(code, SharedFunctionInfo(), name_buffer_->get(),
|
|
name_buffer_->size());
|
|
}
|
|
|
|
void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
|
|
AbstractCode code,
|
|
SharedFunctionInfo shared, Name name) {
|
|
name_buffer_->Init(tag);
|
|
name_buffer_->AppendBytes(ComputeMarker(shared, code));
|
|
name_buffer_->AppendByte(' ');
|
|
name_buffer_->AppendName(name);
|
|
LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
|
|
}
|
|
|
|
void CodeEventLogger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
|
|
AbstractCode code,
|
|
SharedFunctionInfo shared, Name source,
|
|
int line, int column) {
|
|
name_buffer_->Init(tag);
|
|
name_buffer_->AppendBytes(ComputeMarker(shared, code));
|
|
name_buffer_->AppendString(shared->DebugName());
|
|
name_buffer_->AppendByte(' ');
|
|
if (source->IsString()) {
|
|
name_buffer_->AppendString(String::cast(source));
|
|
} else {
|
|
name_buffer_->AppendBytes("symbol(hash ");
|
|
name_buffer_->AppendHex(Name::cast(source)->Hash());
|
|
name_buffer_->AppendByte(')');
|
|
}
|
|
name_buffer_->AppendByte(':');
|
|
name_buffer_->AppendInt(line);
|
|
LogRecordedBuffer(code, shared, name_buffer_->get(), name_buffer_->size());
|
|
}
|
|
|
|
void CodeEventLogger::CodeCreateEvent(LogEventsAndTags tag,
|
|
const wasm::WasmCode* code,
|
|
wasm::WasmName name) {
|
|
name_buffer_->Init(tag);
|
|
if (name.empty()) {
|
|
name_buffer_->AppendBytes("<wasm-unknown>");
|
|
} else {
|
|
name_buffer_->AppendBytes(name.start(), name.length());
|
|
}
|
|
name_buffer_->AppendByte('-');
|
|
if (code->IsAnonymous()) {
|
|
name_buffer_->AppendBytes("<anonymous>");
|
|
} else {
|
|
name_buffer_->AppendInt(code->index());
|
|
}
|
|
LogRecordedBuffer(code, name_buffer_->get(), name_buffer_->size());
|
|
}
|
|
|
|
void CodeEventLogger::RegExpCodeCreateEvent(AbstractCode code, String source) {
|
|
name_buffer_->Init(CodeEventListener::REG_EXP_TAG);
|
|
name_buffer_->AppendString(source);
|
|
LogRecordedBuffer(code, SharedFunctionInfo(), name_buffer_->get(),
|
|
name_buffer_->size());
|
|
}
|
|
|
|
// Linux perf tool logging support
|
|
class PerfBasicLogger : public CodeEventLogger {
|
|
public:
|
|
explicit PerfBasicLogger(Isolate* isolate);
|
|
~PerfBasicLogger() override;
|
|
|
|
void CodeMoveEvent(AbstractCode from, AbstractCode to) override {}
|
|
void CodeDisableOptEvent(AbstractCode code,
|
|
SharedFunctionInfo shared) override {}
|
|
|
|
private:
|
|
void LogRecordedBuffer(AbstractCode code, SharedFunctionInfo shared,
|
|
const char* name, int length) override;
|
|
void LogRecordedBuffer(const wasm::WasmCode* code, const char* name,
|
|
int length) override;
|
|
void WriteLogRecordedBuffer(uintptr_t address, int size, const char* name,
|
|
int name_length);
|
|
|
|
// Extension added to V8 log file name to get the low-level log name.
|
|
static const char kFilenameFormatString[];
|
|
static const int kFilenameBufferPadding;
|
|
|
|
FILE* perf_output_handle_;
|
|
};
|
|
|
|
const char PerfBasicLogger::kFilenameFormatString[] = "/tmp/perf-%d.map";
|
|
// Extra space for the PID in the filename
|
|
const int PerfBasicLogger::kFilenameBufferPadding = 16;
|
|
|
|
PerfBasicLogger::PerfBasicLogger(Isolate* isolate)
|
|
: CodeEventLogger(isolate), perf_output_handle_(nullptr) {
|
|
// Open the perf JIT dump file.
|
|
int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
|
|
ScopedVector<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_, nullptr, _IOLBF, 0);
|
|
}
|
|
|
|
|
|
PerfBasicLogger::~PerfBasicLogger() {
|
|
fclose(perf_output_handle_);
|
|
perf_output_handle_ = nullptr;
|
|
}
|
|
|
|
void PerfBasicLogger::WriteLogRecordedBuffer(uintptr_t address, int size,
|
|
const char* name,
|
|
int name_length) {
|
|
// Linux perf expects hex literals without a leading 0x, while some
|
|
// implementations of printf might prepend one when using the %p format
|
|
// for pointers, leading to wrongly formatted JIT symbols maps.
|
|
//
|
|
// Instead, we use V8PRIxPTR format string and cast pointer to uintpr_t,
|
|
// so that we have control over the exact output format.
|
|
base::OS::FPrint(perf_output_handle_, "%" V8PRIxPTR " %x %.*s\n", address,
|
|
size, name_length, name);
|
|
}
|
|
|
|
void PerfBasicLogger::LogRecordedBuffer(AbstractCode code, SharedFunctionInfo,
|
|
const char* name, int length) {
|
|
if (FLAG_perf_basic_prof_only_functions &&
|
|
(code->kind() != AbstractCode::INTERPRETED_FUNCTION &&
|
|
code->kind() != AbstractCode::BUILTIN &&
|
|
code->kind() != AbstractCode::OPTIMIZED_FUNCTION)) {
|
|
return;
|
|
}
|
|
|
|
WriteLogRecordedBuffer(static_cast<uintptr_t>(code->InstructionStart()),
|
|
code->InstructionSize(), name, length);
|
|
}
|
|
|
|
void PerfBasicLogger::LogRecordedBuffer(const wasm::WasmCode* code,
|
|
const char* name, int length) {
|
|
WriteLogRecordedBuffer(static_cast<uintptr_t>(code->instruction_start()),
|
|
code->instructions().length(), name, length);
|
|
}
|
|
|
|
// External CodeEventListener
|
|
ExternalCodeEventListener::ExternalCodeEventListener(Isolate* isolate)
|
|
: is_listening_(false), isolate_(isolate), code_event_handler_(nullptr) {}
|
|
|
|
ExternalCodeEventListener::~ExternalCodeEventListener() {
|
|
if (is_listening_) {
|
|
StopListening();
|
|
}
|
|
}
|
|
|
|
void ExternalCodeEventListener::LogExistingCode() {
|
|
HandleScope scope(isolate_);
|
|
ExistingCodeLogger logger(isolate_, this);
|
|
logger.LogCodeObjects();
|
|
logger.LogCompiledFunctions();
|
|
}
|
|
|
|
void ExternalCodeEventListener::StartListening(
|
|
CodeEventHandler* code_event_handler) {
|
|
if (is_listening_ || code_event_handler == nullptr) {
|
|
return;
|
|
}
|
|
code_event_handler_ = code_event_handler;
|
|
is_listening_ = isolate_->code_event_dispatcher()->AddListener(this);
|
|
if (is_listening_) {
|
|
LogExistingCode();
|
|
}
|
|
}
|
|
|
|
void ExternalCodeEventListener::StopListening() {
|
|
if (!is_listening_) {
|
|
return;
|
|
}
|
|
|
|
isolate_->code_event_dispatcher()->RemoveListener(this);
|
|
is_listening_ = false;
|
|
}
|
|
|
|
void ExternalCodeEventListener::CodeCreateEvent(
|
|
CodeEventListener::LogEventsAndTags tag, AbstractCode code,
|
|
const char* comment) {
|
|
CodeEvent code_event;
|
|
code_event.code_start_address =
|
|
static_cast<uintptr_t>(code->InstructionStart());
|
|
code_event.code_size = static_cast<size_t>(code->InstructionSize());
|
|
code_event.function_name = isolate_->factory()->empty_string();
|
|
code_event.script_name = isolate_->factory()->empty_string();
|
|
code_event.script_line = 0;
|
|
code_event.script_column = 0;
|
|
code_event.code_type = GetCodeEventTypeForTag(tag);
|
|
code_event.comment = comment;
|
|
|
|
code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
|
|
}
|
|
|
|
void ExternalCodeEventListener::CodeCreateEvent(
|
|
CodeEventListener::LogEventsAndTags tag, AbstractCode code, Name name) {
|
|
Handle<String> name_string =
|
|
Name::ToFunctionName(isolate_, Handle<Name>(name, isolate_))
|
|
.ToHandleChecked();
|
|
|
|
CodeEvent code_event;
|
|
code_event.code_start_address =
|
|
static_cast<uintptr_t>(code->InstructionStart());
|
|
code_event.code_size = static_cast<size_t>(code->InstructionSize());
|
|
code_event.function_name = name_string;
|
|
code_event.script_name = isolate_->factory()->empty_string();
|
|
code_event.script_line = 0;
|
|
code_event.script_column = 0;
|
|
code_event.code_type = GetCodeEventTypeForTag(tag);
|
|
code_event.comment = "";
|
|
|
|
code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
|
|
}
|
|
|
|
void ExternalCodeEventListener::CodeCreateEvent(
|
|
CodeEventListener::LogEventsAndTags tag, AbstractCode code,
|
|
SharedFunctionInfo shared, Name name) {
|
|
Handle<String> name_string =
|
|
Name::ToFunctionName(isolate_, Handle<Name>(name, isolate_))
|
|
.ToHandleChecked();
|
|
|
|
CodeEvent code_event;
|
|
code_event.code_start_address =
|
|
static_cast<uintptr_t>(code->InstructionStart());
|
|
code_event.code_size = static_cast<size_t>(code->InstructionSize());
|
|
code_event.function_name = name_string;
|
|
code_event.script_name = isolate_->factory()->empty_string();
|
|
code_event.script_line = 0;
|
|
code_event.script_column = 0;
|
|
code_event.code_type = GetCodeEventTypeForTag(tag);
|
|
code_event.comment = "";
|
|
|
|
code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
|
|
}
|
|
|
|
void ExternalCodeEventListener::CodeCreateEvent(
|
|
CodeEventListener::LogEventsAndTags tag, AbstractCode code,
|
|
SharedFunctionInfo shared, Name source, int line, int column) {
|
|
Handle<String> name_string =
|
|
Name::ToFunctionName(isolate_, Handle<Name>(shared->Name(), isolate_))
|
|
.ToHandleChecked();
|
|
Handle<String> source_string =
|
|
Name::ToFunctionName(isolate_, Handle<Name>(source, isolate_))
|
|
.ToHandleChecked();
|
|
|
|
CodeEvent code_event;
|
|
code_event.code_start_address =
|
|
static_cast<uintptr_t>(code->InstructionStart());
|
|
code_event.code_size = static_cast<size_t>(code->InstructionSize());
|
|
code_event.function_name = name_string;
|
|
code_event.script_name = source_string;
|
|
code_event.script_line = line;
|
|
code_event.script_column = column;
|
|
code_event.code_type = GetCodeEventTypeForTag(tag);
|
|
code_event.comment = "";
|
|
|
|
code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
|
|
}
|
|
|
|
void ExternalCodeEventListener::CodeCreateEvent(LogEventsAndTags tag,
|
|
const wasm::WasmCode* code,
|
|
wasm::WasmName name) {
|
|
// TODO(mmarchini): handle later
|
|
}
|
|
|
|
void ExternalCodeEventListener::RegExpCodeCreateEvent(AbstractCode code,
|
|
String source) {
|
|
CodeEvent code_event;
|
|
code_event.code_start_address =
|
|
static_cast<uintptr_t>(code->InstructionStart());
|
|
code_event.code_size = static_cast<size_t>(code->InstructionSize());
|
|
code_event.function_name = Handle<String>(source, isolate_);
|
|
code_event.script_name = isolate_->factory()->empty_string();
|
|
code_event.script_line = 0;
|
|
code_event.script_column = 0;
|
|
code_event.code_type = GetCodeEventTypeForTag(CodeEventListener::REG_EXP_TAG);
|
|
code_event.comment = "";
|
|
|
|
code_event_handler_->Handle(reinterpret_cast<v8::CodeEvent*>(&code_event));
|
|
}
|
|
|
|
// Low-level logging support.
|
|
class LowLevelLogger : public CodeEventLogger {
|
|
public:
|
|
LowLevelLogger(Isolate* isolate, const char* file_name);
|
|
~LowLevelLogger() override;
|
|
|
|
void CodeMoveEvent(AbstractCode from, AbstractCode to) override;
|
|
void CodeDisableOptEvent(AbstractCode code,
|
|
SharedFunctionInfo shared) override {}
|
|
void SnapshotPositionEvent(HeapObject obj, int pos);
|
|
void CodeMovingGCEvent() override;
|
|
|
|
private:
|
|
void LogRecordedBuffer(AbstractCode code, SharedFunctionInfo shared,
|
|
const char* name, int length) override;
|
|
void LogRecordedBuffer(const wasm::WasmCode* code, const char* name,
|
|
int length) override;
|
|
|
|
// Low-level profiling event structures.
|
|
struct CodeCreateStruct {
|
|
static const char kTag = 'C';
|
|
|
|
int32_t name_size;
|
|
Address code_address;
|
|
int32_t code_size;
|
|
};
|
|
|
|
|
|
struct CodeMoveStruct {
|
|
static const char kTag = 'M';
|
|
|
|
Address from_address;
|
|
Address to_address;
|
|
};
|
|
|
|
|
|
static const char kCodeMovingGCTag = 'G';
|
|
|
|
|
|
// Extension added to V8 log file name to get the low-level log name.
|
|
static const char kLogExt[];
|
|
|
|
void LogCodeInfo();
|
|
void LogWriteBytes(const char* bytes, int size);
|
|
|
|
template <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(Isolate* isolate, const char* name)
|
|
: CodeEventLogger(isolate), ll_output_handle_(nullptr) {
|
|
// 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_, nullptr, _IOLBF, 0);
|
|
|
|
LogCodeInfo();
|
|
}
|
|
|
|
|
|
LowLevelLogger::~LowLevelLogger() {
|
|
fclose(ll_output_handle_);
|
|
ll_output_handle_ = nullptr;
|
|
}
|
|
|
|
|
|
void LowLevelLogger::LogCodeInfo() {
|
|
#if V8_TARGET_ARCH_IA32
|
|
const char arch[] = "ia32";
|
|
#elif V8_TARGET_ARCH_X64 && V8_TARGET_ARCH_64_BIT
|
|
const char arch[] = "x64";
|
|
#elif V8_TARGET_ARCH_ARM
|
|
const char arch[] = "arm";
|
|
#elif V8_TARGET_ARCH_PPC
|
|
const char arch[] = "ppc";
|
|
#elif V8_TARGET_ARCH_MIPS
|
|
const char arch[] = "mips";
|
|
#elif V8_TARGET_ARCH_ARM64
|
|
const char arch[] = "arm64";
|
|
#elif V8_TARGET_ARCH_S390
|
|
const char arch[] = "s390";
|
|
#else
|
|
const char arch[] = "unknown";
|
|
#endif
|
|
LogWriteBytes(arch, sizeof(arch));
|
|
}
|
|
|
|
void LowLevelLogger::LogRecordedBuffer(AbstractCode code, SharedFunctionInfo,
|
|
const char* name, int length) {
|
|
CodeCreateStruct event;
|
|
event.name_size = length;
|
|
event.code_address = code->InstructionStart();
|
|
event.code_size = code->InstructionSize();
|
|
LogWriteStruct(event);
|
|
LogWriteBytes(name, length);
|
|
LogWriteBytes(reinterpret_cast<const char*>(code->InstructionStart()),
|
|
code->InstructionSize());
|
|
}
|
|
|
|
void LowLevelLogger::LogRecordedBuffer(const wasm::WasmCode* code,
|
|
const char* name, int length) {
|
|
CodeCreateStruct event;
|
|
event.name_size = length;
|
|
event.code_address = code->instruction_start();
|
|
event.code_size = code->instructions().length();
|
|
LogWriteStruct(event);
|
|
LogWriteBytes(name, length);
|
|
LogWriteBytes(reinterpret_cast<const char*>(code->instruction_start()),
|
|
code->instructions().length());
|
|
}
|
|
|
|
void LowLevelLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) {
|
|
CodeMoveStruct event;
|
|
event.from_address = from->InstructionStart();
|
|
event.to_address = to->InstructionStart();
|
|
LogWriteStruct(event);
|
|
}
|
|
|
|
void LowLevelLogger::LogWriteBytes(const char* bytes, int size) {
|
|
size_t rv = fwrite(bytes, 1, size, ll_output_handle_);
|
|
DCHECK(static_cast<size_t>(size) == rv);
|
|
USE(rv);
|
|
}
|
|
|
|
|
|
void LowLevelLogger::CodeMovingGCEvent() {
|
|
const char tag = kCodeMovingGCTag;
|
|
|
|
LogWriteBytes(&tag, sizeof(tag));
|
|
}
|
|
|
|
class JitLogger : public CodeEventLogger {
|
|
public:
|
|
JitLogger(Isolate* isolate, JitCodeEventHandler code_event_handler);
|
|
|
|
void CodeMoveEvent(AbstractCode from, AbstractCode to) override;
|
|
void CodeDisableOptEvent(AbstractCode code,
|
|
SharedFunctionInfo shared) override {}
|
|
void AddCodeLinePosInfoEvent(void* jit_handler_data, int pc_offset,
|
|
int position,
|
|
JitCodeEvent::PositionType position_type);
|
|
|
|
void* StartCodePosInfoEvent();
|
|
void EndCodePosInfoEvent(Address start_address, void* jit_handler_data);
|
|
|
|
private:
|
|
void LogRecordedBuffer(AbstractCode code, SharedFunctionInfo shared,
|
|
const char* name, int length) override;
|
|
void LogRecordedBuffer(const wasm::WasmCode* code, const char* name,
|
|
int length) override;
|
|
|
|
JitCodeEventHandler code_event_handler_;
|
|
base::Mutex logger_mutex_;
|
|
};
|
|
|
|
JitLogger::JitLogger(Isolate* isolate, JitCodeEventHandler code_event_handler)
|
|
: CodeEventLogger(isolate), code_event_handler_(code_event_handler) {}
|
|
|
|
void JitLogger::LogRecordedBuffer(AbstractCode code, SharedFunctionInfo shared,
|
|
const char* name, int length) {
|
|
JitCodeEvent event;
|
|
memset(static_cast<void*>(&event), 0, sizeof(event));
|
|
event.type = JitCodeEvent::CODE_ADDED;
|
|
event.code_start = reinterpret_cast<void*>(code->InstructionStart());
|
|
event.code_type =
|
|
code->IsCode() ? JitCodeEvent::JIT_CODE : JitCodeEvent::BYTE_CODE;
|
|
event.code_len = code->InstructionSize();
|
|
Handle<SharedFunctionInfo> shared_function_handle;
|
|
if (!shared.is_null() && shared->script()->IsScript()) {
|
|
shared_function_handle =
|
|
Handle<SharedFunctionInfo>(shared, shared->GetIsolate());
|
|
}
|
|
event.script = ToApiHandle<v8::UnboundScript>(shared_function_handle);
|
|
event.name.str = name;
|
|
event.name.len = length;
|
|
event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
|
|
code_event_handler_(&event);
|
|
}
|
|
|
|
void JitLogger::LogRecordedBuffer(const wasm::WasmCode* code, const char* name,
|
|
int length) {
|
|
JitCodeEvent event;
|
|
memset(static_cast<void*>(&event), 0, sizeof(event));
|
|
event.type = JitCodeEvent::CODE_ADDED;
|
|
event.code_type = JitCodeEvent::JIT_CODE;
|
|
event.code_start = code->instructions().start();
|
|
event.code_len = code->instructions().length();
|
|
event.name.str = name;
|
|
event.name.len = length;
|
|
event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
|
|
code_event_handler_(&event);
|
|
}
|
|
|
|
void JitLogger::CodeMoveEvent(AbstractCode from, AbstractCode to) {
|
|
base::MutexGuard guard(&logger_mutex_);
|
|
|
|
JitCodeEvent event;
|
|
event.type = JitCodeEvent::CODE_MOVED;
|
|
event.code_type =
|
|
from->IsCode() ? JitCodeEvent::JIT_CODE : JitCodeEvent::BYTE_CODE;
|
|
event.code_start = reinterpret_cast<void*>(from->InstructionStart());
|
|
event.code_len = from->InstructionSize();
|
|
event.new_code_start = reinterpret_cast<void*>(to->InstructionStart());
|
|
event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
|
|
|
|
code_event_handler_(&event);
|
|
}
|
|
|
|
void JitLogger::AddCodeLinePosInfoEvent(
|
|
void* jit_handler_data,
|
|
int pc_offset,
|
|
int position,
|
|
JitCodeEvent::PositionType position_type) {
|
|
JitCodeEvent event;
|
|
memset(static_cast<void*>(&event), 0, sizeof(event));
|
|
event.type = JitCodeEvent::CODE_ADD_LINE_POS_INFO;
|
|
event.user_data = jit_handler_data;
|
|
event.line_info.offset = pc_offset;
|
|
event.line_info.pos = position;
|
|
event.line_info.position_type = position_type;
|
|
event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
|
|
|
|
code_event_handler_(&event);
|
|
}
|
|
|
|
|
|
void* JitLogger::StartCodePosInfoEvent() {
|
|
JitCodeEvent event;
|
|
memset(static_cast<void*>(&event), 0, sizeof(event));
|
|
event.type = JitCodeEvent::CODE_START_LINE_INFO_RECORDING;
|
|
event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
|
|
|
|
code_event_handler_(&event);
|
|
return event.user_data;
|
|
}
|
|
|
|
void JitLogger::EndCodePosInfoEvent(Address start_address,
|
|
void* jit_handler_data) {
|
|
JitCodeEvent event;
|
|
memset(static_cast<void*>(&event), 0, sizeof(event));
|
|
event.type = JitCodeEvent::CODE_END_LINE_INFO_RECORDING;
|
|
event.code_start = reinterpret_cast<void*>(start_address);
|
|
event.user_data = jit_handler_data;
|
|
event.isolate = reinterpret_cast<v8::Isolate*>(isolate_);
|
|
|
|
code_event_handler_(&event);
|
|
}
|
|
|
|
|
|
// TODO(lpy): Keeping sampling thread inside V8 is a workaround currently,
|
|
// the reason is to reduce code duplication during migration to sampler library,
|
|
// sampling thread, as well as the sampler, will be moved to D8 eventually.
|
|
class SamplingThread : public base::Thread {
|
|
public:
|
|
static const int kSamplingThreadStackSize = 64 * KB;
|
|
|
|
SamplingThread(sampler::Sampler* sampler, int interval_microseconds)
|
|
: base::Thread(
|
|
base::Thread::Options("SamplingThread", kSamplingThreadStackSize)),
|
|
sampler_(sampler),
|
|
interval_microseconds_(interval_microseconds) {}
|
|
void Run() override {
|
|
while (sampler_->IsActive()) {
|
|
sampler_->DoSample();
|
|
base::OS::Sleep(
|
|
base::TimeDelta::FromMicroseconds(interval_microseconds_));
|
|
}
|
|
}
|
|
|
|
private:
|
|
sampler::Sampler* sampler_;
|
|
const int interval_microseconds_;
|
|
};
|
|
|
|
|
|
// The Profiler samples pc and sp values for the main thread.
|
|
// Each sample is appended to a circular buffer.
|
|
// An independent thread removes data and writes it to the log.
|
|
// This design minimizes the time spent in the sampler.
|
|
//
|
|
class Profiler: public base::Thread {
|
|
public:
|
|
explicit Profiler(Isolate* isolate);
|
|
void Engage();
|
|
void Disengage();
|
|
|
|
// Inserts collected profiling data into buffer.
|
|
void Insert(v8::TickSample* sample) {
|
|
if (Succ(head_) == static_cast<int>(base::Relaxed_Load(&tail_))) {
|
|
overflow_ = true;
|
|
} else {
|
|
buffer_[head_] = *sample;
|
|
head_ = Succ(head_);
|
|
buffer_semaphore_.Signal(); // Tell we have an element.
|
|
}
|
|
}
|
|
|
|
void Run() override;
|
|
|
|
private:
|
|
// Waits for a signal and removes profiling data.
|
|
bool Remove(v8::TickSample* sample) {
|
|
buffer_semaphore_.Wait(); // Wait for an element.
|
|
*sample = buffer_[base::Relaxed_Load(&tail_)];
|
|
bool result = overflow_;
|
|
base::Relaxed_Store(
|
|
&tail_, static_cast<base::Atomic32>(Succ(base::Relaxed_Load(&tail_))));
|
|
overflow_ = false;
|
|
return result;
|
|
}
|
|
|
|
// Returns the next index in the cyclic buffer.
|
|
int Succ(int index) { return (index + 1) % kBufferSize; }
|
|
|
|
Isolate* isolate_;
|
|
// Cyclic buffer for communicating profiling samples
|
|
// between the signal handler and the worker thread.
|
|
static const int kBufferSize = 128;
|
|
v8::TickSample buffer_[kBufferSize]; // Buffer storage.
|
|
int head_; // Index to the buffer head.
|
|
base::Atomic32 tail_; // Index to the buffer tail.
|
|
bool overflow_; // Tell whether a buffer overflow has occurred.
|
|
// Semaphore used for buffer synchronization.
|
|
base::Semaphore buffer_semaphore_;
|
|
|
|
// Tells whether worker thread should continue running.
|
|
base::Atomic32 running_;
|
|
};
|
|
|
|
|
|
//
|
|
// Ticker used to provide ticks to the profiler and the sliding state
|
|
// window.
|
|
//
|
|
class Ticker: public sampler::Sampler {
|
|
public:
|
|
Ticker(Isolate* isolate, int interval_microseconds)
|
|
: sampler::Sampler(reinterpret_cast<v8::Isolate*>(isolate)),
|
|
sampling_thread_(
|
|
base::make_unique<SamplingThread>(this, interval_microseconds)) {}
|
|
|
|
~Ticker() override {
|
|
if (IsActive()) Stop();
|
|
}
|
|
|
|
void SetProfiler(Profiler* profiler) {
|
|
DCHECK_NULL(profiler_);
|
|
profiler_ = profiler;
|
|
if (!IsActive()) Start();
|
|
sampling_thread_->StartSynchronously();
|
|
}
|
|
|
|
void ClearProfiler() {
|
|
profiler_ = nullptr;
|
|
if (IsActive()) Stop();
|
|
sampling_thread_->Join();
|
|
}
|
|
|
|
void SampleStack(const v8::RegisterState& state) override {
|
|
if (!profiler_) return;
|
|
Isolate* isolate = reinterpret_cast<Isolate*>(this->isolate());
|
|
TickSample sample;
|
|
sample.Init(isolate, state, TickSample::kIncludeCEntryFrame, true);
|
|
profiler_->Insert(&sample);
|
|
}
|
|
|
|
private:
|
|
Profiler* profiler_ = nullptr;
|
|
std::unique_ptr<SamplingThread> sampling_thread_;
|
|
};
|
|
|
|
//
|
|
// Profiler implementation when invoking with --prof.
|
|
//
|
|
Profiler::Profiler(Isolate* isolate)
|
|
: base::Thread(Options("v8:Profiler")),
|
|
isolate_(isolate),
|
|
head_(0),
|
|
overflow_(false),
|
|
buffer_semaphore_(0) {
|
|
base::Relaxed_Store(&tail_, 0);
|
|
base::Relaxed_Store(&running_, 0);
|
|
}
|
|
|
|
void Profiler::Engage() {
|
|
std::vector<base::OS::SharedLibraryAddress> addresses =
|
|
base::OS::GetSharedLibraryAddresses();
|
|
for (const auto& address : addresses) {
|
|
LOG(isolate_, SharedLibraryEvent(address.library_path, address.start,
|
|
address.end, address.aslr_slide));
|
|
}
|
|
|
|
// Start thread processing the profiler buffer.
|
|
base::Relaxed_Store(&running_, 1);
|
|
Start();
|
|
|
|
// Register to get ticks.
|
|
Logger* logger = isolate_->logger();
|
|
logger->ticker_->SetProfiler(this);
|
|
|
|
logger->ProfilerBeginEvent();
|
|
}
|
|
|
|
|
|
void Profiler::Disengage() {
|
|
// Stop receiving ticks.
|
|
isolate_->logger()->ticker_->ClearProfiler();
|
|
|
|
// Terminate the worker thread by setting running_ to false,
|
|
// inserting a fake element in the queue and then wait for
|
|
// the thread to terminate.
|
|
base::Relaxed_Store(&running_, 0);
|
|
v8::TickSample sample;
|
|
Insert(&sample);
|
|
Join();
|
|
|
|
LOG(isolate_, UncheckedStringEvent("profiler", "end"));
|
|
}
|
|
|
|
|
|
void Profiler::Run() {
|
|
v8::TickSample sample;
|
|
bool overflow = Remove(&sample);
|
|
while (base::Relaxed_Load(&running_)) {
|
|
LOG(isolate_, TickEvent(&sample, overflow));
|
|
overflow = Remove(&sample);
|
|
}
|
|
}
|
|
|
|
|
|
//
|
|
// Logger class implementation.
|
|
//
|
|
|
|
Logger::Logger(Isolate* isolate)
|
|
: isolate_(isolate),
|
|
log_events_(nullptr),
|
|
is_logging_(false),
|
|
log_(nullptr),
|
|
is_initialized_(false),
|
|
existing_code_logger_(isolate) {}
|
|
|
|
Logger::~Logger() {
|
|
delete log_;
|
|
}
|
|
|
|
const LogSeparator Logger::kNext = LogSeparator::kSeparator;
|
|
|
|
void Logger::AddCodeEventListener(CodeEventListener* listener) {
|
|
bool result = isolate_->code_event_dispatcher()->AddListener(listener);
|
|
CHECK(result);
|
|
}
|
|
|
|
void Logger::RemoveCodeEventListener(CodeEventListener* listener) {
|
|
isolate_->code_event_dispatcher()->RemoveListener(listener);
|
|
}
|
|
|
|
void Logger::ProfilerBeginEvent() {
|
|
if (!log_->IsEnabled()) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "profiler" << kNext << "begin" << kNext << FLAG_prof_sampling_interval;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
|
|
void Logger::StringEvent(const char* name, const char* value) {
|
|
if (FLAG_log) UncheckedStringEvent(name, value);
|
|
}
|
|
|
|
|
|
void Logger::UncheckedStringEvent(const char* name, const char* value) {
|
|
if (!log_->IsEnabled()) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << name << kNext << value;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
|
|
void Logger::IntPtrTEvent(const char* name, intptr_t value) {
|
|
if (FLAG_log) UncheckedIntPtrTEvent(name, value);
|
|
}
|
|
|
|
|
|
void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
|
|
if (!log_->IsEnabled()) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << name << kNext;
|
|
msg.AppendFormatString("%" V8PRIdPTR, value);
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::HandleEvent(const char* name, Address* location) {
|
|
if (!log_->IsEnabled() || !FLAG_log_handles) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << name << kNext << reinterpret_cast<void*>(location);
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
|
|
void Logger::ApiSecurityCheck() {
|
|
if (!log_->IsEnabled() || !FLAG_log_api) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "api" << kNext << "check-security";
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::SharedLibraryEvent(const std::string& library_path,
|
|
uintptr_t start, uintptr_t end,
|
|
intptr_t aslr_slide) {
|
|
if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "shared-library" << kNext << library_path.c_str() << kNext
|
|
<< reinterpret_cast<void*>(start) << kNext << reinterpret_cast<void*>(end)
|
|
<< kNext << aslr_slide;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::CodeDeoptEvent(Code code, DeoptimizeKind kind, Address pc,
|
|
int fp_to_sp_delta) {
|
|
if (!log_->IsEnabled()) return;
|
|
Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(code, pc);
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "code-deopt" << kNext << timer_.Elapsed().InMicroseconds() << kNext
|
|
<< code->CodeSize() << kNext
|
|
<< reinterpret_cast<void*>(code->InstructionStart());
|
|
|
|
// Deoptimization position.
|
|
std::ostringstream deopt_location;
|
|
int inlining_id = -1;
|
|
int script_offset = -1;
|
|
if (info.position.IsKnown()) {
|
|
info.position.Print(deopt_location, code);
|
|
inlining_id = info.position.InliningId();
|
|
script_offset = info.position.ScriptOffset();
|
|
} else {
|
|
deopt_location << "<unknown>";
|
|
}
|
|
msg << kNext << inlining_id << kNext << script_offset << kNext;
|
|
msg << Deoptimizer::MessageFor(kind) << kNext;
|
|
msg << deopt_location.str().c_str() << kNext
|
|
<< DeoptimizeReasonToString(info.deopt_reason);
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
|
|
void Logger::CurrentTimeEvent() {
|
|
if (!log_->IsEnabled()) return;
|
|
DCHECK(FLAG_log_internal_timer_events);
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "current-time" << kNext << timer_.Elapsed().InMicroseconds();
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
|
|
void Logger::TimerEvent(Logger::StartEnd se, const char* name) {
|
|
if (!log_->IsEnabled()) return;
|
|
Log::MessageBuilder msg(log_);
|
|
switch (se) {
|
|
case START:
|
|
msg << "timer-event-start";
|
|
break;
|
|
case END:
|
|
msg << "timer-event-end";
|
|
break;
|
|
case STAMP:
|
|
msg << "timer-event";
|
|
}
|
|
msg << kNext << name << kNext << timer_.Elapsed().InMicroseconds();
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
// static
|
|
void Logger::EnterExternal(Isolate* isolate) {
|
|
DCHECK(FLAG_log_internal_timer_events);
|
|
LOG(isolate, TimerEvent(START, TimerEventExternal::name()));
|
|
DCHECK(isolate->current_vm_state() == JS);
|
|
isolate->set_current_vm_state(EXTERNAL);
|
|
}
|
|
|
|
// static
|
|
void Logger::LeaveExternal(Isolate* isolate) {
|
|
DCHECK(FLAG_log_internal_timer_events);
|
|
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 property_name) {
|
|
DCHECK(property_name->IsName());
|
|
if (!log_->IsEnabled() || !FLAG_log_api) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "api" << kNext << tag << kNext << holder->class_name() << kNext
|
|
<< Name::cast(property_name);
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::ApiIndexedPropertyAccess(const char* tag, JSObject holder,
|
|
uint32_t index) {
|
|
if (!log_->IsEnabled() || !FLAG_log_api) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "api" << kNext << tag << kNext << holder->class_name() << kNext
|
|
<< index;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::ApiObjectAccess(const char* tag, JSObject object) {
|
|
if (!log_->IsEnabled() || !FLAG_log_api) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "api" << kNext << tag << kNext << object->class_name();
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::ApiEntryCall(const char* name) {
|
|
if (!log_->IsEnabled() || !FLAG_log_api) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "api" << kNext << name;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
|
|
void Logger::NewEvent(const char* name, void* object, size_t size) {
|
|
if (!log_->IsEnabled() || !FLAG_log) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "new" << kNext << name << kNext << object << kNext
|
|
<< static_cast<unsigned int>(size);
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
|
|
void Logger::DeleteEvent(const char* name, void* object) {
|
|
if (!log_->IsEnabled() || !FLAG_log) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "delete" << kNext << name << kNext << object;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::CallbackEventInternal(const char* prefix, Name name,
|
|
Address entry_point) {
|
|
if (!FLAG_log_code || !log_->IsEnabled()) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT] << kNext
|
|
<< kLogEventsNames[CodeEventListener::CALLBACK_TAG] << kNext << -2
|
|
<< kNext << timer_.Elapsed().InMicroseconds() << kNext
|
|
<< reinterpret_cast<void*>(entry_point) << kNext << 1 << kNext << prefix
|
|
<< name;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::CallbackEvent(Name name, Address entry_point) {
|
|
CallbackEventInternal("", name, entry_point);
|
|
}
|
|
|
|
void Logger::GetterCallbackEvent(Name name, Address entry_point) {
|
|
CallbackEventInternal("get ", name, entry_point);
|
|
}
|
|
|
|
void Logger::SetterCallbackEvent(Name name, Address entry_point) {
|
|
CallbackEventInternal("set ", name, entry_point);
|
|
}
|
|
|
|
namespace {
|
|
|
|
void AppendCodeCreateHeader(Log::MessageBuilder& msg,
|
|
CodeEventListener::LogEventsAndTags tag,
|
|
AbstractCode::Kind kind, uint8_t* address, int size,
|
|
base::ElapsedTimer* timer) {
|
|
msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT]
|
|
<< Logger::kNext << kLogEventsNames[tag] << Logger::kNext << kind
|
|
<< Logger::kNext << timer->Elapsed().InMicroseconds() << Logger::kNext
|
|
<< reinterpret_cast<void*>(address) << Logger::kNext << size
|
|
<< Logger::kNext;
|
|
}
|
|
|
|
void AppendCodeCreateHeader(Log::MessageBuilder& msg,
|
|
CodeEventListener::LogEventsAndTags tag,
|
|
AbstractCode code, base::ElapsedTimer* timer) {
|
|
AppendCodeCreateHeader(msg, tag, code->kind(),
|
|
reinterpret_cast<uint8_t*>(code->InstructionStart()),
|
|
code->InstructionSize(), timer);
|
|
}
|
|
|
|
} // namespace
|
|
|
|
void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
|
|
AbstractCode code, const char* comment) {
|
|
if (!is_listening_to_code_events()) return;
|
|
if (!FLAG_log_code || !log_->IsEnabled()) return;
|
|
Log::MessageBuilder msg(log_);
|
|
AppendCodeCreateHeader(msg, tag, code, &timer_);
|
|
msg << comment;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
|
|
AbstractCode code, Name name) {
|
|
if (!is_listening_to_code_events()) return;
|
|
if (!FLAG_log_code || !log_->IsEnabled()) return;
|
|
Log::MessageBuilder msg(log_);
|
|
AppendCodeCreateHeader(msg, tag, code, &timer_);
|
|
msg << name;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
|
|
AbstractCode code, SharedFunctionInfo shared,
|
|
Name name) {
|
|
if (!is_listening_to_code_events()) return;
|
|
if (!FLAG_log_code || !log_->IsEnabled()) return;
|
|
if (code == AbstractCode::cast(
|
|
isolate_->builtins()->builtin(Builtins::kCompileLazy))) {
|
|
return;
|
|
}
|
|
|
|
Log::MessageBuilder msg(log_);
|
|
AppendCodeCreateHeader(msg, tag, code, &timer_);
|
|
msg << name << kNext << reinterpret_cast<void*>(shared->address()) << kNext
|
|
<< ComputeMarker(shared, code);
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
|
|
const wasm::WasmCode* code, wasm::WasmName name) {
|
|
if (!is_listening_to_code_events()) return;
|
|
if (!FLAG_log_code || !log_->IsEnabled()) return;
|
|
Log::MessageBuilder msg(log_);
|
|
AppendCodeCreateHeader(msg, tag, AbstractCode::Kind::WASM_FUNCTION,
|
|
code->instructions().start(),
|
|
code->instructions().length(), &timer_);
|
|
if (name.empty()) {
|
|
msg << "<unknown wasm>";
|
|
} else {
|
|
msg.AppendString(name);
|
|
}
|
|
// We have to add two extra fields that allow the tick processor to group
|
|
// events for the same wasm function, even if it gets compiled again. For
|
|
// normal JS functions, we use the shared function info. For wasm, the pointer
|
|
// to the native module + function index works well enough.
|
|
// TODO(herhut) Clean up the tick processor code instead.
|
|
void* tag_ptr =
|
|
reinterpret_cast<byte*>(code->native_module()) + code->index();
|
|
msg << kNext << tag_ptr << kNext << ComputeMarker(code);
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
// Although, it is possible to extract source and line from
|
|
// the SharedFunctionInfo object, we left it to caller
|
|
// to leave logging functions free from heap allocations.
|
|
void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
|
|
AbstractCode code, SharedFunctionInfo shared,
|
|
Name source, int line, int column) {
|
|
if (!is_listening_to_code_events()) return;
|
|
if (!FLAG_log_code || !log_->IsEnabled()) return;
|
|
{
|
|
Log::MessageBuilder msg(log_);
|
|
AppendCodeCreateHeader(msg, tag, code, &timer_);
|
|
msg << shared->DebugName() << " " << source << ":" << line << ":" << column
|
|
<< kNext << reinterpret_cast<void*>(shared->address()) << kNext
|
|
<< ComputeMarker(shared, code);
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
if (!FLAG_log_source_code) return;
|
|
Object script_object = shared->script();
|
|
if (!script_object->IsScript()) return;
|
|
Script script = Script::cast(script_object);
|
|
if (!EnsureLogScriptSource(script)) return;
|
|
|
|
// We log source code information in the form:
|
|
//
|
|
// code-source-info <addr>,<script>,<start>,<end>,<pos>,<inline-pos>,<fns>
|
|
//
|
|
// where
|
|
// <addr> is code object address
|
|
// <script> is script id
|
|
// <start> is the starting position inside the script
|
|
// <end> is the end position inside the script
|
|
// <pos> is source position table encoded in the string,
|
|
// it is a sequence of C<code-offset>O<script-offset>[I<inlining-id>]
|
|
// where
|
|
// <code-offset> is the offset within the code object
|
|
// <script-offset> is the position within the script
|
|
// <inlining-id> is the offset in the <inlining> table
|
|
// <inlining> table is a sequence of strings of the form
|
|
// F<function-id>O<script-offset>[I<inlining-id>]
|
|
// where
|
|
// <function-id> is an index into the <fns> function table
|
|
// <fns> is the function table encoded as a sequence of strings
|
|
// S<shared-function-info-address>
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "code-source-info" << kNext
|
|
<< reinterpret_cast<void*>(code->InstructionStart()) << kNext
|
|
<< script->id() << kNext << shared->StartPosition() << kNext
|
|
<< shared->EndPosition() << kNext;
|
|
|
|
SourcePositionTableIterator iterator(code->source_position_table());
|
|
bool hasInlined = false;
|
|
for (; !iterator.done(); iterator.Advance()) {
|
|
SourcePosition pos = iterator.source_position();
|
|
msg << "C" << iterator.code_offset() << "O" << pos.ScriptOffset();
|
|
if (pos.isInlined()) {
|
|
msg << "I" << pos.InliningId();
|
|
hasInlined = true;
|
|
}
|
|
}
|
|
msg << kNext;
|
|
int maxInlinedId = -1;
|
|
if (hasInlined) {
|
|
PodArray<InliningPosition> inlining_positions =
|
|
DeoptimizationData::cast(Code::cast(code)->deoptimization_data())
|
|
->InliningPositions();
|
|
for (int i = 0; i < inlining_positions->length(); i++) {
|
|
InliningPosition inlining_pos = inlining_positions->get(i);
|
|
msg << "F";
|
|
if (inlining_pos.inlined_function_id != -1) {
|
|
msg << inlining_pos.inlined_function_id;
|
|
if (inlining_pos.inlined_function_id > maxInlinedId) {
|
|
maxInlinedId = inlining_pos.inlined_function_id;
|
|
}
|
|
}
|
|
SourcePosition pos = inlining_pos.position;
|
|
msg << "O" << pos.ScriptOffset();
|
|
if (pos.isInlined()) {
|
|
msg << "I" << pos.InliningId();
|
|
}
|
|
}
|
|
}
|
|
msg << kNext;
|
|
if (hasInlined) {
|
|
DeoptimizationData deopt_data =
|
|
DeoptimizationData::cast(Code::cast(code)->deoptimization_data());
|
|
|
|
msg << std::hex;
|
|
for (int i = 0; i <= maxInlinedId; i++) {
|
|
msg << "S"
|
|
<< reinterpret_cast<void*>(
|
|
deopt_data->GetInlinedFunction(i)->address());
|
|
}
|
|
msg << std::dec;
|
|
}
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::CodeDisableOptEvent(AbstractCode code, SharedFunctionInfo shared) {
|
|
if (!is_listening_to_code_events()) return;
|
|
if (!FLAG_log_code || !log_->IsEnabled()) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT] << kNext
|
|
<< shared->DebugName() << kNext
|
|
<< GetBailoutReason(shared->disable_optimization_reason());
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::CodeMovingGCEvent() {
|
|
if (!is_listening_to_code_events()) return;
|
|
if (!log_->IsEnabled() || !FLAG_ll_prof) return;
|
|
base::OS::SignalCodeMovingGC();
|
|
}
|
|
|
|
void Logger::RegExpCodeCreateEvent(AbstractCode code, String source) {
|
|
if (!is_listening_to_code_events()) return;
|
|
if (!FLAG_log_code || !log_->IsEnabled()) return;
|
|
Log::MessageBuilder msg(log_);
|
|
AppendCodeCreateHeader(msg, CodeEventListener::REG_EXP_TAG, code, &timer_);
|
|
msg << source;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::CodeMoveEvent(AbstractCode from, AbstractCode to) {
|
|
if (!is_listening_to_code_events()) return;
|
|
MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from->address(),
|
|
to->address());
|
|
}
|
|
|
|
namespace {
|
|
|
|
void CodeLinePosEvent(JitLogger* jit_logger, Address code_start,
|
|
SourcePositionTableIterator& iter) {
|
|
if (jit_logger) {
|
|
void* jit_handler_data = jit_logger->StartCodePosInfoEvent();
|
|
for (; !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_start, jit_handler_data);
|
|
}
|
|
}
|
|
|
|
} // namespace
|
|
|
|
void Logger::CodeLinePosInfoRecordEvent(Address code_start,
|
|
ByteArray source_position_table) {
|
|
SourcePositionTableIterator iter(source_position_table);
|
|
CodeLinePosEvent(jit_logger_.get(), code_start, iter);
|
|
}
|
|
|
|
void Logger::CodeLinePosInfoRecordEvent(
|
|
Address code_start, Vector<const byte> source_position_table) {
|
|
SourcePositionTableIterator iter(source_position_table);
|
|
CodeLinePosEvent(jit_logger_.get(), code_start, iter);
|
|
}
|
|
|
|
void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
|
|
if (code_name == nullptr) return; // Not a code object.
|
|
Log::MessageBuilder msg(log_);
|
|
msg << kLogEventsNames[CodeEventListener::SNAPSHOT_CODE_NAME_EVENT] << kNext
|
|
<< pos << kNext << code_name;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
|
|
void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
|
|
if (!is_listening_to_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 << kLogEventsNames[event] << kNext << reinterpret_cast<void*>(from)
|
|
<< kNext << reinterpret_cast<void*>(to);
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
|
|
void Logger::ResourceEvent(const char* name, const char* tag) {
|
|
if (!log_->IsEnabled() || !FLAG_log) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << name << kNext << tag << kNext;
|
|
|
|
uint32_t sec, usec;
|
|
if (base::OS::GetUserTime(&sec, &usec) != -1) {
|
|
msg << sec << kNext << usec << kNext;
|
|
}
|
|
msg.AppendFormatString("%.0f",
|
|
V8::GetCurrentPlatform()->CurrentClockTimeMillis());
|
|
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()
|
|
: ReadOnlyRoots(isolate_).empty_string();
|
|
msg << "suspect-read" << kNext << class_name << kNext << name;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
namespace {
|
|
void AppendFunctionMessage(Log::MessageBuilder& msg, const char* reason,
|
|
int script_id, double time_delta, int start_position,
|
|
int end_position, base::ElapsedTimer* timer) {
|
|
msg << "function" << Logger::kNext << reason << Logger::kNext << script_id
|
|
<< Logger::kNext << start_position << Logger::kNext << end_position
|
|
<< Logger::kNext << time_delta << Logger::kNext
|
|
<< timer->Elapsed().InMicroseconds() << Logger::kNext;
|
|
}
|
|
} // namespace
|
|
|
|
void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
|
|
int start_position, int end_position,
|
|
String function_name) {
|
|
if (!log_->IsEnabled() || !FLAG_log_function_events) return;
|
|
Log::MessageBuilder msg(log_);
|
|
AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
|
|
end_position, &timer_);
|
|
if (!function_name.is_null()) msg << function_name;
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
|
|
int start_position, int end_position,
|
|
const char* function_name,
|
|
size_t function_name_length) {
|
|
if (!log_->IsEnabled() || !FLAG_log_function_events) return;
|
|
Log::MessageBuilder msg(log_);
|
|
AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
|
|
end_position, &timer_);
|
|
if (function_name_length > 0) {
|
|
msg.AppendString(function_name, function_name_length);
|
|
}
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::CompilationCacheEvent(const char* action, const char* cache_type,
|
|
SharedFunctionInfo sfi) {
|
|
if (!log_->IsEnabled() || !FLAG_log_function_events) return;
|
|
Log::MessageBuilder msg(log_);
|
|
int script_id = -1;
|
|
if (sfi->script()->IsScript()) {
|
|
script_id = Script::cast(sfi->script())->id();
|
|
}
|
|
msg << "compilation-cache" << Logger::kNext << action << Logger::kNext
|
|
<< cache_type << Logger::kNext << script_id << Logger::kNext
|
|
<< sfi->StartPosition() << Logger::kNext << sfi->EndPosition()
|
|
<< Logger::kNext << timer_.Elapsed().InMicroseconds();
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::ScriptEvent(ScriptEventType type, int script_id) {
|
|
if (!log_->IsEnabled() || !FLAG_log_function_events) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "script" << Logger::kNext;
|
|
switch (type) {
|
|
case ScriptEventType::kReserveId:
|
|
msg << "reserve-id";
|
|
break;
|
|
case ScriptEventType::kCreate:
|
|
msg << "create";
|
|
break;
|
|
case ScriptEventType::kDeserialize:
|
|
msg << "deserialize";
|
|
break;
|
|
case ScriptEventType::kBackgroundCompile:
|
|
msg << "background-compile";
|
|
break;
|
|
case ScriptEventType::kStreamingCompile:
|
|
msg << "streaming-compile";
|
|
break;
|
|
}
|
|
msg << Logger::kNext << script_id << Logger::kNext
|
|
<< timer_.Elapsed().InMicroseconds();
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::ScriptDetails(Script script) {
|
|
if (!log_->IsEnabled() || !FLAG_log_function_events) return;
|
|
{
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "script-details" << Logger::kNext << script->id() << Logger::kNext;
|
|
if (script->name()->IsString()) {
|
|
msg << String::cast(script->name());
|
|
}
|
|
msg << Logger::kNext << script->line_offset() << Logger::kNext
|
|
<< script->column_offset() << Logger::kNext;
|
|
if (script->source_mapping_url()->IsString()) {
|
|
msg << String::cast(script->source_mapping_url());
|
|
}
|
|
msg.WriteToLogFile();
|
|
}
|
|
EnsureLogScriptSource(script);
|
|
}
|
|
|
|
bool Logger::EnsureLogScriptSource(Script script) {
|
|
if (!log_->IsEnabled()) return false;
|
|
Log::MessageBuilder msg(log_);
|
|
// Make sure the script is written to the log file.
|
|
int script_id = script->id();
|
|
if (logged_source_code_.find(script_id) != logged_source_code_.end()) {
|
|
return true;
|
|
}
|
|
// This script has not been logged yet.
|
|
logged_source_code_.insert(script_id);
|
|
Object source_object = script->source();
|
|
if (!source_object->IsString()) return false;
|
|
String source_code = String::cast(source_object);
|
|
msg << "script-source" << kNext << script_id << kNext;
|
|
|
|
// Log the script name.
|
|
if (script->name()->IsString()) {
|
|
msg << String::cast(script->name()) << kNext;
|
|
} else {
|
|
msg << "<unknown>" << kNext;
|
|
}
|
|
|
|
// Log the source code.
|
|
msg << source_code;
|
|
msg.WriteToLogFile();
|
|
return true;
|
|
}
|
|
|
|
void Logger::RuntimeCallTimerEvent() {
|
|
RuntimeCallStats* stats = isolate_->counters()->runtime_call_stats();
|
|
RuntimeCallCounter* counter = stats->current_counter();
|
|
if (counter == nullptr) return;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "active-runtime-timer" << kNext << counter->name();
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::TickEvent(v8::TickSample* sample, bool overflow) {
|
|
if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
|
|
if (V8_UNLIKELY(TracingFlags::runtime_stats.load(std::memory_order_relaxed) ==
|
|
v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE)) {
|
|
RuntimeCallTimerEvent();
|
|
}
|
|
Log::MessageBuilder msg(log_);
|
|
msg << kLogEventsNames[CodeEventListener::TICK_EVENT] << kNext
|
|
<< reinterpret_cast<void*>(sample->pc) << kNext
|
|
<< timer_.Elapsed().InMicroseconds();
|
|
if (sample->has_external_callback) {
|
|
msg << kNext << 1 << kNext
|
|
<< reinterpret_cast<void*>(sample->external_callback_entry);
|
|
} else {
|
|
msg << kNext << 0 << kNext << reinterpret_cast<void*>(sample->tos);
|
|
}
|
|
msg << kNext << static_cast<int>(sample->state);
|
|
if (overflow) msg << kNext << "overflow";
|
|
for (unsigned i = 0; i < sample->frames_count; ++i) {
|
|
msg << kNext << reinterpret_cast<void*>(sample->stack[i]);
|
|
}
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::ICEvent(const char* type, bool keyed, 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 << "Keyed";
|
|
int line;
|
|
int column;
|
|
Address pc = isolate_->GetAbstractPC(&line, &column);
|
|
msg << type << kNext << reinterpret_cast<void*>(pc) << kNext << line << kNext
|
|
<< column << kNext << old_state << kNext << new_state << kNext
|
|
<< AsHex::Address(map.ptr()) << kNext;
|
|
if (key->IsSmi()) {
|
|
msg << Smi::ToInt(key);
|
|
} else if (key->IsNumber()) {
|
|
msg << key->Number();
|
|
} else if (key->IsName()) {
|
|
msg << Name::cast(key);
|
|
}
|
|
msg << kNext << modifier << kNext;
|
|
if (slow_stub_reason != nullptr) {
|
|
msg << slow_stub_reason;
|
|
}
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::MapEvent(const char* type, Map from, Map to, const char* reason,
|
|
HeapObject name_or_sfi) {
|
|
DisallowHeapAllocation no_gc;
|
|
if (!log_->IsEnabled() || !FLAG_trace_maps) return;
|
|
if (!to.is_null()) MapDetails(to);
|
|
int line = -1;
|
|
int column = -1;
|
|
Address pc = 0;
|
|
|
|
if (!isolate_->bootstrapper()->IsActive()) {
|
|
pc = isolate_->GetAbstractPC(&line, &column);
|
|
}
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "map" << kNext << type << kNext << timer_.Elapsed().InMicroseconds()
|
|
<< kNext << AsHex::Address(from.ptr()) << kNext
|
|
<< AsHex::Address(to.ptr()) << kNext << AsHex::Address(pc) << kNext
|
|
<< line << kNext << column << kNext << reason << kNext;
|
|
|
|
if (!name_or_sfi.is_null()) {
|
|
if (name_or_sfi->IsName()) {
|
|
msg << Name::cast(name_or_sfi);
|
|
} else if (name_or_sfi->IsSharedFunctionInfo()) {
|
|
SharedFunctionInfo sfi = SharedFunctionInfo::cast(name_or_sfi);
|
|
msg << sfi->DebugName();
|
|
#if V8_SFI_HAS_UNIQUE_ID
|
|
msg << " " << SharedFunctionInfoWithID::cast(sfi)->unique_id();
|
|
#endif // V8_SFI_HAS_UNIQUE_ID
|
|
}
|
|
}
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::MapCreate(Map map) {
|
|
if (!log_->IsEnabled() || !FLAG_trace_maps) return;
|
|
DisallowHeapAllocation no_gc;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "map-create" << kNext << timer_.Elapsed().InMicroseconds() << kNext
|
|
<< AsHex::Address(map.ptr());
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
void Logger::MapDetails(Map map) {
|
|
if (!log_->IsEnabled() || !FLAG_trace_maps) return;
|
|
DisallowHeapAllocation no_gc;
|
|
Log::MessageBuilder msg(log_);
|
|
msg << "map-details" << kNext << timer_.Elapsed().InMicroseconds() << kNext
|
|
<< AsHex::Address(map.ptr()) << kNext;
|
|
if (FLAG_trace_maps_details) {
|
|
std::ostringstream buffer;
|
|
map->PrintMapDetails(buffer);
|
|
msg << buffer.str().c_str();
|
|
}
|
|
msg.WriteToLogFile();
|
|
}
|
|
|
|
static void AddFunctionAndCode(SharedFunctionInfo sfi, AbstractCode code_object,
|
|
Handle<SharedFunctionInfo>* sfis,
|
|
Handle<AbstractCode>* code_objects, int offset) {
|
|
if (sfis != nullptr) {
|
|
sfis[offset] = Handle<SharedFunctionInfo>(sfi, sfi->GetIsolate());
|
|
}
|
|
if (code_objects != nullptr) {
|
|
code_objects[offset] = Handle<AbstractCode>(code_object, sfi->GetIsolate());
|
|
}
|
|
}
|
|
|
|
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.is_null();
|
|
obj = iterator.next()) {
|
|
if (obj->IsSharedFunctionInfo()) {
|
|
SharedFunctionInfo sfi = SharedFunctionInfo::cast(obj);
|
|
if (sfi->is_compiled() &&
|
|
(!sfi->script()->IsScript() ||
|
|
Script::cast(sfi->script())->HasValidSource())) {
|
|
AddFunctionAndCode(sfi, AbstractCode::cast(sfi->abstract_code()), sfis,
|
|
code_objects, compiled_funcs_count);
|
|
++compiled_funcs_count;
|
|
}
|
|
} else if (obj->IsJSFunction()) {
|
|
// Given that we no longer iterate over all optimized JSFunctions, we need
|
|
// to take care of this here.
|
|
JSFunction function = JSFunction::cast(obj);
|
|
SharedFunctionInfo sfi = SharedFunctionInfo::cast(function->shared());
|
|
Object maybe_script = sfi->script();
|
|
if (maybe_script->IsScript() &&
|
|
!Script::cast(maybe_script)->HasValidSource()) {
|
|
continue;
|
|
}
|
|
// TODO(jarin) This leaves out deoptimized code that might still be on the
|
|
// stack. Also note that we will not log optimized code objects that are
|
|
// only on a type feedback vector. We should make this mroe precise.
|
|
if (function->IsOptimized()) {
|
|
AddFunctionAndCode(sfi, AbstractCode::cast(function->code()), sfis,
|
|
code_objects, compiled_funcs_count);
|
|
++compiled_funcs_count;
|
|
}
|
|
}
|
|
}
|
|
return compiled_funcs_count;
|
|
}
|
|
|
|
static int EnumerateWasmModuleObjects(
|
|
Heap* heap, Handle<WasmModuleObject>* module_objects) {
|
|
HeapIterator iterator(heap);
|
|
DisallowHeapAllocation no_gc;
|
|
int module_objects_count = 0;
|
|
|
|
for (HeapObject obj = iterator.next(); !obj.is_null();
|
|
obj = iterator.next()) {
|
|
if (obj->IsWasmModuleObject()) {
|
|
WasmModuleObject module = WasmModuleObject::cast(obj);
|
|
if (module_objects != nullptr) {
|
|
module_objects[module_objects_count] =
|
|
handle(module, Isolate::FromHeap(heap));
|
|
}
|
|
module_objects_count++;
|
|
}
|
|
}
|
|
return module_objects_count;
|
|
}
|
|
|
|
void Logger::LogCodeObject(Object object) {
|
|
existing_code_logger_.LogCodeObject(object);
|
|
}
|
|
|
|
void Logger::LogCodeObjects() { existing_code_logger_.LogCodeObjects(); }
|
|
|
|
void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
|
|
Handle<AbstractCode> code) {
|
|
existing_code_logger_.LogExistingFunction(shared, code);
|
|
}
|
|
|
|
void Logger::LogCompiledFunctions() {
|
|
existing_code_logger_.LogCompiledFunctions();
|
|
}
|
|
|
|
void Logger::LogAccessorCallbacks() {
|
|
Heap* heap = isolate_->heap();
|
|
HeapIterator iterator(heap);
|
|
DisallowHeapAllocation no_gc;
|
|
for (HeapObject obj = iterator.next(); !obj.is_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));
|
|
}
|
|
}
|
|
}
|
|
|
|
void Logger::LogAllMaps() {
|
|
DisallowHeapAllocation no_gc;
|
|
Heap* heap = isolate_->heap();
|
|
HeapIterator iterator(heap);
|
|
for (HeapObject obj = iterator.next(); !obj.is_null();
|
|
obj = iterator.next()) {
|
|
if (!obj->IsMap()) continue;
|
|
Map map = Map::cast(obj);
|
|
MapCreate(map);
|
|
MapDetails(map);
|
|
}
|
|
}
|
|
|
|
static void AddIsolateIdIfNeeded(std::ostream& os, // NOLINT
|
|
Isolate* isolate) {
|
|
if (FLAG_logfile_per_isolate) {
|
|
os << "isolate-" << isolate << "-" << base::OS::GetCurrentProcessId()
|
|
<< "-";
|
|
}
|
|
}
|
|
|
|
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>(
|
|
V8::GetCurrentPlatform()->CurrentClockTimeMillis());
|
|
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;
|
|
std::ostringstream source_log_file_name;
|
|
PrepareLogFileName(log_file_name, isolate, FLAG_logfile);
|
|
log_ = new Log(this, log_file_name.str().c_str());
|
|
|
|
if (FLAG_perf_basic_prof) {
|
|
perf_basic_logger_.reset(new PerfBasicLogger(isolate));
|
|
AddCodeEventListener(perf_basic_logger_.get());
|
|
}
|
|
|
|
if (FLAG_perf_prof) {
|
|
perf_jit_logger_.reset(new PerfJitLogger(isolate));
|
|
AddCodeEventListener(perf_jit_logger_.get());
|
|
}
|
|
|
|
if (FLAG_ll_prof) {
|
|
ll_logger_.reset(new LowLevelLogger(isolate, log_file_name.str().c_str()));
|
|
AddCodeEventListener(ll_logger_.get());
|
|
}
|
|
|
|
ticker_.reset(new Ticker(isolate, FLAG_prof_sampling_interval));
|
|
|
|
if (Log::InitLogAtStart()) {
|
|
is_logging_ = true;
|
|
}
|
|
|
|
timer_.Start();
|
|
|
|
if (FLAG_prof_cpp) {
|
|
profiler_.reset(new Profiler(isolate));
|
|
is_logging_ = true;
|
|
profiler_->Engage();
|
|
}
|
|
|
|
if (is_logging_) {
|
|
AddCodeEventListener(this);
|
|
}
|
|
|
|
return true;
|
|
}
|
|
|
|
|
|
void Logger::SetCodeEventHandler(uint32_t options,
|
|
JitCodeEventHandler event_handler) {
|
|
if (jit_logger_) {
|
|
RemoveCodeEventListener(jit_logger_.get());
|
|
jit_logger_.reset();
|
|
}
|
|
|
|
if (event_handler) {
|
|
if (isolate_->wasm_engine() != nullptr) {
|
|
isolate_->wasm_engine()->EnableCodeLogging(isolate_);
|
|
}
|
|
jit_logger_.reset(new JitLogger(isolate_, event_handler));
|
|
AddCodeEventListener(jit_logger_.get());
|
|
if (options & kJitCodeEventEnumExisting) {
|
|
HandleScope scope(isolate_);
|
|
LogCodeObjects();
|
|
LogCompiledFunctions();
|
|
}
|
|
}
|
|
}
|
|
|
|
sampler::Sampler* Logger::sampler() { return ticker_.get(); }
|
|
|
|
void Logger::StopProfilerThread() {
|
|
if (profiler_ != nullptr) {
|
|
profiler_->Disengage();
|
|
profiler_.reset();
|
|
}
|
|
}
|
|
|
|
FILE* Logger::TearDown() {
|
|
if (!is_initialized_) return nullptr;
|
|
is_initialized_ = false;
|
|
|
|
// Stop the profiler thread before closing the file.
|
|
StopProfilerThread();
|
|
|
|
ticker_.reset();
|
|
|
|
if (perf_basic_logger_) {
|
|
RemoveCodeEventListener(perf_basic_logger_.get());
|
|
perf_basic_logger_.reset();
|
|
}
|
|
|
|
if (perf_jit_logger_) {
|
|
RemoveCodeEventListener(perf_jit_logger_.get());
|
|
perf_jit_logger_.reset();
|
|
}
|
|
|
|
if (ll_logger_) {
|
|
RemoveCodeEventListener(ll_logger_.get());
|
|
ll_logger_.reset();
|
|
}
|
|
|
|
if (jit_logger_) {
|
|
RemoveCodeEventListener(jit_logger_.get());
|
|
jit_logger_.reset();
|
|
}
|
|
|
|
return log_->Close();
|
|
}
|
|
|
|
void ExistingCodeLogger::LogCodeObject(Object object) {
|
|
AbstractCode abstract_code = AbstractCode::cast(object);
|
|
CodeEventListener::LogEventsAndTags tag = CodeEventListener::STUB_TAG;
|
|
const char* description = "Unknown code from before profiling";
|
|
switch (abstract_code->kind()) {
|
|
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::STUB:
|
|
description = "STUB code";
|
|
tag = CodeEventListener::STUB_TAG;
|
|
break;
|
|
case AbstractCode::REGEXP:
|
|
description = "Regular expression code";
|
|
tag = CodeEventListener::REG_EXP_TAG;
|
|
break;
|
|
case AbstractCode::BUILTIN:
|
|
if (Code::cast(object)->is_interpreter_trampoline_builtin() &&
|
|
Code::cast(object) !=
|
|
*BUILTIN_CODE(isolate_, InterpreterEntryTrampoline)) {
|
|
return;
|
|
}
|
|
description =
|
|
isolate_->builtins()->name(abstract_code->GetCode()->builtin_index());
|
|
tag = CodeEventListener::BUILTIN_TAG;
|
|
break;
|
|
case AbstractCode::WASM_FUNCTION:
|
|
description = "A Wasm function";
|
|
tag = CodeEventListener::FUNCTION_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::C_WASM_ENTRY:
|
|
description = "A C to Wasm entry stub";
|
|
tag = CodeEventListener::STUB_TAG;
|
|
break;
|
|
case AbstractCode::NUMBER_OF_KINDS:
|
|
UNIMPLEMENTED();
|
|
}
|
|
CALL_CODE_EVENT_HANDLER(CodeCreateEvent(tag, abstract_code, description))
|
|
}
|
|
|
|
void ExistingCodeLogger::LogCodeObjects() {
|
|
Heap* heap = isolate_->heap();
|
|
HeapIterator iterator(heap);
|
|
DisallowHeapAllocation no_gc;
|
|
for (HeapObject obj = iterator.next(); !obj.is_null();
|
|
obj = iterator.next()) {
|
|
if (obj->IsCode()) LogCodeObject(obj);
|
|
if (obj->IsBytecodeArray()) LogCodeObject(obj);
|
|
}
|
|
}
|
|
|
|
void ExistingCodeLogger::LogCompiledFunctions() {
|
|
Heap* heap = isolate_->heap();
|
|
HandleScope scope(isolate_);
|
|
const int compiled_funcs_count =
|
|
EnumerateCompiledFunctions(heap, nullptr, nullptr);
|
|
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) {
|
|
SharedFunctionInfo::EnsureSourcePositionsAvailable(isolate_, sfis[i]);
|
|
if (sfis[i]->function_data()->IsInterpreterData()) {
|
|
LogExistingFunction(
|
|
sfis[i],
|
|
Handle<AbstractCode>(
|
|
AbstractCode::cast(sfis[i]->InterpreterTrampoline()), isolate_),
|
|
CodeEventListener::INTERPRETED_FUNCTION_TAG);
|
|
}
|
|
if (code_objects[i].is_identical_to(BUILTIN_CODE(isolate_, CompileLazy)))
|
|
continue;
|
|
LogExistingFunction(sfis[i], code_objects[i]);
|
|
}
|
|
|
|
const int wasm_module_objects_count =
|
|
EnumerateWasmModuleObjects(heap, nullptr);
|
|
std::unique_ptr<Handle<WasmModuleObject>[]> module_objects(
|
|
new Handle<WasmModuleObject>[wasm_module_objects_count]);
|
|
EnumerateWasmModuleObjects(heap, module_objects.get());
|
|
for (int i = 0; i < wasm_module_objects_count; ++i) {
|
|
module_objects[i]->native_module()->LogWasmCodes(isolate_);
|
|
}
|
|
}
|
|
|
|
void ExistingCodeLogger::LogExistingFunction(
|
|
Handle<SharedFunctionInfo> shared, Handle<AbstractCode> code,
|
|
CodeEventListener::LogEventsAndTags tag) {
|
|
if (shared->script()->IsScript()) {
|
|
Handle<Script> script(Script::cast(shared->script()), isolate_);
|
|
int line_num = Script::GetLineNumber(script, shared->StartPosition()) + 1;
|
|
int column_num =
|
|
Script::GetColumnNumber(script, shared->StartPosition()) + 1;
|
|
if (script->name()->IsString()) {
|
|
Handle<String> script_name(String::cast(script->name()), isolate_);
|
|
if (line_num > 0) {
|
|
CALL_CODE_EVENT_HANDLER(
|
|
CodeCreateEvent(Logger::ToNativeByScript(tag, *script), *code,
|
|
*shared, *script_name, line_num, column_num))
|
|
} else {
|
|
// Can't distinguish eval and script here, so always use Script.
|
|
CALL_CODE_EVENT_HANDLER(CodeCreateEvent(
|
|
Logger::ToNativeByScript(CodeEventListener::SCRIPT_TAG, *script),
|
|
*code, *shared, *script_name))
|
|
}
|
|
} else {
|
|
CALL_CODE_EVENT_HANDLER(CodeCreateEvent(
|
|
Logger::ToNativeByScript(tag, *script), *code, *shared,
|
|
ReadOnlyRoots(isolate_).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
|
|
CALL_CODE_EVENT_HANDLER(CallbackEvent(shared->DebugName(), entry_point))
|
|
}
|
|
}
|
|
}
|
|
|
|
#undef CALL_CODE_EVENT_HANDLER
|
|
|
|
} // namespace internal
|
|
} // namespace v8
|