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

[log] Add predictable logging

Browse Source 
Use monotonic times for logging with --predictable.

Bug: v8:10937, v8:10966, v8:10668
Change-Id: I3d4f0d48375f6f5d9fa375cf5393ff3afee7c0b9
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2465829
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Reviewed-by: Michael Achenbach <machenbach@chromium.org>
Cr-Commit-Position: refs/heads/master@{#70474}
This commit is contained in:
Camillo Bruni 2020-10-12 19:59:21 +02:00 committed by Commit Bot
parent f1ffb4df53
commit 509802fd08
3 changed files with 48 additions and 44 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

87
src/logging/log.cc
View File

@ -993,6 +993,13 @@ Logger::~Logger() = default;
const LogSeparator Logger::kNext = LogSeparator::kSeparator;
int64_t Logger::Time() {
if (V8_UNLIKELY(FLAG_verify_predictable)) {
return isolate_->heap()->MonotonicallyIncreasingTimeInMs() * 1000;
}
return timer_.Elapsed().InMicroseconds();
}
void Logger::AddCodeEventListener(CodeEventListener* listener) {
bool result = isolate_->code_event_dispatcher()->AddListener(listener);
CHECK(result);
@ -1071,7 +1078,7 @@ void Logger::CurrentTimeEvent() {
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
msg << "current-time" << kNext << timer_.Elapsed().InMicroseconds();
msg << "current-time" << kNext << Time();
msg.WriteToLogFile();
}
@ -1089,7 +1096,7 @@ void Logger::TimerEvent(Logger::StartEnd se, const char* name) {
case STAMP:
msg << "timer-event";
}
msg << kNext << name << kNext << timer_.Elapsed().InMicroseconds();
msg << kNext << name << kNext << Time();
msg.WriteToLogFile();
}
@ -1192,22 +1199,20 @@ namespace {
void AppendCodeCreateHeader(
Log::MessageBuilder& msg, // NOLINT(runtime/references)
CodeEventListener::LogEventsAndTags tag, CodeKind kind, uint8_t* address,
int size, base::ElapsedTimer* timer) {
int size, uint64_t time) {
msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT]
<< Logger::kNext << kLogEventsNames[tag] << Logger::kNext
<< static_cast<int>(kind) << Logger::kNext
<< timer->Elapsed().InMicroseconds() << Logger::kNext
<< static_cast<int>(kind) << Logger::kNext << time << Logger::kNext
<< reinterpret_cast<void*>(address) << Logger::kNext << size
<< Logger::kNext;
}
void AppendCodeCreateHeader(
Log::MessageBuilder& msg, // NOLINT(runtime/references)
CodeEventListener::LogEventsAndTags tag, AbstractCode code,
base::ElapsedTimer* timer) {
CodeEventListener::LogEventsAndTags tag, AbstractCode code, uint64_t time) {
AppendCodeCreateHeader(msg, tag, code.kind(),
reinterpret_cast<uint8_t*>(code.InstructionStart()),
code.InstructionSize(), timer);
code.InstructionSize(), time);
}
} // namespace
@ -1219,7 +1224,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
AppendCodeCreateHeader(msg, tag, *code, &timer_);
AppendCodeCreateHeader(msg, tag, *code, Time());
msg << name;
msg.WriteToLogFile();
}
@ -1231,7 +1236,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
AppendCodeCreateHeader(msg, tag, *code, &timer_);
AppendCodeCreateHeader(msg, tag, *code, Time());
msg << *name;
msg.WriteToLogFile();
}
@ -1249,7 +1254,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
AppendCodeCreateHeader(msg, tag, *code, &timer_);
AppendCodeCreateHeader(msg, tag, *code, Time());
msg << *script_name << kNext << reinterpret_cast<void*>(shared->address())
<< kNext << ComputeMarker(*shared, *code);
msg.WriteToLogFile();
@ -1267,7 +1272,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
AppendCodeCreateHeader(msg, tag, *code, &timer_);
AppendCodeCreateHeader(msg, tag, *code, Time());
msg << shared->DebugName() << " " << *script_name << ":" << line << ":"
<< column << kNext << reinterpret_cast<void*>(shared->address())
<< kNext << ComputeMarker(*shared, *code);
@ -1367,7 +1372,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
Log::MessageBuilder& msg = *msg_ptr.get();
AppendCodeCreateHeader(msg, tag, CodeKind::WASM_FUNCTION,
code->instructions().begin(),
code->instructions().length(), &timer_);
code->instructions().length(), Time());
DCHECK(!name.empty());
msg.AppendString(name);
@ -1390,9 +1395,8 @@ void Logger::CallbackEventInternal(const char* prefix, Handle<Name> name,
Log::MessageBuilder& msg = *msg_ptr.get();
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;
<< kNext << Time() << kNext << reinterpret_cast<void*>(entry_point)
<< kNext << 1 << kNext << prefix << *name;
msg.WriteToLogFile();
}
@ -1415,7 +1419,7 @@ void Logger::RegExpCodeCreateEvent(Handle<AbstractCode> code,
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
AppendCodeCreateHeader(msg, CodeEventListener::REG_EXP_TAG, *code, &timer_);
AppendCodeCreateHeader(msg, CodeEventListener::REG_EXP_TAG, *code, Time());
msg << *source;
msg.WriteToLogFile();
}
@ -1455,8 +1459,7 @@ void Logger::ProcessDeoptEvent(Handle<Code> code, SourcePosition position,
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
msg << "code-deopt" << kNext << timer_.Elapsed().InMicroseconds() << kNext
<< code->CodeSize() << kNext
msg << "code-deopt" << kNext << Time() << kNext << code->CodeSize() << kNext
<< reinterpret_cast<void*>(code->InstructionStart());
std::ostringstream deopt_location;
@ -1580,11 +1583,16 @@ namespace {
void AppendFunctionMessage(
Log::MessageBuilder& msg, // NOLINT(runtime/references)
const char* reason, int script_id, double time_delta, int start_position,
int end_position, base::ElapsedTimer* timer) {
int end_position, uint64_t time) {
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;
<< Logger::kNext;
if (V8_UNLIKELY(FLAG_predictable)) {
msg << 0.1;
} else {
msg << time_delta;
}
msg << Logger::kNext << time << Logger::kNext;
}
} // namespace
@ -1596,7 +1604,7 @@ void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
end_position, &timer_);
end_position, Time());
if (!function_name.is_null()) msg << function_name;
msg.WriteToLogFile();
}
@ -1610,7 +1618,7 @@ void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
end_position, &timer_);
end_position, Time());
if (function_name_length > 0) {
msg.AppendString(function_name, function_name_length, is_one_byte);
}
@ -1630,7 +1638,7 @@ void Logger::CompilationCacheEvent(const char* action, const char* cache_type,
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();
<< Logger::kNext << Time();
msg.WriteToLogFile();
}
@ -1657,8 +1665,7 @@ void Logger::ScriptEvent(ScriptEventType type, int script_id) {
msg << "streaming-compile";
break;
}
msg << Logger::kNext << script_id << Logger::kNext
<< timer_.Elapsed().InMicroseconds();
msg << Logger::kNext << script_id << Logger::kNext << Time();
msg.WriteToLogFile();
}
@ -1732,8 +1739,7 @@ void Logger::TickEvent(TickSample* sample, bool overflow) {
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
msg << kLogEventsNames[CodeEventListener::TICK_EVENT] << kNext
<< reinterpret_cast<void*>(sample->pc) << kNext
<< timer_.Elapsed().InMicroseconds();
<< reinterpret_cast<void*>(sample->pc) << kNext << Time();
if (sample->has_external_callback) {
msg << kNext << 1 << kNext
<< reinterpret_cast<void*>(sample->external_callback_entry);
@ -1759,9 +1765,9 @@ void Logger::ICEvent(const char* type, bool keyed, Handle<Map> map,
int line;
int column;
Address pc = isolate_->GetAbstractPC(&line, &column);
msg << type << kNext << reinterpret_cast<void*>(pc) << kNext
<< timer_.Elapsed().InMicroseconds() << kNext << line << kNext << column
<< kNext << old_state << kNext << new_state << kNext
msg << type << kNext << reinterpret_cast<void*>(pc) << kNext << Time()
<< kNext << line << kNext << column << kNext << old_state << kNext
<< new_state << kNext
<< AsHex::Address(map.is_null() ? kNullAddress : map->ptr()) << kNext;
if (key->IsSmi()) {
msg << Smi::ToInt(*key);
@ -1791,11 +1797,11 @@ void Logger::MapEvent(const char* type, Handle<Map> from, Handle<Map> to,
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
msg << "map" << kNext << type << kNext << timer_.Elapsed().InMicroseconds()
<< kNext << AsHex::Address(from.is_null() ? kNullAddress : from->ptr())
<< kNext << AsHex::Address(to.is_null() ? kNullAddress : to->ptr())
<< kNext << AsHex::Address(pc) << kNext << line << kNext << column
<< kNext << reason << kNext;
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
<< AsHex::Address(pc) << kNext << line << kNext << column << kNext
<< reason << kNext;
if (!name_or_sfi.is_null()) {
if (name_or_sfi->IsName()) {
@ -1817,8 +1823,7 @@ void Logger::MapCreate(Map map) {
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
msg << "map-create" << kNext << timer_.Elapsed().InMicroseconds() << kNext
<< AsHex::Address(map.ptr());
msg << "map-create" << kNext << Time() << kNext << AsHex::Address(map.ptr());
msg.WriteToLogFile();
}
@ -1828,8 +1833,8 @@ void Logger::MapDetails(Map map) {
std::unique_ptr<Log::MessageBuilder> msg_ptr = log_->NewMessageBuilder();
if (!msg_ptr) return;
Log::MessageBuilder& msg = *msg_ptr.get();
msg << "map-details" << kNext << timer_.Elapsed().InMicroseconds() << kNext
<< AsHex::Address(map.ptr()) << kNext;
msg << "map-details" << kNext << Time() << kNext << AsHex::Address(map.ptr())
<< kNext;
if (FLAG_trace_maps_details) {
std::ostringstream buffer;
map.PrintMapDetails(buffer);

2
src/logging/log.h
View File

@ -314,6 +314,8 @@ class Logger : public CodeEventListener {
// each script is logged only once.
bool EnsureLogScriptSource(Script script);
int64_t Time();
Isolate* isolate_;
// The sampler used by the profiler and the sliding state window.

3
test/mjsunit/mjsunit.status
View File

@ -984,9 +984,6 @@
# BUG(v8:9975).
'es6/typedarray-copywithin': [SKIP],
# BUG(https://crbug.com/v8/10966)
'tools/log_two_byte': [SKIP],
}], # 'predictable == True'
##############################################################################