Commit aafd5c52 authored by Camillo Bruni's avatar Camillo Bruni Committed by Commit Bot

[parser][log] Log script id during background compilation

- Add separate script-create, script-reserve-id and script-details log events
- Add log events for CompilationCache hits and puts
- Simplify function event logging by only pass along the script id
- Explicitly create Scripts in parse-processor.js on script events only
- Create a temporary script id in the ParseInfo for use during background
  parsing and compilation
- Clean up ParseInfo initialization to centralize creation and use of
  script ids
- Allow creating Scripts with predefined script ids

Bug: chromium:757467, chromium:850038
Change-Id: I02dfd1d5725795b9fe0ea94ef57b287b934a1efe
Reviewed-on: https://chromium-review.googlesource.com/1097131Reviewed-by: 's avatarSathya Gunasekaran <gsathya@chromium.org>
Reviewed-by: 's avatarLeszek Swirski <leszeks@chromium.org>
Reviewed-by: 's avatarUlan Degenbaev <ulan@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/master@{#53978}
parent 9635e1a3
...@@ -160,6 +160,7 @@ MaybeHandle<SharedFunctionInfo> CompilationCacheScript::Lookup( ...@@ -160,6 +160,7 @@ MaybeHandle<SharedFunctionInfo> CompilationCacheScript::Lookup(
resource_options)); resource_options));
#endif #endif
isolate()->counters()->compilation_cache_hits()->Increment(); isolate()->counters()->compilation_cache_hits()->Increment();
LOG(isolate(), CompilationCacheEvent("hit", "script", *function_info));
} else { } else {
isolate()->counters()->compilation_cache_misses()->Increment(); isolate()->counters()->compilation_cache_misses()->Increment();
} }
...@@ -274,14 +275,23 @@ InfoCellPair CompilationCache::LookupEval(Handle<String> source, ...@@ -274,14 +275,23 @@ InfoCellPair CompilationCache::LookupEval(Handle<String> source,
InfoCellPair result; InfoCellPair result;
if (!IsEnabled()) return result; if (!IsEnabled()) return result;
const char* cache_type;
if (context->IsNativeContext()) { if (context->IsNativeContext()) {
result = eval_global_.Lookup(source, outer_info, context, language_mode, result = eval_global_.Lookup(source, outer_info, context, language_mode,
position); position);
cache_type = "eval-global";
} else { } else {
DCHECK_NE(position, kNoSourcePosition); DCHECK_NE(position, kNoSourcePosition);
Handle<Context> native_context(context->native_context(), isolate()); Handle<Context> native_context(context->native_context(), isolate());
result = eval_contextual_.Lookup(source, outer_info, native_context, result = eval_contextual_.Lookup(source, outer_info, native_context,
language_mode, position); language_mode, position);
cache_type = "eval-contextual";
}
if (result.has_shared()) {
LOG(isolate(), CompilationCacheEvent("hit", cache_type, result.shared()));
} }
return result; return result;
...@@ -299,6 +309,7 @@ void CompilationCache::PutScript(Handle<String> source, ...@@ -299,6 +309,7 @@ void CompilationCache::PutScript(Handle<String> source,
LanguageMode language_mode, LanguageMode language_mode,
Handle<SharedFunctionInfo> function_info) { Handle<SharedFunctionInfo> function_info) {
if (!IsEnabled()) return; if (!IsEnabled()) return;
LOG(isolate(), CompilationCacheEvent("put", "script", *function_info));
script_.Put(source, native_context, language_mode, function_info); script_.Put(source, native_context, language_mode, function_info);
} }
...@@ -311,24 +322,26 @@ void CompilationCache::PutEval(Handle<String> source, ...@@ -311,24 +322,26 @@ void CompilationCache::PutEval(Handle<String> source,
int position) { int position) {
if (!IsEnabled()) return; if (!IsEnabled()) return;
const char* cache_type;
HandleScope scope(isolate()); HandleScope scope(isolate());
if (context->IsNativeContext()) { if (context->IsNativeContext()) {
eval_global_.Put(source, outer_info, function_info, context, feedback_cell, eval_global_.Put(source, outer_info, function_info, context, feedback_cell,
position); position);
cache_type = "eval-global";
} else { } else {
DCHECK_NE(position, kNoSourcePosition); DCHECK_NE(position, kNoSourcePosition);
Handle<Context> native_context(context->native_context(), isolate()); Handle<Context> native_context(context->native_context(), isolate());
eval_contextual_.Put(source, outer_info, function_info, native_context, eval_contextual_.Put(source, outer_info, function_info, native_context,
feedback_cell, position); feedback_cell, position);
cache_type = "eval-contextual";
} }
LOG(isolate(), CompilationCacheEvent("put", cache_type, *function_info));
} }
void CompilationCache::PutRegExp(Handle<String> source, void CompilationCache::PutRegExp(Handle<String> source,
JSRegExp::Flags flags, JSRegExp::Flags flags,
Handle<FixedArray> data) { Handle<FixedArray> data) {
if (!IsEnabled()) { if (!IsEnabled()) return;
return;
}
reg_exp_.Put(source, flags, data); reg_exp_.Put(source, flags, data);
} }
......
...@@ -220,9 +220,9 @@ class CompilationCache { ...@@ -220,9 +220,9 @@ class CompilationCache {
// The number of sub caches covering the different types to cache. // The number of sub caches covering the different types to cache.
static const int kSubCacheCount = 4; static const int kSubCacheCount = 4;
bool IsEnabled() { return FLAG_compilation_cache && enabled_; } bool IsEnabled() const { return FLAG_compilation_cache && enabled_; }
Isolate* isolate() { return isolate_; } Isolate* isolate() const { return isolate_; }
Isolate* isolate_; Isolate* isolate_;
......
...@@ -116,14 +116,22 @@ void UnoptimizedCompileJob::PrepareOnMainThread(Isolate* isolate) { ...@@ -116,14 +116,22 @@ void UnoptimizedCompileJob::PrepareOnMainThread(Isolate* isolate) {
static_cast<void*>(this)); static_cast<void*>(this));
} }
HandleScope scope(isolate); ParseInfo* parse_info = new ParseInfo(isolate, shared_);
parse_info_.reset(parse_info);
unicode_cache_.reset(new UnicodeCache()); unicode_cache_.reset(new UnicodeCache());
Handle<Script> script(Script::cast(shared_->script()), isolate); parse_info_->set_unicode_cache(unicode_cache_.get());
DCHECK(script->type() != Script::TYPE_NATIVE); parse_info_->set_function_literal_id(shared_->function_literal_id());
if (V8_UNLIKELY(FLAG_runtime_stats)) {
parse_info_->set_runtime_call_stats(new (parse_info_->zone())
RuntimeCallStats());
}
Handle<Script> script = parse_info->script();
HandleScope scope(isolate);
DCHECK(script->type() != Script::TYPE_NATIVE);
Handle<String> source(String::cast(script->source()), isolate); Handle<String> source(String::cast(script->source()), isolate);
parse_info_.reset(new ParseInfo(isolate->allocator()));
parse_info_->InitFromIsolate(isolate);
if (source->IsExternalTwoByteString() || source->IsExternalOneByteString()) { if (source->IsExternalTwoByteString() || source->IsExternalOneByteString()) {
std::unique_ptr<Utf16CharacterStream> stream(ScannerStream::For( std::unique_ptr<Utf16CharacterStream> stream(ScannerStream::For(
source, shared_->StartPosition(), shared_->EndPosition())); source, shared_->StartPosition(), shared_->EndPosition()));
...@@ -190,29 +198,15 @@ void UnoptimizedCompileJob::PrepareOnMainThread(Isolate* isolate) { ...@@ -190,29 +198,15 @@ void UnoptimizedCompileJob::PrepareOnMainThread(Isolate* isolate) {
shared_->EndPosition() - offset)); shared_->EndPosition() - offset));
parse_info_->set_character_stream(std::move(stream)); parse_info_->set_character_stream(std::move(stream));
} }
parse_info_->set_hash_seed(isolate->heap()->HashSeed());
parse_info_->set_is_named_expression(shared_->is_named_expression());
parse_info_->set_function_flags(shared_->flags());
parse_info_->set_start_position(shared_->StartPosition());
parse_info_->set_end_position(shared_->EndPosition());
parse_info_->set_unicode_cache(unicode_cache_.get());
parse_info_->set_language_mode(shared_->language_mode());
parse_info_->set_function_literal_id(shared_->function_literal_id());
if (V8_UNLIKELY(FLAG_runtime_stats)) {
parse_info_->set_runtime_call_stats(new (parse_info_->zone())
RuntimeCallStats());
}
parser_.reset(new Parser(parse_info_.get())); parser_.reset(new Parser(parse_info_.get()));
MaybeHandle<ScopeInfo> outer_scope_info; parser_->DeserializeScopeChain(isolate, parse_info_.get(),
if (shared_->HasOuterScopeInfo()) { parse_info_->maybe_outer_scope_info());
outer_scope_info = handle(shared_->GetOuterScopeInfo(), isolate);
}
parser_->DeserializeScopeChain(isolate, parse_info_.get(), outer_scope_info);
// Initailize the name after setting up the ast_value_factory.
Handle<String> name(shared_->Name()); Handle<String> name(shared_->Name());
parse_info_->set_function_name( parse_info_->set_function_name(
parse_info_->ast_value_factory()->GetString(name)); parse_info_->ast_value_factory()->GetString(name));
set_status(Status::kPrepared); set_status(Status::kPrepared);
} }
...@@ -278,7 +272,8 @@ void UnoptimizedCompileJob::FinalizeOnMainThread(Isolate* isolate) { ...@@ -278,7 +272,8 @@ void UnoptimizedCompileJob::FinalizeOnMainThread(Isolate* isolate) {
} }
Handle<Script> script(Script::cast(shared_->script()), isolate); Handle<Script> script(Script::cast(shared_->script()), isolate);
parse_info_->set_script(script); DCHECK_EQ(*parse_info_->script(), shared_->script());
parser_->UpdateStatistics(isolate, script); parser_->UpdateStatistics(isolate, script);
parse_info_->UpdateBackgroundParseStatisticsOnMainThread(isolate); parse_info_->UpdateBackgroundParseStatisticsOnMainThread(isolate);
parser_->HandleSourceURLComments(isolate, script); parser_->HandleSourceURLComments(isolate, script);
......
...@@ -119,7 +119,7 @@ void LogFunctionCompilation(CodeEventListener::LogEventsAndTags tag, ...@@ -119,7 +119,7 @@ void LogFunctionCompilation(CodeEventListener::LogEventsAndTags tag,
UNREACHABLE(); UNREACHABLE();
} }
LOG(isolate, FunctionEvent(name.c_str(), nullptr, script->id(), time_taken_ms, LOG(isolate, FunctionEvent(name.c_str(), script->id(), time_taken_ms,
shared->StartPosition(), shared->EndPosition(), shared->StartPosition(), shared->EndPosition(),
shared->DebugName())); shared->DebugName()));
} }
...@@ -972,8 +972,8 @@ BackgroundCompileTask::BackgroundCompileTask(ScriptStreamingData* source, ...@@ -972,8 +972,8 @@ BackgroundCompileTask::BackgroundCompileTask(ScriptStreamingData* source,
// Prepare the data for the internalization phase and compilation phase, which // Prepare the data for the internalization phase and compilation phase, which
// will happen in the main thread after parsing. // will happen in the main thread after parsing.
ParseInfo* info = new ParseInfo(isolate->allocator()); ParseInfo* info = new ParseInfo(isolate);
info->InitFromIsolate(isolate); LOG(isolate, ScriptEvent("background-compile", info->script_id()));
if (V8_UNLIKELY(FLAG_runtime_stats)) { if (V8_UNLIKELY(FLAG_runtime_stats)) {
info->set_runtime_call_stats(new (info->zone()) RuntimeCallStats()); info->set_runtime_call_stats(new (info->zone()) RuntimeCallStats());
} else { } else {
...@@ -1278,18 +1278,16 @@ MaybeHandle<JSFunction> Compiler::GetFunctionFromEval( ...@@ -1278,18 +1278,16 @@ MaybeHandle<JSFunction> Compiler::GetFunctionFromEval(
script = Handle<Script>(Script::cast(shared_info->script()), isolate); script = Handle<Script>(Script::cast(shared_info->script()), isolate);
allow_eval_cache = true; allow_eval_cache = true;
} else { } else {
script = isolate->factory()->NewScript(source); ParseInfo parse_info(isolate);
if (isolate->NeedsSourcePositionsForProfiling()) { script = parse_info.CreateScript(isolate, source, options);
Script::InitLineEnds(script);
}
if (!script_name.is_null()) { if (!script_name.is_null()) {
// TODO(cbruni): check whether we can store this data in options
script->set_name(*script_name); script->set_name(*script_name);
script->set_line_offset(line_offset); script->set_line_offset(line_offset);
script->set_column_offset(column_offset); script->set_column_offset(column_offset);
LOG(isolate, ScriptDetails(*script));
} }
script->set_origin_options(options);
script->set_compilation_type(Script::COMPILATION_TYPE_EVAL); script->set_compilation_type(Script::COMPILATION_TYPE_EVAL);
script->set_eval_from_shared(*outer_info); script->set_eval_from_shared(*outer_info);
if (eval_position == kNoSourcePosition) { if (eval_position == kNoSourcePosition) {
// If the position is missing, attempt to get the code offset by // If the position is missing, attempt to get the code offset by
...@@ -1307,7 +1305,6 @@ MaybeHandle<JSFunction> Compiler::GetFunctionFromEval( ...@@ -1307,7 +1305,6 @@ MaybeHandle<JSFunction> Compiler::GetFunctionFromEval(
} }
script->set_eval_from_position(eval_position); script->set_eval_from_position(eval_position);
ParseInfo parse_info(isolate, script);
parse_info.set_eval(); parse_info.set_eval();
parse_info.set_language_mode(language_mode); parse_info.set_language_mode(language_mode);
parse_info.set_parse_restriction(restriction); parse_info.set_parse_restriction(restriction);
...@@ -1601,29 +1598,20 @@ struct ScriptCompileTimerScope { ...@@ -1601,29 +1598,20 @@ struct ScriptCompileTimerScope {
} }
}; };
Handle<Script> NewScript(Isolate* isolate, Handle<String> source, Handle<Script> NewScript(Isolate* isolate, ParseInfo* parse_info,
Handle<String> source,
Compiler::ScriptDetails script_details, Compiler::ScriptDetails script_details,
ScriptOriginOptions origin_options, ScriptOriginOptions origin_options,
NativesFlag natives) { NativesFlag natives) {
// Create a script object describing the script to be compiled. // Create a script object describing the script to be compiled.
Handle<Script> script = isolate->factory()->NewScript(source); Handle<Script> script =
if (isolate->NeedsSourcePositionsForProfiling()) { parse_info->CreateScript(isolate, source, origin_options, natives);
Script::InitLineEnds(script);
}
if (natives == NATIVES_CODE) {
script->set_type(Script::TYPE_NATIVE);
} else if (natives == EXTENSION_CODE) {
script->set_type(Script::TYPE_EXTENSION);
} else if (natives == INSPECTOR_CODE) {
script->set_type(Script::TYPE_INSPECTOR);
}
Handle<Object> script_name; Handle<Object> script_name;
if (script_details.name_obj.ToHandle(&script_name)) { if (script_details.name_obj.ToHandle(&script_name)) {
script->set_name(*script_name); script->set_name(*script_name);
script->set_line_offset(script_details.line_offset); script->set_line_offset(script_details.line_offset);
script->set_column_offset(script_details.column_offset); script->set_column_offset(script_details.column_offset);
} }
script->set_origin_options(origin_options);
Handle<Object> source_map_url; Handle<Object> source_map_url;
if (script_details.source_map_url.ToHandle(&source_map_url)) { if (script_details.source_map_url.ToHandle(&source_map_url)) {
script->set_source_mapping_url(*source_map_url); script->set_source_mapping_url(*source_map_url);
...@@ -1632,6 +1620,7 @@ Handle<Script> NewScript(Isolate* isolate, Handle<String> source, ...@@ -1632,6 +1620,7 @@ Handle<Script> NewScript(Isolate* isolate, Handle<String> source,
if (script_details.host_defined_options.ToHandle(&host_defined_options)) { if (script_details.host_defined_options.ToHandle(&host_defined_options)) {
script->set_host_defined_options(*host_defined_options); script->set_host_defined_options(*host_defined_options);
} }
LOG(isolate, ScriptDetails(*script));
return script; return script;
} }
...@@ -1703,12 +1692,12 @@ MaybeHandle<SharedFunctionInfo> Compiler::GetSharedFunctionInfoForScript( ...@@ -1703,12 +1692,12 @@ MaybeHandle<SharedFunctionInfo> Compiler::GetSharedFunctionInfoForScript(
} }
if (maybe_result.is_null()) { if (maybe_result.is_null()) {
ParseInfo parse_info(isolate);
// No cache entry found compile the script. // No cache entry found compile the script.
Handle<Script> script = NewScript(isolate, &parse_info, source, script_details, origin_options,
NewScript(isolate, source, script_details, origin_options, natives); natives);
// Compile the function and add it to the isolate cache. // Compile the function and add it to the isolate cache.
ParseInfo parse_info(isolate, script);
Zone compile_zone(isolate->allocator(), ZONE_NAME); Zone compile_zone(isolate->allocator(), ZONE_NAME);
if (origin_options.IsModule()) parse_info.set_module(); if (origin_options.IsModule()) parse_info.set_module();
parse_info.set_extension(extension); parse_info.set_extension(extension);
...@@ -1776,11 +1765,11 @@ MaybeHandle<JSFunction> Compiler::GetWrappedFunction( ...@@ -1776,11 +1765,11 @@ MaybeHandle<JSFunction> Compiler::GetWrappedFunction(
Handle<SharedFunctionInfo> wrapped; Handle<SharedFunctionInfo> wrapped;
Handle<Script> script; Handle<Script> script;
if (!maybe_result.ToHandle(&wrapped)) { if (!maybe_result.ToHandle(&wrapped)) {
script = NewScript(isolate, source, script_details, origin_options, ParseInfo parse_info(isolate);
NOT_NATIVES_CODE); script = NewScript(isolate, &parse_info, source, script_details,
origin_options, NOT_NATIVES_CODE);
script->set_wrapped_arguments(*arguments); script->set_wrapped_arguments(*arguments);
ParseInfo parse_info(isolate, script);
parse_info.set_eval(); // Use an eval scope as declaration scope. parse_info.set_eval(); // Use an eval scope as declaration scope.
parse_info.set_wrapped_as_function(); parse_info.set_wrapped_as_function();
// parse_info.set_eager(compile_options == ScriptCompiler::kEagerCompile); // parse_info.set_eager(compile_options == ScriptCompiler::kEagerCompile);
...@@ -1847,9 +1836,9 @@ Compiler::GetSharedFunctionInfoForStreamedScript( ...@@ -1847,9 +1836,9 @@ Compiler::GetSharedFunctionInfoForStreamedScript(
if (maybe_result.is_null()) { if (maybe_result.is_null()) {
// No cache entry found, finalize compilation of the script and add it to // No cache entry found, finalize compilation of the script and add it to
// the isolate cache. // the isolate cache.
Handle<Script> script = NewScript(isolate, source, script_details, Handle<Script> script =
origin_options, NOT_NATIVES_CODE); NewScript(isolate, parse_info, source, script_details, origin_options,
parse_info->set_script(script); NOT_NATIVES_CODE);
streaming_data->parser->UpdateStatistics(isolate, script); streaming_data->parser->UpdateStatistics(isolate, script);
streaming_data->parser->HandleSourceURLComments(isolate, script); streaming_data->parser->HandleSourceURLComments(isolate, script);
......
...@@ -1515,13 +1515,18 @@ Handle<AccessorInfo> Factory::NewAccessorInfo() { ...@@ -1515,13 +1515,18 @@ Handle<AccessorInfo> Factory::NewAccessorInfo() {
} }
Handle<Script> Factory::NewScript(Handle<String> source, PretenureFlag tenure) { Handle<Script> Factory::NewScript(Handle<String> source, PretenureFlag tenure) {
return NewScriptWithId(source, isolate()->heap()->NextScriptId(), tenure);
}
Handle<Script> Factory::NewScriptWithId(Handle<String> source, int script_id,
PretenureFlag tenure) {
DCHECK(tenure == TENURED || tenure == TENURED_READ_ONLY); DCHECK(tenure == TENURED || tenure == TENURED_READ_ONLY);
// Create and initialize script object. // Create and initialize script object.
Heap* heap = isolate()->heap(); Heap* heap = isolate()->heap();
Handle<Script> script = Handle<Script>::cast(NewStruct(SCRIPT_TYPE, tenure)); Handle<Script> script = Handle<Script>::cast(NewStruct(SCRIPT_TYPE, tenure));
script->set_source(*source); script->set_source(*source);
script->set_name(heap->undefined_value()); script->set_name(heap->undefined_value());
script->set_id(isolate()->heap()->NextScriptId()); script->set_id(script_id);
script->set_line_offset(0); script->set_line_offset(0);
script->set_column_offset(0); script->set_column_offset(0);
script->set_context_data(heap->undefined_value()); script->set_context_data(heap->undefined_value());
...@@ -1535,6 +1540,7 @@ Handle<Script> Factory::NewScript(Handle<String> source, PretenureFlag tenure) { ...@@ -1535,6 +1540,7 @@ Handle<Script> Factory::NewScript(Handle<String> source, PretenureFlag tenure) {
script->set_flags(0); script->set_flags(0);
script->set_host_defined_options(*empty_fixed_array()); script->set_host_defined_options(*empty_fixed_array());
heap->set_script_list(*FixedArrayOfWeakCells::Add(script_list(), script)); heap->set_script_list(*FixedArrayOfWeakCells::Add(script_list(), script));
LOG(isolate(), ScriptEvent("create", script_id));
return script; return script;
} }
......
...@@ -401,6 +401,8 @@ class V8_EXPORT_PRIVATE Factory { ...@@ -401,6 +401,8 @@ class V8_EXPORT_PRIVATE Factory {
Handle<Script> NewScript(Handle<String> source, Handle<Script> NewScript(Handle<String> source,
PretenureFlag tenure = TENURED); PretenureFlag tenure = TENURED);
Handle<Script> NewScriptWithId(Handle<String> source, int script_id,
PretenureFlag tenure = TENURED);
Handle<BreakPointInfo> NewBreakPointInfo(int source_position); Handle<BreakPointInfo> NewBreakPointInfo(int source_position);
Handle<BreakPoint> NewBreakPoint(int id, Handle<String> condition); Handle<BreakPoint> NewBreakPoint(int id, Handle<String> condition);
......
...@@ -1530,49 +1530,84 @@ void Logger::SuspectReadEvent(Name* name, Object* obj) { ...@@ -1530,49 +1530,84 @@ void Logger::SuspectReadEvent(Name* name, Object* obj) {
namespace { namespace {
void AppendFunctionMessage(Log::MessageBuilder& msg, const char* reason, void AppendFunctionMessage(Log::MessageBuilder& msg, const char* reason,
Script* script, int script_id, double time_delta, int script_id, double time_delta, int start_position,
int start_position, int end_position, int end_position, base::ElapsedTimer* timer) {
base::ElapsedTimer* timer) { msg << "function" << Logger::kNext << reason << Logger::kNext << script_id
msg << "function" << Logger::kNext << reason << Logger::kNext; << Logger::kNext << start_position << Logger::kNext << end_position
if (script) {
if (script->name()->IsString()) {
msg << String::cast(script->name());
}
msg << Logger::kNext << script->id();
} else {
msg << Logger::kNext << script_id;
}
msg << Logger::kNext << start_position << Logger::kNext << end_position
<< Logger::kNext << time_delta << Logger::kNext << Logger::kNext << time_delta << Logger::kNext
<< timer->Elapsed().InMicroseconds() << Logger::kNext; << timer->Elapsed().InMicroseconds() << Logger::kNext;
} }
} // namespace } // namespace
void Logger::FunctionEvent(const char* reason, Script* script, int script_id, void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
double time_delta, int start_position, int start_position, int end_position,
int end_position, String* function_name) { String* function_name) {
if (!log_->IsEnabled() || !FLAG_log_function_events) return; if (!log_->IsEnabled() || !FLAG_log_function_events) return;
Log::MessageBuilder msg(log_); Log::MessageBuilder msg(log_);
AppendFunctionMessage(msg, reason, script, script_id, time_delta, AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
start_position, end_position, &timer_); end_position, &timer_);
if (function_name) msg << function_name; if (function_name) msg << function_name;
msg.WriteToLogFile(); msg.WriteToLogFile();
} }
void Logger::FunctionEvent(const char* reason, Script* script, int script_id, void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
double time_delta, int start_position, int start_position, int end_position,
int end_position, const char* function_name, const char* function_name,
size_t function_name_length) { size_t function_name_length) {
if (!log_->IsEnabled() || !FLAG_log_function_events) return; if (!log_->IsEnabled() || !FLAG_log_function_events) return;
Log::MessageBuilder msg(log_); Log::MessageBuilder msg(log_);
AppendFunctionMessage(msg, reason, script, script_id, time_delta, AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
start_position, end_position, &timer_); end_position, &timer_);
if (function_name_length > 0) { if (function_name_length > 0) {
msg.AppendStringPart(function_name, function_name_length); msg.AppendStringPart(function_name, function_name_length);
} }
msg.WriteToLogFile(); msg.WriteToLogFile();
} }
namespace {
void AppendCompilationCacheMessage(Log::MessageBuilder& msg,
SharedFunctionInfo* sfi) {
int script_id = -1;
if (sfi->script()->IsScript()) {
script_id = Script::cast(sfi->script())->id();
}
msg << script_id << Logger::kNext << sfi->StartPosition() << Logger::kNext
<< sfi->EndPosition();
}
} // namespace
void Logger::CompilationCacheEvent(const char* action, const char* cache_type,
SharedFunctionInfo* sfi) {
if (!log_->IsEnabled() || !FLAG_log_function_events) return;
Log::MessageBuilder msg(log_);
msg << "compilation-cache" << Logger::kNext << action << Logger::kNext
<< cache_type << Logger::kNext;
AppendCompilationCacheMessage(msg, sfi);
msg.WriteToLogFile();
}
void Logger::ScriptEvent(const char* event_name, int script_id) {
if (!log_->IsEnabled() || !FLAG_log_function_events) return;
Log::MessageBuilder msg(log_);
msg << "script" << Logger::kNext << event_name << Logger::kNext << script_id;
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();
}
void Logger::RuntimeCallTimerEvent() { void Logger::RuntimeCallTimerEvent() {
RuntimeCallStats* stats = isolate_->counters()->runtime_call_stats(); RuntimeCallStats* stats = isolate_->counters()->runtime_call_stats();
RuntimeCallCounter* counter = stats->current_counter(); RuntimeCallCounter* counter = stats->current_counter();
......
...@@ -165,14 +165,20 @@ class Logger : public CodeEventListener { ...@@ -165,14 +165,20 @@ class Logger : public CodeEventListener {
// object. // object.
void SuspectReadEvent(Name* name, Object* obj); void SuspectReadEvent(Name* name, Object* obj);
void FunctionEvent(const char* reason, Script* script, int script_id, // ==== Events logged by --log-function-events ====
double time_delta_ms, int start_position = -1, void FunctionEvent(const char* reason, int script_id, double time_delta_ms,
int end_position = -1, String* function_name = nullptr); int start_position = -1, int end_position = -1,
void FunctionEvent(const char* reason, Script* script, int script_id, String* function_name = nullptr);
double time_delta_ms, int start_position, int end_position, void FunctionEvent(const char* reason, int script_id, double time_delta_ms,
int start_position, int end_position,
const char* function_name = nullptr, const char* function_name = nullptr,
size_t function_name_length = 0); size_t function_name_length = 0);
void CompilationCacheEvent(const char* action, const char* cache_type,
SharedFunctionInfo* sfi);
void ScriptEvent(const char* event_name, int script_id);
void ScriptDetails(Script* script);
// ==== Events logged by --log-api. ==== // ==== Events logged by --log-api. ====
void ApiSecurityCheck(); void ApiSecurityCheck();
void ApiNamedPropertyAccess(const char* tag, JSObject* holder, Object* name); void ApiNamedPropertyAccess(const char* tag, JSObject* holder, Object* name);
......
...@@ -16,7 +16,7 @@ ...@@ -16,7 +16,7 @@
namespace v8 { namespace v8 {
namespace internal { namespace internal {
ParseInfo::ParseInfo(AccountingAllocator* zone_allocator) ParseInfo::ParseInfo(Isolate* isolate, AccountingAllocator* zone_allocator)
: zone_(std::make_shared<Zone>(zone_allocator, ZONE_NAME)), : zone_(std::make_shared<Zone>(zone_allocator, ZONE_NAME)),
flags_(0), flags_(0),
extension_(nullptr), extension_(nullptr),
...@@ -25,6 +25,7 @@ ParseInfo::ParseInfo(AccountingAllocator* zone_allocator) ...@@ -25,6 +25,7 @@ ParseInfo::ParseInfo(AccountingAllocator* zone_allocator)
stack_limit_(0), stack_limit_(0),
hash_seed_(0), hash_seed_(0),
function_flags_(0), function_flags_(0),
script_id_(-1),
start_position_(0), start_position_(0),
end_position_(0), end_position_(0),
parameters_end_pos_(kNoSourcePosition), parameters_end_pos_(kNoSourcePosition),
...@@ -36,12 +37,25 @@ ParseInfo::ParseInfo(AccountingAllocator* zone_allocator) ...@@ -36,12 +37,25 @@ ParseInfo::ParseInfo(AccountingAllocator* zone_allocator)
function_name_(nullptr), function_name_(nullptr),
runtime_call_stats_(nullptr), runtime_call_stats_(nullptr),
source_range_map_(nullptr), source_range_map_(nullptr),
literal_(nullptr) {} literal_(nullptr) {
set_hash_seed(isolate->heap()->HashSeed());
set_stack_limit(isolate->stack_guard()->real_climit());
set_unicode_cache(isolate->unicode_cache());
set_runtime_call_stats(isolate->counters()->runtime_call_stats());
set_logger(isolate->logger());
set_ast_string_constants(isolate->ast_string_constants());
if (isolate->is_block_code_coverage()) set_block_coverage_enabled();
if (isolate->is_collecting_type_profile()) set_collect_type_profile();
}
ParseInfo::ParseInfo(Isolate* isolate, Handle<SharedFunctionInfo> shared) ParseInfo::ParseInfo(Isolate* isolate)
: ParseInfo(isolate->allocator()) { : ParseInfo(isolate, isolate->allocator()) {
InitFromIsolate(isolate); script_id_ = isolate->heap()->NextScriptId();
LOG(isolate, ScriptEvent("reserve-id", script_id_));
}
ParseInfo::ParseInfo(Isolate* isolate, Handle<SharedFunctionInfo> shared)
: ParseInfo(isolate, isolate->allocator()) {
// Do not support re-parsing top-level function of a wrapped script. // Do not support re-parsing top-level function of a wrapped script.
// TODO(yangguo): consider whether we need a top-level function in a // TODO(yangguo): consider whether we need a top-level function in a
// wrapped script at all. // wrapped script at all.
...@@ -60,10 +74,6 @@ ParseInfo::ParseInfo(Isolate* isolate, Handle<SharedFunctionInfo> shared) ...@@ -60,10 +74,6 @@ ParseInfo::ParseInfo(Isolate* isolate, Handle<SharedFunctionInfo> shared)
Handle<Script> script(Script::cast(shared->script()), isolate); Handle<Script> script(Script::cast(shared->script()), isolate);
set_script(script); set_script(script);
set_native(script->type() == Script::TYPE_NATIVE);
set_eval(script->compilation_type() == Script::COMPILATION_TYPE_EVAL);
set_module(script->origin_options().IsModule());
DCHECK(!(is_eval() && is_module()));
if (shared->HasOuterScopeInfo()) { if (shared->HasOuterScopeInfo()) {
set_outer_scope_info(handle(shared->GetOuterScopeInfo(), isolate)); set_outer_scope_info(handle(shared->GetOuterScopeInfo(), isolate));
...@@ -77,70 +87,17 @@ ParseInfo::ParseInfo(Isolate* isolate, Handle<SharedFunctionInfo> shared) ...@@ -77,70 +87,17 @@ ParseInfo::ParseInfo(Isolate* isolate, Handle<SharedFunctionInfo> shared)
(shared->HasFeedbackMetadata() (shared->HasFeedbackMetadata()
? shared->feedback_metadata()->HasTypeProfileSlot() ? shared->feedback_metadata()->HasTypeProfileSlot()
: script->IsUserJavaScript())); : script->IsUserJavaScript()));
if (block_coverage_enabled() && script->IsUserJavaScript()) {
AllocateSourceRangeMap();
}
} }
ParseInfo::ParseInfo(Isolate* isolate, Handle<Script> script) ParseInfo::ParseInfo(Isolate* isolate, Handle<Script> script)
: ParseInfo(isolate->allocator()) { : ParseInfo(isolate, isolate->allocator()) {
InitFromIsolate(isolate); SetScriptForToplevelCompile(isolate, script);
set_allow_lazy_parsing();
set_toplevel();
set_script(script);
set_wrapped_as_function(script->is_wrapped());
set_native(script->type() == Script::TYPE_NATIVE);
set_eval(script->compilation_type() == Script::COMPILATION_TYPE_EVAL);
set_module(script->origin_options().IsModule());
DCHECK(!(is_eval() && is_module()));
set_collect_type_profile(isolate->is_collecting_type_profile() && set_collect_type_profile(isolate->is_collecting_type_profile() &&
script->IsUserJavaScript()); script->IsUserJavaScript());
if (block_coverage_enabled() && script->IsUserJavaScript()) {
AllocateSourceRangeMap();
}
} }
ParseInfo::~ParseInfo() {} ParseInfo::~ParseInfo() {}
// static
ParseInfo* ParseInfo::AllocateWithoutScript(Isolate* isolate,
Handle<SharedFunctionInfo> shared) {
ParseInfo* p = new ParseInfo(isolate->allocator());
p->InitFromIsolate(isolate);
p->set_toplevel(shared->is_toplevel());
p->set_allow_lazy_parsing(FLAG_lazy_inner_functions);
p->set_is_named_expression(shared->is_named_expression());
p->set_function_flags(shared->flags());
p->set_start_position(shared->StartPosition());
p->set_end_position(shared->EndPosition());
p->function_literal_id_ = shared->function_literal_id();
p->set_language_mode(shared->language_mode());
// BUG(5946): This function exists as a workaround until we can
// get rid of %SetCode in our native functions. The ParseInfo
// is explicitly set up for the case that:
// a) you have a native built-in,
// b) it's being run for the 2nd-Nth time in an isolate,
// c) we've already compiled bytecode and therefore don't need
// to parse.
// We tolerate a ParseInfo without a Script in this case.
p->set_native(true);
p->set_eval(false);
p->set_module(false);
DCHECK_NE(shared->kind(), FunctionKind::kModule);
Handle<HeapObject> scope_info(shared->GetOuterScopeInfo(), isolate);
if (!scope_info->IsTheHole(isolate) &&
Handle<ScopeInfo>::cast(scope_info)->length() > 0) {
p->set_outer_scope_info(Handle<ScopeInfo>::cast(scope_info));
}
return p;
}
DeclarationScope* ParseInfo::scope() const { return literal()->scope(); } DeclarationScope* ParseInfo::scope() const { return literal()->scope(); }
bool ParseInfo::is_declaration() const { bool ParseInfo::is_declaration() const {
...@@ -156,18 +113,6 @@ bool ParseInfo::requires_instance_fields_initializer() const { ...@@ -156,18 +113,6 @@ bool ParseInfo::requires_instance_fields_initializer() const {
function_flags_); function_flags_);
} }
void ParseInfo::InitFromIsolate(Isolate* isolate) {
DCHECK_NOT_NULL(isolate);
set_hash_seed(isolate->heap()->HashSeed());
set_stack_limit(isolate->stack_guard()->real_climit());
set_unicode_cache(isolate->unicode_cache());
set_runtime_call_stats(isolate->counters()->runtime_call_stats());
set_logger(isolate->logger());
set_ast_string_constants(isolate->ast_string_constants());
if (isolate->is_block_code_coverage()) set_block_coverage_enabled();
if (isolate->is_collecting_type_profile()) set_collect_type_profile();
}
void ParseInfo::EmitBackgroundParseStatisticsOnBackgroundThread() { void ParseInfo::EmitBackgroundParseStatisticsOnBackgroundThread() {
// If runtime call stats was enabled by tracing, emit a trace event at the // If runtime call stats was enabled by tracing, emit a trace event at the
// end of background parsing on the background thread. // end of background parsing on the background thread.
...@@ -201,6 +146,38 @@ void ParseInfo::ShareZone(ParseInfo* other) { ...@@ -201,6 +146,38 @@ void ParseInfo::ShareZone(ParseInfo* other) {
zone_ = other->zone_; zone_ = other->zone_;
} }
Handle<Script> ParseInfo::CreateScript(Isolate* isolate, Handle<String> source,
ScriptOriginOptions origin_options,
NativesFlag natives) {
// Create a script object describing the script to be compiled.
Handle<Script> script;
if (script_id_ == -1) {
script = isolate->factory()->NewScript(source);
} else {
script = isolate->factory()->NewScriptWithId(source, script_id_);
}
if (isolate->NeedsSourcePositionsForProfiling()) {
Script::InitLineEnds(script);
}
switch (natives) {
case NATIVES_CODE:
script->set_type(Script::TYPE_NATIVE);
break;
case EXTENSION_CODE:
script->set_type(Script::TYPE_EXTENSION);
break;
case INSPECTOR_CODE:
script->set_type(Script::TYPE_INSPECTOR);
break;
case NOT_NATIVES_CODE:
break;
}
script->set_origin_options(origin_options);
SetScriptForToplevelCompile(isolate, script);
return script;
}
AstValueFactory* ParseInfo::GetOrCreateAstValueFactory() { AstValueFactory* ParseInfo::GetOrCreateAstValueFactory() {
if (!ast_value_factory_.get()) { if (!ast_value_factory_.get()) {
ast_value_factory_.reset( ast_value_factory_.reset(
...@@ -227,5 +204,30 @@ void ParseInfo::set_character_stream( ...@@ -227,5 +204,30 @@ void ParseInfo::set_character_stream(
character_stream_.swap(character_stream); character_stream_.swap(character_stream);
} }
void ParseInfo::SetScriptForToplevelCompile(Isolate* isolate,
Handle<Script> script) {
set_script(script);
set_allow_lazy_parsing();
set_toplevel();
set_collect_type_profile(isolate->is_collecting_type_profile() &&
script->IsUserJavaScript());
set_wrapped_as_function(script->is_wrapped());
}
void ParseInfo::set_script(Handle<Script> script) {
script_ = script;
DCHECK(script_id_ == -1 || script_id_ == script->id());
script_id_ = script->id();
set_native(script->type() == Script::TYPE_NATIVE);
set_eval(script->compilation_type() == Script::COMPILATION_TYPE_EVAL);
set_module(script->origin_options().IsModule());
DCHECK(!(is_eval() && is_module()));
if (block_coverage_enabled() && script->IsUserJavaScript()) {
AllocateSourceRangeMap();
}
}
} // namespace internal } // namespace internal
} // namespace v8 } // namespace v8
...@@ -37,16 +37,16 @@ class Zone; ...@@ -37,16 +37,16 @@ class Zone;
// A container for the inputs, configuration options, and outputs of parsing. // A container for the inputs, configuration options, and outputs of parsing.
class V8_EXPORT_PRIVATE ParseInfo { class V8_EXPORT_PRIVATE ParseInfo {
public: public:
ParseInfo(AccountingAllocator* zone_allocator); ParseInfo(Isolate*);
ParseInfo(Isolate*, AccountingAllocator* zone_allocator);
ParseInfo(Isolate* isolate, Handle<Script> script); ParseInfo(Isolate* isolate, Handle<Script> script);
ParseInfo(Isolate* isolate, Handle<SharedFunctionInfo> shared); ParseInfo(Isolate* isolate, Handle<SharedFunctionInfo> shared);
~ParseInfo(); ~ParseInfo();
void InitFromIsolate(Isolate* isolate); Handle<Script> CreateScript(Isolate* isolate, Handle<String> source,
ScriptOriginOptions origin_options,
static ParseInfo* AllocateWithoutScript(Isolate* isolate, NativesFlag natives = NOT_NATIVES_CODE);
Handle<SharedFunctionInfo> shared);
// Either returns the ast-value-factory associcated with this ParseInfo, or // Either returns the ast-value-factory associcated with this ParseInfo, or
// creates and returns a new factory if none exists. // creates and returns a new factory if none exists.
...@@ -208,11 +208,11 @@ class V8_EXPORT_PRIVATE ParseInfo { ...@@ -208,11 +208,11 @@ class V8_EXPORT_PRIVATE ParseInfo {
MaybeHandle<ScopeInfo> maybe_outer_scope_info() const { MaybeHandle<ScopeInfo> maybe_outer_scope_info() const {
return maybe_outer_scope_info_; return maybe_outer_scope_info_;
} }
void clear_script() { script_ = Handle<Script>::null(); }
void set_outer_scope_info(Handle<ScopeInfo> outer_scope_info) { void set_outer_scope_info(Handle<ScopeInfo> outer_scope_info) {
maybe_outer_scope_info_ = outer_scope_info; maybe_outer_scope_info_ = outer_scope_info;
} }
void set_script(Handle<Script> script) { script_ = script; }
int script_id() const { return script_id_; }
//-------------------------------------------------------------------------- //--------------------------------------------------------------------------
LanguageMode language_mode() const { LanguageMode language_mode() const {
...@@ -227,6 +227,9 @@ class V8_EXPORT_PRIVATE ParseInfo { ...@@ -227,6 +227,9 @@ class V8_EXPORT_PRIVATE ParseInfo {
void UpdateBackgroundParseStatisticsOnMainThread(Isolate* isolate); void UpdateBackgroundParseStatisticsOnMainThread(Isolate* isolate);
private: private:
void SetScriptForToplevelCompile(Isolate* isolate, Handle<Script> script);
void set_script(Handle<Script> script);
// Various configuration flags for parsing. // Various configuration flags for parsing.
enum Flag { enum Flag {
// ---------- Input flags --------------------------- // ---------- Input flags ---------------------------
...@@ -259,6 +262,7 @@ class V8_EXPORT_PRIVATE ParseInfo { ...@@ -259,6 +262,7 @@ class V8_EXPORT_PRIVATE ParseInfo {
// TODO(leszeks): Move any remaining flags used here either to the flags_ // TODO(leszeks): Move any remaining flags used here either to the flags_
// field or to other fields. // field or to other fields.
int function_flags_; int function_flags_;
int script_id_;
int start_position_; int start_position_;
int end_position_; int end_position_;
int parameters_end_pos_; int parameters_end_pos_;
......
...@@ -4479,9 +4479,8 @@ ParserBase<Impl>::ParseArrowFunctionLiteral( ...@@ -4479,9 +4479,8 @@ ParserBase<Impl>::ParseArrowFunctionLiteral(
const char* event_name = const char* event_name =
is_lazy_top_level_function ? "preparse-no-resolution" : "parse"; is_lazy_top_level_function ? "preparse-no-resolution" : "parse";
const char* name = "arrow function"; const char* name = "arrow function";
logger_->FunctionEvent(event_name, nullptr, script_id(), ms, logger_->FunctionEvent(event_name, script_id(), ms, scope->start_position(),
scope->start_position(), scope->end_position(), name, scope->end_position(), name, strlen(name));
strlen(name));
} }
return function_literal; return function_literal;
......
...@@ -523,7 +523,8 @@ FunctionLiteral* Parser::ParseProgram(Isolate* isolate, ParseInfo* info) { ...@@ -523,7 +523,8 @@ FunctionLiteral* Parser::ParseProgram(Isolate* isolate, ParseInfo* info) {
start = 0; start = 0;
end = String::cast(script->source())->length(); end = String::cast(script->source())->length();
} }
LOG(isolate, FunctionEvent(event_name, script, -1, ms, start, end, "", 0)); LOG(isolate,
FunctionEvent(event_name, script->id(), ms, start, end, "", 0));
} }
return result; return result;
} }
...@@ -714,10 +715,9 @@ FunctionLiteral* Parser::ParseFunction(Isolate* isolate, ParseInfo* info, ...@@ -714,10 +715,9 @@ FunctionLiteral* Parser::ParseFunction(Isolate* isolate, ParseInfo* info,
// We need to make sure that the debug-name is available. // We need to make sure that the debug-name is available.
ast_value_factory()->Internalize(isolate); ast_value_factory()->Internalize(isolate);
DeclarationScope* function_scope = result->scope(); DeclarationScope* function_scope = result->scope();
Script* script = *info->script();
std::unique_ptr<char[]> function_name = result->GetDebugName(); std::unique_ptr<char[]> function_name = result->GetDebugName();
LOG(isolate, LOG(isolate,
FunctionEvent("parse-function", script, -1, ms, FunctionEvent("parse-function", info->script()->id(), ms,
function_scope->start_position(), function_scope->start_position(),
function_scope->end_position(), function_name.get(), function_scope->end_position(), function_name.get(),
strlen(function_name.get()))); strlen(function_name.get())));
...@@ -2655,7 +2655,7 @@ FunctionLiteral* Parser::ParseFunctionLiteral( ...@@ -2655,7 +2655,7 @@ FunctionLiteral* Parser::ParseFunctionLiteral(
: "preparse-resolution") : "preparse-resolution")
: "full-parse"; : "full-parse";
logger_->FunctionEvent( logger_->FunctionEvent(
event_name, nullptr, script_id(), ms, scope->start_position(), event_name, script_id(), ms, scope->start_position(),
scope->end_position(), scope->end_position(),
reinterpret_cast<const char*>(function_name->raw_data()), reinterpret_cast<const char*>(function_name->raw_data()),
function_name->byte_length()); function_name->byte_length());
...@@ -3436,9 +3436,7 @@ void Parser::ParseOnBackground(ParseInfo* info) { ...@@ -3436,9 +3436,7 @@ void Parser::ParseOnBackground(ParseInfo* info) {
RuntimeCallTimerScope runtimeTimer( RuntimeCallTimerScope runtimeTimer(
runtime_call_stats_, RuntimeCallCounterId::kParseBackgroundProgram); runtime_call_stats_, RuntimeCallCounterId::kParseBackgroundProgram);
parsing_on_main_thread_ = false; parsing_on_main_thread_ = false;
if (!info->script().is_null()) { set_script_id(info->script_id());
set_script_id(info->script()->id());
}
DCHECK_NULL(info->literal()); DCHECK_NULL(info->literal());
FunctionLiteral* result = nullptr; FunctionLiteral* result = nullptr;
......
...@@ -366,7 +366,7 @@ PreParser::Expression PreParser::ParseFunctionLiteral( ...@@ -366,7 +366,7 @@ PreParser::Expression PreParser::ParseFunctionLiteral(
name_byte_length = string->byte_length(); name_byte_length = string->byte_length();
} }
logger_->FunctionEvent( logger_->FunctionEvent(
event_name, nullptr, script_id(), ms, function_scope->start_position(), event_name, script_id(), ms, function_scope->start_position(),
function_scope->end_position(), name, name_byte_length); function_scope->end_position(), name, name_byte_length);
} }
......
...@@ -67,9 +67,9 @@ RUNTIME_FUNCTION(Runtime_FunctionFirstExecution) { ...@@ -67,9 +67,9 @@ RUNTIME_FUNCTION(Runtime_FunctionFirstExecution) {
OptimizationMarker::kLogFirstExecution); OptimizationMarker::kLogFirstExecution);
DCHECK(FLAG_log_function_events); DCHECK(FLAG_log_function_events);
Handle<SharedFunctionInfo> sfi(function->shared()); Handle<SharedFunctionInfo> sfi(function->shared());
LOG(isolate, FunctionEvent("first-execution", Script::cast(sfi->script()), -1, LOG(isolate, FunctionEvent(
0, sfi->StartPosition(), sfi->EndPosition(), "first-execution", Script::cast(sfi->script())->id(), 0,
sfi->DebugName())); sfi->StartPosition(), sfi->EndPosition(), sfi->DebugName()));
function->feedback_vector()->ClearOptimizationMarker(); function->feedback_vector()->ClearOptimizationMarker();
// Return the code to continue execution, we don't care at this point whether // Return the code to continue execution, we don't care at this point whether
// this is for lazy compilation or has been eagerly complied. // this is for lazy compilation or has been eagerly complied.
......
...@@ -126,25 +126,30 @@ class ScopedLoggerInitializer { ...@@ -126,25 +126,30 @@ class ScopedLoggerInitializer {
v8::Isolate* isolate() { return isolate_; } v8::Isolate* isolate() { return isolate_; }
i::Isolate* i_isolate() { return reinterpret_cast<i::Isolate*>(isolate()); }
Logger* logger() { return logger_; } Logger* logger() { return logger_; }
void PrintLog(int nofLines = 0) { void PrintLog(int requested_nof_lines = 0, const char* start = nullptr) {
if (nofLines <= 0) { if (requested_nof_lines <= 0) {
printf("%s", log_.start()); printf("%s", log_.start());
return; return;
} }
// Try to print the last {nofLines} of the log. // Try to print the last {requested_nof_lines} of the log.
const char* start = log_.start(); if (start == nullptr) start = log_.start();
const char* current = log_.end(); const char* current = log_.end();
while (current > start && nofLines > 0) { int nof_lines = requested_nof_lines;
while (current > start && nof_lines > 0) {
current--; current--;
if (*current == '\n') nofLines--; if (*current == '\n') nof_lines--;
} }
printf( printf(
"======================================================\n" "======================================================\n"
"Last log lines:\n...%s\n" "Last %i log lines:\n"
"======================================================\n"
"...\n%s\n"
"======================================================\n", "======================================================\n",
current); requested_nof_lines, current);
} }
v8::Local<v8::String> GetLogString() { v8::Local<v8::String> GetLogString() {
...@@ -159,12 +164,14 @@ class ScopedLoggerInitializer { ...@@ -159,12 +164,14 @@ class ScopedLoggerInitializer {
CHECK(exists); CHECK(exists);
} }
const char* GetEndPosition() { return log_.start() + log_.length(); }
const char* FindLine(const char* prefix, const char* suffix = nullptr, const char* FindLine(const char* prefix, const char* suffix = nullptr,
const char* start = nullptr) { const char* start = nullptr) {
// Make sure that StopLogging() has been called before. // Make sure that StopLogging() has been called before.
CHECK(log_.size()); CHECK(log_.size());
if (start == nullptr) start = log_.start(); if (start == nullptr) start = log_.start();
const char* end = log_.start() + log_.length(); const char* end = GetEndPosition();
return FindLogLine(start, end, prefix, suffix); return FindLogLine(start, end, prefix, suffix);
} }
...@@ -176,7 +183,7 @@ class ScopedLoggerInitializer { ...@@ -176,7 +183,7 @@ class ScopedLoggerInitializer {
const char* suffix = pairs[0][1]; const char* suffix = pairs[0][1];
const char* last_position = FindLine(prefix, suffix, start); const char* last_position = FindLine(prefix, suffix, start);
if (last_position == nullptr) { if (last_position == nullptr) {
PrintLog(50); PrintLog(100, start);
V8_Fatal(__FILE__, __LINE__, "Could not find log line: %s ... %s", prefix, V8_Fatal(__FILE__, __LINE__, "Could not find log line: %s ... %s", prefix,
suffix); suffix);
} }
...@@ -186,13 +193,13 @@ class ScopedLoggerInitializer { ...@@ -186,13 +193,13 @@ class ScopedLoggerInitializer {
suffix = pairs[i][1]; suffix = pairs[i][1];
const char* position = FindLine(prefix, suffix, start); const char* position = FindLine(prefix, suffix, start);
if (position == nullptr) { if (position == nullptr) {
PrintLog(50); PrintLog(100, start);
V8_Fatal(__FILE__, __LINE__, "Could not find log line: %s ... %s", V8_Fatal(__FILE__, __LINE__, "Could not find log line: %s ... %s",
prefix, suffix); prefix, suffix);
} }
// Check that all string positions are in order. // Check that all string positions are in order.
if (position <= last_position) { if (position <= last_position) {
PrintLog(50); PrintLog(100, start);
V8_Fatal(__FILE__, __LINE__, V8_Fatal(__FILE__, __LINE__,
"Log statements not in expected order (prev=%p, current=%p): " "Log statements not in expected order (prev=%p, current=%p): "
"%s ... %s", "%s ... %s",
...@@ -1054,8 +1061,19 @@ TEST(LogFunctionEvents) { ...@@ -1054,8 +1061,19 @@ TEST(LogFunctionEvents) {
v8::Isolate::CreateParams create_params; v8::Isolate::CreateParams create_params;
create_params.array_buffer_allocator = CcTest::array_buffer_allocator(); create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
v8::Isolate* isolate = v8::Isolate::New(create_params); v8::Isolate* isolate = v8::Isolate::New(create_params);
{ {
ScopedLoggerInitializer logger(saved_log, saved_prof, isolate); ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
// Run some warmup code to help ignoring existing log entries.
CompileRun(
"function warmUp(a) {"
" let b = () => 1;"
" return function(c) { return a+b+c; };"
"};"
"warmUp(1)(2);"
"(function warmUpEndMarkerFunction(){})();");
const char* source_text = const char* source_text =
"function lazyNotExecutedFunction() { return 'lazy' };" "function lazyNotExecutedFunction() { return 'lazy' };"
"function lazyFunction() { " "function lazyFunction() { "
...@@ -1071,13 +1089,14 @@ TEST(LogFunctionEvents) { ...@@ -1071,13 +1089,14 @@ TEST(LogFunctionEvents) {
logger.StopLogging(); logger.StopLogging();
// TODO(cbruni): Extend with first-execution log statements. // Ignore all the log entries that happened before warmup
CHECK_NULL(
logger.FindLine("function,compile-lazy,", ",lazyNotExecutedFunction"));
// Only consider the log starting from the first preparse statement on.
const char* start = const char* start =
logger.FindLine("function,preparse-", ",lazyNotExecutedFunction"); logger.FindLine("function,first-execution", "warmUpEndMarkerFunction");
CHECK_NOT_NULL(start);
const char* pairs[][2] = { const char* pairs[][2] = {
// Create a new script
{"script,create", nullptr},
{"script-details", nullptr},
// Step 1: parsing top-level script, preparsing functions // Step 1: parsing top-level script, preparsing functions
{"function,preparse-", ",lazyNotExecutedFunction"}, {"function,preparse-", ",lazyNotExecutedFunction"},
// Missing name for preparsing lazyInnerFunction // Missing name for preparsing lazyInnerFunction
...@@ -1092,7 +1111,7 @@ TEST(LogFunctionEvents) { ...@@ -1092,7 +1111,7 @@ TEST(LogFunctionEvents) {
// Step 2: compiling top-level script and eager functions // Step 2: compiling top-level script and eager functions
// - Compiling script without name. // - Compiling script without name.
{"function,compile,,", nullptr}, {"function,compile,", nullptr},
{"function,compile,", ",eagerFunction"}, {"function,compile,", ",eagerFunction"},
// Step 3: start executing script // Step 3: start executing script
......
...@@ -326,7 +326,7 @@ function createFunktionList(metric, time, funktions) { ...@@ -326,7 +326,7 @@ function createFunktionList(metric, time, funktions) {
<h2>Data</h2> <h2>Data</h2>
<form name="fileForm"> <form name="fileForm">
<p> <p>
<input id="uploadInput" type="file" name="files" onchange="loadFile();"> trace entries: <span id="count">0</span> <input id="uploadInput" type="file" name="files" onchange="loadFile();" accept=".log"> trace entries: <span id="count">0</span>
</p> </p>
</form> </form>
......
...@@ -65,12 +65,12 @@ function timestampMin(list) { ...@@ -65,12 +65,12 @@ function timestampMin(list) {
// =========================================================================== // ===========================================================================
class Script { class Script {
constructor(file, id) { constructor(id) {
this.file = file; this.file = '';
this.isNative = false;
this.id = id; this.id = id;
this.isNative = false;
if (id === void 0 || id <= 0) { if (id === void 0 || id <= 0) {
throw new Error(`Invalid id=${id} for script with file='${file}'`); throw new Error(`Invalid id=${id} for script`);
} }
this.isEval = false; this.isEval = false;
this.funktions = []; this.funktions = [];
...@@ -91,7 +91,6 @@ class Script { ...@@ -91,7 +91,6 @@ class Script {
this.ownBytes = -1; this.ownBytes = -1;
this.finalized = false; this.finalized = false;
this.summary = ''; this.summary = '';
this.setFile(file);
} }
setFile(name) { setFile(name) {
...@@ -691,21 +690,30 @@ class ParseProcessor extends LogReader { ...@@ -691,21 +690,30 @@ class ParseProcessor extends LogReader {
// Avoid accidental leaking of __proto__ properties and force this object // Avoid accidental leaking of __proto__ properties and force this object
// to be in dictionary-mode. // to be in dictionary-mode.
__proto__: null, __proto__: null,
// "function", {event type}, // "function",{event type},
// {script file},{script id},{start position},{end position}, // {script id},{start position},{end position},{time},{timestamp},
// {time},{timestamp},{function name} // {function name}
'function': { 'function': {
parsers: [ parsers: [
parseString, parseString, parseInt, parseInt, parseInt, parseFloat, parseString, parseInt, parseInt, parseInt, parseFloat, parseInt,
parseInt, parseString parseString
], ],
processor: this.processFunctionEvent processor: this.processFunctionEvent
}, },
// "compilation-cache", "hit"|"put", {type}, {start position}, // "compilation-cache", "hit"|"put", {type}, {start position},
// {end position} // {end position}
'compilation-cache' : { 'compilation-cache': {
parsers: [parseString, parseString, parseString, parseInt, parseInt], parsers: [parseString, parseString, parseInt, parseInt],
processor: this.processCompilationCacheEvent processor: this.processCompilationCacheEvent
},
'script': {
parsers: [parseString, parseInt],
processor: this.processScriptEvent
},
// "script-details", {script_id}, {file}, {line}, {column}, {size}
'script-details': {
parsers: [parseInt, parseString, parseInt, parseInt, parseInt],
processor: this.processScriptDetails
} }
}; };
this.functionEventDispatchTable_ = { this.functionEventDispatchTable_ = {
...@@ -801,14 +809,14 @@ class ParseProcessor extends LogReader { ...@@ -801,14 +809,14 @@ class ParseProcessor extends LogReader {
} }
processFunctionEvent( processFunctionEvent(
eventName, file, scriptId, startPosition, endPosition, duration, eventName, scriptId, startPosition, endPosition, duration, timestamp,
timestamp, functionName) { functionName) {
let handlerFn = this.functionEventDispatchTable_[eventName]; let handlerFn = this.functionEventDispatchTable_[eventName];
if (handlerFn === undefined) { if (handlerFn === undefined) {
console.error('Couldn\'t find handler for function event:' + eventName); console.error('Couldn\'t find handler for function event:' + eventName);
} }
handlerFn( handlerFn(
file, scriptId, startPosition, endPosition, duration, timestamp, scriptId, startPosition, endPosition, duration, timestamp,
functionName); functionName);
} }
...@@ -816,28 +824,16 @@ class ParseProcessor extends LogReader { ...@@ -816,28 +824,16 @@ class ParseProcessor extends LogReader {
this.entries.push(entry); this.entries.push(entry);
} }
lookupScript(file, id) { lookupScript(id) {
// During preparsing we only have the temporary ranges and no script yet. return this.idToScript.get(id);
let script;
if (this.idToScript.has(id)) {
script = this.idToScript.get(id);
} else {
script = new Script(file, id);
this.idToScript.set(id, script);
}
if (file.length > 0 && script.file.length === 0) {
script.setFile(file);
this.fileToScript.set(file, script);
}
return script;
} }
lookupFunktion(file, scriptId, getOrCreateFunction(
startPosition, endPosition, duration, timestamp, functionName) { scriptId, startPosition, endPosition, duration, timestamp, functionName) {
if (file == "" && scriptId == -1) { if (scriptId == -1) {
return this.lookupFunktionByRange(startPosition, endPosition); return this.lookupFunktionByRange(startPosition, endPosition);
} }
let script = this.lookupScript(file, scriptId); let script = this.lookupScript(scriptId);
let funktion = script.funktionAtPosition(startPosition); let funktion = script.funktionAtPosition(startPosition);
if (funktion === void 0) { if (funktion === void 0) {
funktion = new Funktion(functionName, startPosition, endPosition, script); funktion = new Funktion(functionName, startPosition, endPosition, script);
...@@ -863,21 +859,36 @@ class ParseProcessor extends LogReader { ...@@ -863,21 +859,36 @@ class ParseProcessor extends LogReader {
return results[0]; return results[0];
} }
processEval(file, scriptId, startPosition, processScriptEvent(eventName, scriptId) {
endPosition, duration, timestamp, functionName) { if (eventName == 'create' || eventName == 'reserve-id') {
let script = this.lookupScript(file, scriptId); if (this.idToScript.has(scriptId)) return;
let script = new Script(scriptId);
this.idToScript.set(scriptId, script);
} else {
console.log('Unhandled script event: ' + eventName);
}
}
processScriptDetails(scriptId, file, startLine, startColumn, size) {
let script = this.lookupScript(scriptId);
script.setFile(file);
}
processEval(
scriptId, startPosition, endPosition, duration, timestamp, functionName) {
let script = this.lookupScript(scriptId);
script.isEval = true; script.isEval = true;
} }
processFull(file, scriptId, startPosition, processFull(
endPosition, duration, timestamp, functionName) { scriptId, startPosition, endPosition, duration, timestamp, functionName) {
if (startPosition == 0) { if (startPosition == 0) {
// This should only happen for eval. // This should only happen for eval.
let script = this.lookupScript(file, scriptId); let script = this.lookupScript(scriptId);
script.isEval = true; script.isEval = true;
return; return;
} }
let funktion = this.lookupFunktion(...arguments); let funktion = this.getOrCreateFunction(...arguments);
// TODO(cbruni): this should never happen, emit differen event from the // TODO(cbruni): this should never happen, emit differen event from the
// parser. // parser.
if (funktion.parseTimestamp > 0) return; if (funktion.parseTimestamp > 0) return;
...@@ -885,17 +896,17 @@ class ParseProcessor extends LogReader { ...@@ -885,17 +896,17 @@ class ParseProcessor extends LogReader {
funktion.parseTime = duration; funktion.parseTime = duration;
} }
processParseFunction(file, scriptId, startPosition, processParseFunction(
endPosition, duration, timestamp, functionName) { scriptId, startPosition, endPosition, duration, timestamp, functionName) {
let funktion = this.lookupFunktion(...arguments); let funktion = this.getOrCreateFunction(...arguments);
funktion.parseTimestamp = startOf(timestamp, duration); funktion.parseTimestamp = startOf(timestamp, duration);
funktion.parseTime = duration; funktion.parseTime = duration;
} }
processScript(file, scriptId, startPosition, processScript(
endPosition, duration, timestamp, functionName) { scriptId, startPosition, endPosition, duration, timestamp, functionName) {
// TODO timestamp and duration // TODO timestamp and duration
let script = this.lookupScript(file, scriptId); let script = this.lookupScript(scriptId);
let ts = startOf(timestamp, duration); let ts = startOf(timestamp, duration);
script.parseTimestamp = ts; script.parseTimestamp = ts;
script.firstEventTimestamp = ts; script.firstEventTimestamp = ts;
...@@ -903,9 +914,9 @@ class ParseProcessor extends LogReader { ...@@ -903,9 +914,9 @@ class ParseProcessor extends LogReader {
script.parseTime = duration; script.parseTime = duration;
} }
processPreparseResolution(file, scriptId, processPreparseResolution(
startPosition, endPosition, duration, timestamp, functionName) { scriptId, startPosition, endPosition, duration, timestamp, functionName) {
let funktion = this.lookupFunktion(...arguments); let funktion = this.getOrCreateFunction(...arguments);
// TODO(cbruni): this should never happen, emit different event from the // TODO(cbruni): this should never happen, emit different event from the
// parser. // parser.
if (funktion.resolutionTimestamp > 0) return; if (funktion.resolutionTimestamp > 0) return;
...@@ -913,16 +924,16 @@ class ParseProcessor extends LogReader { ...@@ -913,16 +924,16 @@ class ParseProcessor extends LogReader {
funktion.resolutionTime = duration; funktion.resolutionTime = duration;
} }
processPreparseNoResolution(file, scriptId, processPreparseNoResolution(
startPosition, endPosition, duration, timestamp, functionName) { scriptId, startPosition, endPosition, duration, timestamp, functionName) {
let funktion = this.lookupFunktion(...arguments); let funktion = this.getOrCreateFunction(...arguments);
funktion.preparseTimestamp = startOf(timestamp, duration); funktion.preparseTimestamp = startOf(timestamp, duration);
funktion.preparseTime = duration; funktion.preparseTime = duration;
} }
processFirstExecution(file, scriptId, processFirstExecution(
startPosition, endPosition, duration, timestamp, functionName) { scriptId, startPosition, endPosition, duration, timestamp, functionName) {
let script = this.lookupScript(file, scriptId); let script = this.lookupScript(scriptId);
if (startPosition === 0) { if (startPosition === 0) {
// undefined = eval fn execution // undefined = eval fn execution
if (script) { if (script) {
...@@ -938,17 +949,16 @@ class ParseProcessor extends LogReader { ...@@ -938,17 +949,16 @@ class ParseProcessor extends LogReader {
} }
} }
processCompileLazy(file, scriptId, processCompileLazy(
startPosition, endPosition, duration, timestamp, functionName) { scriptId, startPosition, endPosition, duration, timestamp, functionName) {
let funktion = this.lookupFunktion(...arguments); let funktion = this.getOrCreateFunction(...arguments);
funktion.lazyCompileTimestamp = startOf(timestamp, duration); funktion.lazyCompileTimestamp = startOf(timestamp, duration);
funktion.lazyCompileTime = duration; funktion.lazyCompileTime = duration;
} }
processCompile(file, scriptId, processCompile(
startPosition, endPosition, duration, timestamp, functionName) { scriptId, startPosition, endPosition, duration, timestamp, functionName) {
let script = this.lookupScript(scriptId);
let script = this.lookupScript(file, scriptId);
if (startPosition === 0) { if (startPosition === 0) {
script.compileTimestamp = startOf(timestamp, duration); script.compileTimestamp = startOf(timestamp, duration);
script.compileTime = duration; script.compileTime = duration;
...@@ -964,12 +974,12 @@ class ParseProcessor extends LogReader { ...@@ -964,12 +974,12 @@ class ParseProcessor extends LogReader {
} }
} }
processCompileEval(file, scriptId, processCompileEval(
startPosition, endPosition, duration, timestamp, functionName) { scriptId, startPosition, endPosition, duration, timestamp, functionName) {
} }
processOptimizeLazy(file, scriptId, processOptimizeLazy(
startPosition, endPosition, duration, timestamp, functionName) { scriptId, startPosition, endPosition, duration, timestamp, functionName) {
} }
processCompilationCacheEvent(eventType, cacheType, startPosition, processCompilationCacheEvent(eventType, cacheType, startPosition,
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment