AuroraMiddleware/v8
1
0
Fork 0
Code Issues 2 Pull Requests Releases Wiki Activity

[tools][log] Add support for disassembled code

Browse Source 
- Add FLAG_log_code_disassemble
- Add code-disassamble log entries for Code and BytecodeArray
- Add basic code-panel to system-analyzer

Bug: v8:10644
Change-Id: I1abb339a42b55df01265d63d0f0d8c1ac2e041dc
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2565517
Reviewed-by: Sathya Gunasekaran  <gsathya@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/master@{#71556}
This commit is contained in:
Camillo Bruni 2020-12-01 20:37:17 +01:00 committed by Commit Bot
parent 2afb00c0e8
commit c899ad5e5e
10 changed files with 329 additions and 228 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
src/flags/flag-definitions.h
View File

@ -1712,6 +1712,9 @@ DEFINE_BOOL(log_all, false, "Log all events to the log file.")
DEFINE_BOOL(log_api, false, "Log API events to the log file.")
DEFINE_BOOL(log_code, false,
"Log code events to the log file without profiling.")
DEFINE_BOOL(log_code_disassemble, false,
"Log all disassembled code to the log file.")
DEFINE_IMPLICATION(log_code_disassemble, log_code)
DEFINE_BOOL(log_handles, false, "Log global handle events.")
DEFINE_BOOL(log_suspect, false, "Log suspect operations.")
DEFINE_BOOL(log_source_code, false, "Log source code.")
@ -1721,6 +1724,7 @@ DEFINE_BOOL(log_function_events, false,
DEFINE_IMPLICATION(log_all, log_api)
DEFINE_IMPLICATION(log_all, log_code)
DEFINE_IMPLICATION(log_all, log_code_disassemble)
DEFINE_IMPLICATION(log_all, log_suspect)
DEFINE_IMPLICATION(log_all, log_handles)
DEFINE_IMPLICATION(log_all, log_internal_timer_events)

379
src/logging/log.cc
View File

@ -35,6 +35,7 @@
#include "src/logging/log-utils.h"
#include "src/objects/api-callbacks.h"
#include "src/objects/code-kind.h"
#include "src/objects/code.h"
#include "src/profiler/tick-sample.h"
#include "src/snapshot/embedded/embedded-data.h"
#include "src/strings/string-stream.h"
@ -978,6 +979,10 @@ void Profiler::Run() {
//
// Logger class implementation.
//
#define MSG_BUILDER() \
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder(); \
if (!msg_ptr) return; \
Log::MessageBuilder& msg = *msg_ptr.get();
Logger::Logger(Isolate* isolate)
: isolate_(isolate),
@ -1006,9 +1011,7 @@ void Logger::RemoveCodeEventListener(CodeEventListener* listener) {
}
void Logger::ProfilerBeginEvent() {
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "profiler" << kNext << "begin" << kNext << FLAG_prof_sampling_interval;
msg.WriteToLogFile();
}
@ -1018,9 +1021,7 @@ void Logger::StringEvent(const char* name, const char* value) {
}
void Logger::UncheckedStringEvent(const char* name, const char* value) {
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << name << kNext << value;
msg.WriteToLogFile();
}
@ -1030,9 +1031,7 @@ void Logger::IntPtrTEvent(const char* name, intptr_t value) {
}
void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << name << kNext;
msg.AppendFormatString("%" V8PRIdPTR, value);
msg.WriteToLogFile();
@ -1040,18 +1039,14 @@ void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
void Logger::HandleEvent(const char* name, Address* location) {
if (!FLAG_log_handles) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << name << kNext << reinterpret_cast<void*>(location);
msg.WriteToLogFile();
}
void Logger::ApiSecurityCheck() {
if (!FLAG_log_api) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "api" << kNext << "check-security";
msg.WriteToLogFile();
}
@ -1060,9 +1055,7 @@ void Logger::SharedLibraryEvent(const std::string& library_path,
uintptr_t start, uintptr_t end,
intptr_t aslr_slide) {
if (!FLAG_prof_cpp) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "shared-library" << kNext << library_path.c_str() << kNext
<< reinterpret_cast<void*>(start) << kNext << reinterpret_cast<void*>(end)
<< kNext << aslr_slide;
@ -1071,17 +1064,13 @@ void Logger::SharedLibraryEvent(const std::string& library_path,
void Logger::CurrentTimeEvent() {
DCHECK(FLAG_log_internal_timer_events);
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "current-time" << kNext << Time();
msg.WriteToLogFile();
}
void Logger::TimerEvent(Logger::StartEnd se, const char* name) {
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
switch (se) {
case START:
msg << "timer-event-start";
@ -1099,9 +1088,7 @@ void Logger::TimerEvent(Logger::StartEnd se, const char* name) {
void Logger::BasicBlockCounterEvent(const char* name, int block_id,
double count) {
if (!FLAG_turbo_profiling_log_builtins) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << ProfileDataFromFileConstants::kBlockCounterMarker << kNext << name
<< kNext << block_id << kNext << count;
msg.WriteToLogFile();
@ -1109,9 +1096,7 @@ void Logger::BasicBlockCounterEvent(const char* name, int block_id,
void Logger::BuiltinHashEvent(const char* name, int hash) {
if (!FLAG_turbo_profiling_log_builtins) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << ProfileDataFromFileConstants::kBuiltinHashMarker << kNext << name
<< kNext << hash;
msg.WriteToLogFile();
@ -1134,9 +1119,7 @@ void Logger::ApiNamedPropertyAccess(const char* tag, JSObject holder,
Object property_name) {
DCHECK(property_name.IsName());
if (!FLAG_log_api) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "api" << kNext << tag << kNext << holder.class_name() << kNext
<< Name::cast(property_name);
msg.WriteToLogFile();
@ -1145,9 +1128,7 @@ void Logger::ApiNamedPropertyAccess(const char* tag, JSObject holder,
void Logger::ApiIndexedPropertyAccess(const char* tag, JSObject holder,
uint32_t index) {
if (!FLAG_log_api) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "api" << kNext << tag << kNext << holder.class_name() << kNext
<< index;
msg.WriteToLogFile();
@ -1155,27 +1136,21 @@ void Logger::ApiIndexedPropertyAccess(const char* tag, JSObject holder,
void Logger::ApiObjectAccess(const char* tag, JSObject object) {
if (!FLAG_log_api) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "api" << kNext << tag << kNext << object.class_name();
msg.WriteToLogFile();
}
void Logger::ApiEntryCall(const char* name) {
if (!FLAG_log_api) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "api" << kNext << name;
msg.WriteToLogFile();
}
void Logger::NewEvent(const char* name, void* object, size_t size) {
if (!FLAG_log) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "new" << kNext << name << kNext << object << kNext
<< static_cast<unsigned int>(size);
msg.WriteToLogFile();
@ -1183,9 +1158,7 @@ void Logger::NewEvent(const char* name, void* object, size_t size) {
void Logger::DeleteEvent(const char* name, void* object) {
if (!FLAG_log) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "delete" << kNext << name << kNext << object;
msg.WriteToLogFile();
}
@ -1212,103 +1185,40 @@ void AppendCodeCreateHeader(
}
} // namespace
// 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>
void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
const char* name) {
if (!is_listening_to_code_events()) return;
if (!FLAG_log_code) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
AppendCodeCreateHeader(msg, tag, *code, Time());
msg << name;
msg.WriteToLogFile();
}
void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
Handle<Name> name) {
if (!is_listening_to_code_events()) return;
if (!FLAG_log_code) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
AppendCodeCreateHeader(msg, tag, *code, Time());
msg << *name;
msg.WriteToLogFile();
}
void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
Handle<SharedFunctionInfo> shared,
Handle<Name> script_name) {
if (!is_listening_to_code_events()) return;
if (!FLAG_log_code) return;
if (*code == AbstractCode::cast(
isolate_->builtins()->builtin(Builtins::kCompileLazy))) {
return;
}
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
AppendCodeCreateHeader(msg, tag, *code, Time());
msg << *script_name << kNext << reinterpret_cast<void*>(shared->address())
<< kNext << ComputeMarker(*shared, *code);
msg.WriteToLogFile();
}
// Although, it is possible to extract source and line from
// the SharedFunctionInfo object, we left it to caller
// to leave logging functions free from heap allocations.
void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
Handle<SharedFunctionInfo> shared,
Handle<Name> script_name, int line, int column) {
if (!is_listening_to_code_events()) return;
if (!FLAG_log_code) return;
{
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
AppendCodeCreateHeader(msg, tag, *code, Time());
msg << shared->DebugNameCStr().get() << " " << *script_name << ":" << line
<< ":" << column << kNext << reinterpret_cast<void*>(shared->address())
<< kNext << ComputeMarker(*shared, *code);
msg.WriteToLogFile();
}
if (!FLAG_log_source_code) return;
void Logger::LogSourceCodeInformation(Handle<AbstractCode> code,
Handle<SharedFunctionInfo> shared) {
Object script_object = shared->script();
if (!script_object.IsScript()) return;
Script script = Script::cast(script_object);
if (!EnsureLogScriptSource(script)) return;
EnsureLogScriptSource(script);
// 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>
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
msg << "code-source-info" << kNext
<< reinterpret_cast<void*>(code->InstructionStart()) << kNext
<< script.id() << kNext << shared->StartPosition() << kNext
<< shared->EndPosition() << kNext;
MSG_BUILDER();
msg << "code-source-info" << Logger::kNext
<< reinterpret_cast<void*>(code->InstructionStart()) << Logger::kNext
<< script.id() << Logger::kNext << shared->StartPosition()
<< Logger::kNext << shared->EndPosition() << Logger::kNext;
SourcePositionTableIterator iterator(code->source_position_table());
bool hasInlined = false;
@ -1320,7 +1230,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
hasInlined = true;
}
}
msg << kNext;
msg << Logger::kNext;
int maxInlinedId = -1;
if (hasInlined) {
PodArray<InliningPosition> inlining_positions =
@ -1343,11 +1253,10 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
}
}
}
msg << kNext;
msg << Logger::kNext;
if (hasInlined) {
DeoptimizationData deopt_data = DeoptimizationData::cast(
Handle<Code>::cast(code)->deoptimization_data());
msg << std::hex;
for (int i = 0; i <= maxInlinedId; i++) {
msg << "S"
@ -1359,13 +1268,102 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
msg.WriteToLogFile();
}
void Logger::LogCodeDisassemble(Handle<AbstractCode> code) {
if (!FLAG_log_code_disassemble) return;
MSG_BUILDER();
msg << "code-disassemble" << Logger::kNext
<< reinterpret_cast<void*>(code->InstructionStart()) << Logger::kNext
<< CodeKindToString(code->kind()) << Logger::kNext;
{
std::ostringstream stream;
if (code->IsCode()) {
#ifdef ENABLE_DISASSEMBLER
Code::cast(*code).Disassemble(nullptr, stream, isolate_);
#endif
} else {
BytecodeArray::cast(*code).Disassemble(stream);
}
std::string string = stream.str();
msg.AppendString(string.c_str(), string.length());
}
msg.WriteToLogFile();
}
// Builtins and Bytecode handlers
void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
const char* name) {
if (!is_listening_to_code_events()) return;
if (!FLAG_log_code) return;
{
MSG_BUILDER();
AppendCodeCreateHeader(msg, tag, *code, Time());
msg << name;
msg.WriteToLogFile();
}
LogCodeDisassemble(code);
}
void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
Handle<Name> name) {
if (!is_listening_to_code_events()) return;
if (!FLAG_log_code) return;
{
MSG_BUILDER();
AppendCodeCreateHeader(msg, tag, *code, Time());
msg << *name;
msg.WriteToLogFile();
}
LogCodeDisassemble(code);
}
// Scripts
void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
Handle<SharedFunctionInfo> shared,
Handle<Name> script_name) {
if (!is_listening_to_code_events()) return;
if (!FLAG_log_code) return;
if (*code == AbstractCode::cast(
isolate_->builtins()->builtin(Builtins::kCompileLazy))) {
return;
}
{
MSG_BUILDER();
AppendCodeCreateHeader(msg, tag, *code, Time());
msg << *script_name << kNext << reinterpret_cast<void*>(shared->address())
<< kNext << ComputeMarker(*shared, *code);
msg.WriteToLogFile();
}
LogSourceCodeInformation(code, shared);
LogCodeDisassemble(code);
}
// Functions
// 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, Handle<AbstractCode> code,
Handle<SharedFunctionInfo> shared,
Handle<Name> script_name, int line, int column) {
if (!is_listening_to_code_events()) return;
if (!FLAG_log_code) return;
{
MSG_BUILDER();
AppendCodeCreateHeader(msg, tag, *code, Time());
msg << shared->DebugNameCStr().get() << " " << *script_name << ":" << line
<< ":" << column << kNext << reinterpret_cast<void*>(shared->address())
<< kNext << ComputeMarker(*shared, *code);
msg.WriteToLogFile();
}
LogSourceCodeInformation(code, shared);
LogCodeDisassemble(code);
}
void Logger::CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
wasm::WasmName name) {
if (!is_listening_to_code_events()) return;
if (!FLAG_log_code) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
AppendCodeCreateHeader(msg, tag, CodeKind::WASM_FUNCTION,
code->instructions().begin(),
code->instructions().length(), Time());
@ -1386,9 +1384,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
void Logger::CallbackEventInternal(const char* prefix, Handle<Name> name,
Address entry_point) {
if (!FLAG_log_code) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT] << kNext
<< kLogEventsNames[CodeEventListener::CALLBACK_TAG] << kNext << -2
<< kNext << Time() << kNext << reinterpret_cast<void*>(entry_point)
@ -1412,9 +1408,7 @@ void Logger::RegExpCodeCreateEvent(Handle<AbstractCode> code,
Handle<String> source) {
if (!is_listening_to_code_events()) return;
if (!FLAG_log_code) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
AppendCodeCreateHeader(msg, CodeEventListener::REG_EXP_TAG, *code, Time());
msg << *source;
msg.WriteToLogFile();
@ -1441,9 +1435,7 @@ void Logger::CodeDisableOptEvent(Handle<AbstractCode> code,
Handle<SharedFunctionInfo> shared) {
if (!is_listening_to_code_events()) return;
if (!FLAG_log_code) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT] << kNext
<< shared->DebugNameCStr().get() << kNext
<< GetBailoutReason(shared->disable_optimization_reason());
@ -1452,9 +1444,7 @@ void Logger::CodeDisableOptEvent(Handle<AbstractCode> code,
void Logger::ProcessDeoptEvent(Handle<Code> code, SourcePosition position,
const char* kind, const char* reason) {
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "code-deopt" << kNext << Time() << kNext << code->CodeSize() << kNext
<< reinterpret_cast<void*>(code->InstructionStart());
@ -1529,9 +1519,7 @@ void Logger::CodeLinePosInfoRecordEvent(
void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
if (code_name == nullptr) return; // Not a code object.
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << kLogEventsNames[CodeEventListener::SNAPSHOT_CODE_NAME_EVENT] << kNext
<< pos << kNext << code_name;
msg.WriteToLogFile();
@ -1540,9 +1528,7 @@ void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
void Logger::MoveEventInternal(LogEventsAndTags event, Address from,
Address to) {
if (!FLAG_log_code) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << kLogEventsNames[event] << kNext << reinterpret_cast<void*>(from)
<< kNext << reinterpret_cast<void*>(to);
msg.WriteToLogFile();
@ -1550,9 +1536,7 @@ void Logger::MoveEventInternal(LogEventsAndTags event, Address from,
void Logger::ResourceEvent(const char* name, const char* tag) {
if (!FLAG_log) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << name << kNext << tag << kNext;
uint32_t sec, usec;
@ -1566,9 +1550,7 @@ void Logger::ResourceEvent(const char* name, const char* tag) {
void Logger::SuspectReadEvent(Name name, Object obj) {
if (!FLAG_log_suspect) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
String class_name = obj.IsJSObject() ? JSObject::cast(obj).class_name()
: ReadOnlyRoots(isolate_).empty_string();
msg << "suspect-read" << kNext << class_name << kNext << name;
@ -1596,9 +1578,7 @@ void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
int start_position, int end_position,
String function_name) {
if (!FLAG_log_function_events) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
end_position, Time());
if (!function_name.is_null()) msg << function_name;
@ -1610,9 +1590,7 @@ void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
const char* function_name,
size_t function_name_length, bool is_one_byte) {
if (!FLAG_log_function_events) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
end_position, Time());
if (function_name_length > 0) {
@ -1624,9 +1602,7 @@ void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
void Logger::CompilationCacheEvent(const char* action, const char* cache_type,
SharedFunctionInfo sfi) {
if (!FLAG_log_function_events) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
int script_id = -1;
if (sfi.script().IsScript()) {
script_id = Script::cast(sfi.script()).id();
@ -1640,9 +1616,7 @@ void Logger::CompilationCacheEvent(const char* action, const char* cache_type,
void Logger::ScriptEvent(ScriptEventType type, int script_id) {
if (!FLAG_log_function_events) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "script" << Logger::kNext;
switch (type) {
case ScriptEventType::kReserveId:
@ -1668,9 +1642,7 @@ void Logger::ScriptEvent(ScriptEventType type, int script_id) {
void Logger::ScriptDetails(Script script) {
if (!FLAG_log_function_events) return;
{
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "script-details" << Logger::kNext << script.id() << Logger::kNext;
if (script.name().IsString()) {
msg << String::cast(script.name());
@ -1686,9 +1658,6 @@ void Logger::ScriptDetails(Script script) {
}
bool Logger::EnsureLogScriptSource(Script script) {
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return false;
Log::MessageBuilder& msg = *msg_ptr.get();
// 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()) {
@ -1698,6 +1667,11 @@ bool Logger::EnsureLogScriptSource(Script script) {
logged_source_code_.insert(script_id);
Object source_object = script.source();
if (!source_object.IsString()) return false;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return false;
Log::MessageBuilder& msg = *msg_ptr.get();
String source_code = String::cast(source_object);
msg << "script-source" << kNext << script_id << kNext;
@ -1718,9 +1692,7 @@ void Logger::RuntimeCallTimerEvent() {
RuntimeCallStats* stats = isolate_->counters()->runtime_call_stats();
RuntimeCallCounter* counter = stats->current_counter();
if (counter == nullptr) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "active-runtime-timer" << kNext << counter->name();
msg.WriteToLogFile();
}
@ -1731,9 +1703,7 @@ void Logger::TickEvent(TickSample* sample, bool overflow) {
v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE)) {
RuntimeCallTimerEvent();
}
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << kLogEventsNames[CodeEventListener::TICK_EVENT] << kNext
<< reinterpret_cast<void*>(sample->pc) << kNext << Time();
if (sample->has_external_callback) {
@ -1754,9 +1724,7 @@ void Logger::ICEvent(const char* type, bool keyed, Handle<Map> map,
Handle<Object> key, char old_state, char new_state,
const char* modifier, const char* slow_stub_reason) {
if (!FLAG_trace_ic) return;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
if (keyed) msg << "Keyed";
int line;
int column;
@ -1790,9 +1758,7 @@ void Logger::MapEvent(const char* type, Handle<Map> from, Handle<Map> to,
if (!isolate_->bootstrapper()->IsActive()) {
pc = isolate_->GetAbstractPC(&line, &column);
}
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "map" << kNext << type << kNext << Time() << kNext
<< AsHex::Address(from.is_null() ? kNullAddress : from->ptr()) << kNext
<< AsHex::Address(to.is_null() ? kNullAddress : to->ptr()) << kNext
@ -1816,9 +1782,7 @@ void Logger::MapEvent(const char* type, Handle<Map> from, Handle<Map> to,
void Logger::MapCreate(Map map) {
if (!FLAG_trace_maps) return;
DisallowGarbageCollection no_gc;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "map-create" << kNext << Time() << kNext << AsHex::Address(map.ptr());
msg.WriteToLogFile();
}
@ -1826,9 +1790,7 @@ void Logger::MapCreate(Map map) {
void Logger::MapDetails(Map map) {
if (!FLAG_trace_maps) return;
DisallowGarbageCollection no_gc;
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
MSG_BUILDER();
msg << "map-details" << kNext << Time() << kNext << AsHex::Address(map.ptr())
<< kNext;
if (FLAG_trace_maps_details) {
@ -1923,10 +1885,6 @@ static int EnumerateWasmModuleObjects(
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,
@ -2307,6 +2265,7 @@ void ExistingCodeLogger::LogExistingFunction(
}
#undef CALL_CODE_EVENT_HANDLER
#undef MSG_BUILDER
} // namespace internal
} // namespace v8

7
src/logging/log.h
View File

@ -280,9 +280,6 @@ class Logger : public CodeEventListener {
V8_INLINE static CodeEventListener::LogEventsAndTags ToNativeByScript(
CodeEventListener::LogEventsAndTags, Script);
// Used for logging stubs found in the snapshot.
void LogCodeObject(Object code_object);
private:
void UpdateIsLogging(bool value);
@ -314,6 +311,10 @@ class Logger : public CodeEventListener {
// each script is logged only once.
bool EnsureLogScriptSource(Script script);
void LogSourceCodeInformation(Handle<AbstractCode> code,
Handle<SharedFunctionInfo> shared);
void LogCodeDisassemble(Handle<AbstractCode> code);
int64_t Time();
Isolate* isolate_;

31
tools/profile.mjs
View File

@ -86,8 +86,16 @@ export class Script {
}
class SourcePositionInfo{
constructor(script, startPos, endPos, sourcePositionTable, inliningPositions, inlinedFunctions) {
class SourceInfo{
script;
start;
end;
positions;
inlined ;
fns;
disassemble;
setSourcePositionInfo(script, startPos, endPos, sourcePositionTable, inliningPositions, inlinedFunctions) {
this.script = script;
this.start = startPos;
this.end = endPos;
@ -95,6 +103,10 @@ class SourcePositionInfo{
this.inlined = inliningPositions;
this.fns = inlinedFunctions;
}
setDisassemble(code) {
this.disassemble = code;
}
}
/**
@ -297,8 +309,6 @@ export class Profile {
const script = this.getOrCreateScript(scriptId);
const entry = this.codeMap_.findDynamicEntryByStartAddress(start);
if (!entry) return;
const codeId = entry.codeId;
// Resolve the inlined functions list.
if (inlinedFunctions.length > 0) {
inlinedFunctions = inlinedFunctions.substring(1).split("S");
@ -317,12 +327,21 @@ export class Profile {
inlinedFunctions = [];
}
entry.source =
new SourcePositionInfo(
this.getOrCreateSourceInfo(entry).setSourcePositionInfo(
script, startPos, endPos, sourcePositionTable, inliningPositions,
inlinedFunctions);
}
addDisassemble(start, kind, disassemble) {
const entry = this.codeMap_.findDynamicEntryByStartAddress(start);
if (!entry) return;
this.getOrCreateSourceInfo(entry).setDisassemble(disassemble);
}
getOrCreateSourceInfo(entry) {
return entry.source ?? (entry.source = new SourceInfo());
}
addScriptSource(id, url, source) {
const script = this.getOrCreateScript(id);
script.update(url, source);

39
tools/system-analyzer/index.html
View File

@ -20,7 +20,7 @@ found in the LICENSE file. -->
let module = await import('./index.mjs');
globalThis.app = new module.App("#log-file-reader", "#map-panel", "#map-stats-panel",
"#timeline-panel", "#ic-panel", "#map-track", "#ic-track", "#deopt-track",
"#code-track", "#source-panel", "#tool-tip");
"#code-track", "#source-panel", "#code-panel", "#tool-tip");
})();
</script>
@ -110,6 +110,7 @@ found in the LICENSE file. -->
<stats-panel id="map-stats-panel"></stats-panel>
<ic-panel id="ic-panel" onchange="app.handleSelectIc(event)"></ic-panel>
<source-panel id="source-panel"></source-panel>
<code-panel id="code-panel"></code-panel>
</div>
</section>
@ -133,29 +134,53 @@ found in the LICENSE file. -->
For generating a v8.log file from <a href="https://v8.dev/docs/build">d8</a>:
<ul>
<li>
<code>/path/do/d8 --trace-maps --trace_ic --log-source-code $FILE</code>
<code>/path/do/d8 $LOG_FLAGS $FILE</code>
</li>
</ul>
For generating a v8.log file from Chrome:
<ul>
<li>
<code>/path/to/chrome --user-data-dir=/var/tmp/chr$RANDOM --no-sandbox
--js-flags='--trace-ic --trace-maps --log-source-code’
--js-flags='$LOG_FLAGS’
$WEBSITE_URL</code>
</li>
</ul>
<h3>Log Options:</h3>
<h3><code>LOG_FLAGS</code>:</h3>
<dl class="d8-options">
<dt><code>--trace-maps</code></dt>
<dt>
<a href="https://source.chromium.org/search?q=FLAG_log_all">
<code>--log-all</code>
</a>
</dt>
<dd>Enable all V8 logging options.</dd>
<dt>
<a href="https://source.chromium.org/search?q=FLAG_trace_maps">
<code>--trace-maps</code>
</a>
</dt>
<dd>Log<a href="https://v8.dev/blog/fast-properties" target="_blank">
Maps</a></dd>
<dt><code>--trace-ic</code></dt>
<dt>
<a href="https://source.chromium.org/search?q=FLAG_trace_ic">
<code>--trace-ic</code>
</a>
</dt>
<dd>Log
<a href="https://mathiasbynens.be/notes/shapes-ics" target="_blank">
ICs</a></dd>
<dt><code>--log-source-code</code></dt>
<dt>
<a href="https://source.chromium.org/search?q=FLAG_log_source_code">
<code>--log-source-code</code>
</a>
</dt>
<dd>Log source code</dd>
<dt>
<a href="https://source.chromium.org/search?q=FLAG_log_code_disassemble">
<code>--log-code-disassemble</code>
</a>
</dt>
<dd>Log detailed generated generated code</dd>
</dl>
<h3>Keyboard Shortcuts for Navigation</h3>

16
tools/system-analyzer/index.mjs
View File

@ -5,6 +5,7 @@
import {SourcePosition} from '../profile.mjs';
import {State} from './app-model.mjs';
import {CodeLogEntry} from './log/code.mjs';
import {IcLogEntry} from './log/ic.mjs';
import {MapLogEntry} from './log/map.mjs';
import {Processor} from './processor.mjs';
@ -19,7 +20,7 @@ class App {
constructor(
fileReaderId, mapPanelId, mapStatsPanelId, timelinePanelId, icPanelId,
mapTrackId, icTrackId, deoptTrackId, codeTrackId, sourcePanelId,
toolTipId) {
codePanelId, toolTipId) {
this._view = {
__proto__: null,
logFileReader: $(fileReaderId),
@ -32,6 +33,7 @@ class App {
deoptTrack: $(deoptTrackId),
codeTrack: $(codeTrackId),
sourcePanel: $(sourcePanelId),
codePanel: $(codePanelId),
toolTip: $(toolTipId),
};
this.toggleSwitch = $('.theme-switch input[type="checkbox"]');
@ -50,6 +52,7 @@ class App {
import('./view/stats-panel.mjs'),
import('./view/map-panel.mjs'),
import('./view/source-panel.mjs'),
import('./view/code-panel.mjs'),
import('./view/tool-tip.mjs'),
]);
document.addEventListener(
@ -71,6 +74,8 @@ class App {
this.showIcEntries(e.entries);
} else if (entry instanceof SourcePosition) {
this.showSourcePositionEntries(e.entries);
} else if (e.entries[0] instanceof CodeLogEntry) {
this.showCodeEntries(e.entries);
} else {
throw new Error('Unknown selection type!');
}
@ -96,6 +101,7 @@ class App {
showCodeEntries(entries) {
// TODO: creat list panel
this._state.selectedCodeLogEntries = entries;
this._view.codePanel.selectedEntries = entries;
}
showSourcePositionEntries(entries) {
@ -125,6 +131,8 @@ class App {
this.selectICLogEntry(e.entry);
} else if (entry instanceof SourcePosition) {
this.selectSourcePosition(e.entry);
} else if (e.entry instanceof CodeLogEntry) {
this.selectCodeLogEntry(e.entry);
} else {
throw new Error('Unknown selection type!');
}
@ -142,6 +150,11 @@ class App {
this._view.icPanel.selectedEntry = [entry];
}
selectCodeLogEntry(entry) {
this._state.code = entry;
this._view.codePanel.entry = entry;
}
selectSourcePosition(sourcePositions) {
if (!sourcePositions.script) return;
this._view.sourcePanel.selectedSourcePositions = [sourcePositions];
@ -179,6 +192,7 @@ class App {
this._view.mapStatsPanel.timeline = mapTimeline;
this._view.icPanel.timeline = icTimeline;
this._view.sourcePanel.data = processor.scripts;
this._view.codePanel.timeline = codeTimeline;
this.refreshTimelineTrackView();
} catch (e) {
this._view.logFileReader.error = 'Log file contains errors!'

6
tools/system-analyzer/log/code.mjs
View File

@ -15,6 +15,7 @@ export class DeoptLogEntry extends LogEntry {
this._codeSize = codeSize;
this._inliningId = inliningId;
}
toString() {
return `Deopt(${this.type})${this._deoptReason}: ${this._deoptLocation}`;
}
@ -26,7 +27,12 @@ export class CodeLogEntry extends LogEntry {
this._kind = kind;
this._entry = entry;
}
toString() {
return `Code(${this.type}): ${this._entry.toString()}`;
}
get disassemble() {
return this._entry?.source?.disassemble;
}
}

17
tools/system-analyzer/processor.mjs
View File

@ -60,6 +60,14 @@ export class Processor extends LogReader {
],
processor: this.processCodeSourceInfo
},
'code-disassemble': {
parsers: [
parseInt,
parseString,
parseString,
],
processor: this.processCodeDisassemble
},
'script-source': {
parsers: [parseInt, parseString, parseString],
processor: this.processScriptSource
@ -176,15 +184,18 @@ export class Processor extends LogReader {
processCodeCreation(type, kind, timestamp, start, size, name, maybe_func) {
let entry;
let stateName = '';
if (maybe_func.length) {
const funcAddr = parseInt(maybe_func[0]);
stateName = maybe_func[1] ?? '';
const state = Profile.parseState(maybe_func[1]);
entry = this._profile.addFuncCode(
type, name, timestamp, start, size, funcAddr, state);
} else {
entry = this._profile.addCode(type, name, timestamp, start, size);
}
this._codeTimeline.push(new CodeLogEntry(type, timestamp, kind, entry));
this._codeTimeline.push(
new CodeLogEntry(type + stateName, timestamp, kind, entry));
}
processCodeDeopt(
@ -229,6 +240,10 @@ export class Processor extends LogReader {
inlinedFunctions);
}
processCodeDisassemble(start, kind, disassemble) {
this._profile.addDisassemble(start, kind, disassemble);
}
processPropertyIC(
type, pc, time, line, column, old_state, new_state, map, key, modifier,
slow_reason) {

15
tools/system-analyzer/view/code-panel-template.html Normal file
View File

@ -0,0 +1,15 @@
<!-- Copyright 2020 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. -->
<head>
<link href="./index.css" rel="stylesheet">
</head>
<style>
</style>
<div class="panel">
<h2>Code Panel</h2>
<div class="panelBody">
<pre id="code"></pre>
</div>
</div>

43
tools/system-analyzer/view/code-panel.mjs Normal file
View File

@ -0,0 +1,43 @@
// Copyright 2020 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.
import {IcLogEntry} from '../log/ic.mjs';
import {MapLogEntry} from '../log/map.mjs';
import {FocusEvent, SelectionEvent, ToolTipEvent} from './events.mjs';
import {delay, DOM, formatBytes, V8CustomElement} from './helper.mjs';
DOM.defineCustomElement(
'view/code-panel',
(templateText) => class CodePanel extends V8CustomElement {
_timeline;
_selectedEntries;
_entry;
constructor() {
super(templateText);
}
set timeline(timeline) {
this._timeline = timeline;
this.update();
}
set selectedEntries(entries) {
this._selectedEntries = entries;
this.update();
}
set entry(entry) {
this._entry = entry;
this.update();
}
get codeNode() {
return this.$('#code');
}
_update() {
this.codeNode.innerText = this._entry?.disassemble ?? '';
}
});