[log] Support --log-function-events in the parser

This partially retires --trace-parse and --trace-preparse which will be fully removed in
a later CL.

Drive-by-fix: make the Parser constructor arguments order more
consistent.

Bug: chromium:757467
Cq-Include-Trybots: master.tryserver.chromium.linux:linux_chromium_rel_ng
Change-Id: I80a688ce553adfa65ad346718604bd53a9e606a9
Reviewed-on: https://chromium-review.googlesource.com/744046
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Reviewed-by: Marja Hölttä <marja@chromium.org>
Cr-Commit-Position: refs/heads/master@{#49350}

src/compiler.cc

@@ -239,7 +239,7 @@ void CompilationJob::RecordFunctionCompilation(
 
   LOG(isolate, FunctionEvent(name.c_str(), nullptr, script->id(), ms,
                              shared->start_position(), shared->end_position(),
-                             shared->name()));
+                             shared->DebugName()));
 }
 
 // ----------------------------------------------------------------------------

src/log-utils.cc

@@ -161,8 +161,8 @@ void Log::MessageBuilder::AppendStringPart(String* str, int len) {
   }
 }
 
-void Log::MessageBuilder::AppendStringPart(const char* str, int len) {
-  for (int i = 0; i < len; i++) {
+void Log::MessageBuilder::AppendStringPart(const char* str, size_t len) {
+  for (size_t i = 0; i < len; i++) {
     DCHECK_NE(str[i], '\0');
     this->AppendCharacter(str[i]);
   }

src/log-utils.h

@@ -78,7 +78,7 @@ class Log {
 
     // Append and escpae a portion of a string.
     void AppendStringPart(String* source, int len);
-    void AppendStringPart(const char* str, int len);
+    void AppendStringPart(const char* str, size_t len);
 
     void AppendCharacter(const char character);
 

src/log.cc

@@ -1283,7 +1283,7 @@ void Logger::FunctionEvent(const char* reason, Script* script, int script_id,
 void Logger::FunctionEvent(const char* reason, Script* script, int script_id,
                            double time_delta, int start_position,
                            int end_position, const char* function_name,
-                           int function_name_length) {
+                           size_t function_name_length) {
   if (!log_->IsEnabled() || !FLAG_log_function_events) return;
   Log::MessageBuilder msg(log_);
   AppendFunctionMessage(msg, reason, script, script_id, time_delta,

src/log.h

@@ -150,7 +150,7 @@ class Logger : public CodeEventListener {
   void FunctionEvent(const char* reason, Script* script, int script_id,
                      double time_delta_ms, int start_position, int end_position,
                      const char* function_name = nullptr,
-                     int function_name_length = 0);
+                     size_t function_name_length = 0);
 
   // ==== Events logged by --log-api. ====
   void ApiSecurityCheck();

src/parsing/parse-info.cc

@@ -155,6 +155,7 @@ void ParseInfo::InitFromIsolate(Isolate* isolate) {
   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();

src/parsing/parse-info.h

@@ -28,6 +28,7 @@ class AstValueFactory;
 class DeclarationScope;
 class FunctionLiteral;
 class RuntimeCallStats;
+class Logger;
 class ScriptData;
 class SourceRangeMap;
 class UnicodeCache;
@@ -187,6 +188,8 @@ class V8_EXPORT_PRIVATE ParseInfo {
   void set_runtime_call_stats(RuntimeCallStats* runtime_call_stats) {
     runtime_call_stats_ = runtime_call_stats;
   }
+  Logger* logger() const { return logger_; }
+  void set_logger(Logger* logger) { logger_ = logger; }
 
   void AllocateSourceRangeMap();
   SourceRangeMap* source_range_map() const { return source_range_map_; }
@@ -284,6 +287,7 @@ class V8_EXPORT_PRIVATE ParseInfo {
   const class AstStringConstants* ast_string_constants_;
   const AstRawString* function_name_;
   RuntimeCallStats* runtime_call_stats_;
+  Logger* logger_;
   SourceRangeMap* source_range_map_;  // Used when block coverage is enabled.
 
   //----------- Output of parsing and scope analysis ------------------------

src/parsing/parser-base.h

@@ -14,6 +14,7 @@
 #include "src/base/hashmap.h"
 #include "src/counters.h"
 #include "src/globals.h"
+#include "src/log.h"
 #include "src/messages.h"
 #include "src/parsing/expression-classifier.h"
 #include "src/parsing/func-name-inferrer.h"
@@ -252,9 +253,9 @@ class ParserBase {
 
   ParserBase(Zone* zone, Scanner* scanner, uintptr_t stack_limit,
              v8::Extension* extension, AstValueFactory* ast_value_factory,
-             RuntimeCallStats* runtime_call_stats, bool parsing_module,
              PendingCompilationErrorHandler* pending_error_handler,
-             bool parsing_on_main_thread = true)
+             RuntimeCallStats* runtime_call_stats, Logger* logger,
+             int script_id, bool parsing_module, bool parsing_on_main_thread)
       : scope_(nullptr),
         original_scope_(nullptr),
         function_state_(nullptr),
@@ -263,6 +264,7 @@ class ParserBase {
         ast_value_factory_(ast_value_factory),
         ast_node_factory_(ast_value_factory, zone),
         runtime_call_stats_(runtime_call_stats),
+        logger_(logger),
         parsing_on_main_thread_(parsing_on_main_thread),
         parsing_module_(parsing_module),
         stack_limit_(stack_limit),
@@ -272,6 +274,7 @@ class ParserBase {
         scanner_(scanner),
         default_eager_compile_hint_(FunctionLiteral::kShouldLazyCompile),
         function_literal_id_(0),
+        script_id_(script_id),
         allow_natives_(false),
         allow_harmony_do_expressions_(false),
         allow_harmony_function_sent_(false),
@@ -659,6 +662,8 @@ class ParserBase {
     return pending_error_handler()->stack_overflow();
   }
   void set_stack_overflow() { pending_error_handler()->set_stack_overflow(); }
+  int script_id() { return script_id_; }
+  void set_script_id(int id) { script_id_ = id; }
 
   INLINE(Token::Value peek()) {
     if (stack_overflow()) return Token::ILLEGAL;
@@ -1508,6 +1513,7 @@ class ParserBase {
   AstValueFactory* ast_value_factory_;  // Not owned.
   typename Types::Factory ast_node_factory_;
   RuntimeCallStats* runtime_call_stats_;
+  internal::Logger* logger_;
   bool parsing_on_main_thread_;
   const bool parsing_module_;
   uintptr_t stack_limit_;
@@ -1524,6 +1530,7 @@ class ParserBase {
   FunctionLiteral::EagerCompileHint default_eager_compile_hint_;
 
   int function_literal_id_;
+  int script_id_;
 
   bool allow_natives_;
   bool allow_harmony_do_expressions_;
@@ -4317,6 +4324,8 @@ ParserBase<Impl>::ParseArrowFunctionLiteral(
   RuntimeCallTimerScope runtime_timer(
       runtime_call_stats_,
       counters[Impl::IsPreParser()][parsing_on_main_thread_]);
+  base::ElapsedTimer timer;
+  if (V8_UNLIKELY(FLAG_log_function_events)) timer.Start();
 
   if (peek() == Token::ARROW && scanner_->HasAnyLineTerminatorBeforeNext()) {
     // ASI inserts `;` after arrow parameters if a line terminator is found.
@@ -4416,12 +4425,6 @@ ParserBase<Impl>::ParseArrowFunctionLiteral(
     impl()->RewriteDestructuringAssignments();
   }
 
-  if (FLAG_trace_preparse) {
-    Scope* scope = formal_parameters.scope;
-    PrintF("  [%s]: %i-%i (arrow function)\n",
-           is_lazy_top_level_function ? "Preparse no-resolution" : "Full parse",
-           scope->start_position(), scope->end_position());
-  }
   FunctionLiteralT function_literal = factory()->NewFunctionLiteral(
       impl()->EmptyIdentifierString(), formal_parameters.scope, body,
       expected_property_count, formal_parameters.num_parameters(),
@@ -4436,6 +4439,17 @@ ParserBase<Impl>::ParseArrowFunctionLiteral(
 
   impl()->AddFunctionForNameInference(function_literal);
 
+  if (V8_UNLIKELY((FLAG_log_function_events))) {
+    Scope* scope = formal_parameters.scope;
+    double ms = timer.Elapsed().InMillisecondsF();
+    const char* event_name =
+        is_lazy_top_level_function ? "preparse-no-resolution" : "parse";
+    const char* name = "arrow function";
+    logger_->FunctionEvent(event_name, nullptr, script_id(), ms,
+                           scope->start_position(), scope->end_position(), name,
+                           strlen(name));
+  }
+
   return function_literal;
 }
 

src/parsing/parser.cc

@@ -15,6 +15,7 @@
 #include "src/base/platform/platform.h"
 #include "src/char-predicates-inl.h"
 #include "src/compiler-dispatcher/compiler-dispatcher.h"
+#include "src/log.h"
 #include "src/messages.h"
 #include "src/objects-inl.h"
 #include "src/parsing/duplicate-finder.h"
@@ -498,8 +499,10 @@ Expression* Parser::NewV8Intrinsic(const AstRawString* name,
 Parser::Parser(ParseInfo* info)
     : ParserBase<Parser>(info->zone(), &scanner_, info->stack_limit(),
                          info->extension(), info->GetOrCreateAstValueFactory(),
-                         info->runtime_call_stats(), info->is_module(),
-                         info->pending_error_handler(), true),
+                         info->pending_error_handler(),
+                         info->runtime_call_stats(), info->logger(),
+                         info->script().is_null() ? -1 : info->script()->id(),
+                         info->is_module(), true),
       scanner_(info->unicode_cache(), use_counts_),
       reusable_preparser_(nullptr),
       mode_(PARSE_EAGERLY),  // Lazy mode must be set explicitly.
@@ -591,9 +594,7 @@ FunctionLiteral* Parser::ParseProgram(Isolate* isolate, ParseInfo* info) {
                                            : &RuntimeCallStats::ParseProgram);
   TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), "V8.ParseProgram");
   base::ElapsedTimer timer;
-  if (FLAG_trace_parse) {
-    timer.Start();
-  }
+  if (V8_UNLIKELY(FLAG_log_function_events)) timer.Start();
   fni_ = new (zone()) FuncNameInferrer(ast_value_factory(), zone());
 
   // Initialize parser state.
@@ -617,23 +618,25 @@ FunctionLiteral* Parser::ParseProgram(Isolate* isolate, ParseInfo* info) {
 
   HandleSourceURLComments(isolate, info->script());
 
-  if (FLAG_trace_parse && result != nullptr) {
-    double ms = timer.Elapsed().InMillisecondsF();
-    if (info->is_eval()) {
-      PrintF("[parsing eval");
-    } else if (info->script()->name()->IsString()) {
-      String* name = String::cast(info->script()->name());
-      std::unique_ptr<char[]> name_chars = name->ToCString();
-      PrintF("[parsing script: %s", name_chars.get());
-    } else {
-      PrintF("[parsing script");
-    }
-    PrintF(" - took %0.3f ms]\n", ms);
-  }
   if (produce_cached_parse_data() && result != nullptr) {
     *info->cached_data() = logger.GetScriptData();
   }
   log_ = nullptr;
+
+  if (V8_UNLIKELY(FLAG_log_function_events) && result != nullptr) {
+    double ms = timer.Elapsed().InMillisecondsF();
+    const char* event_name = "parse-eval";
+    Script* script = *info->script();
+    int start = -1;
+    int end = -1;
+    if (!info->is_eval()) {
+      event_name = "parse-script";
+      start = 0;
+      end = String::cast(script->source())->length();
+    }
+    LOG(script->GetIsolate(),
+        FunctionEvent(event_name, script, -1, ms, start, end, "", 0));
+  }
   return result;
 }
 
@@ -755,9 +758,8 @@ FunctionLiteral* Parser::ParseFunction(Isolate* isolate, ParseInfo* info,
                                       &RuntimeCallStats::ParseFunction);
   TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("v8.compile"), "V8.ParseFunction");
   base::ElapsedTimer timer;
-  if (FLAG_trace_parse) {
-    timer.Start();
-  }
+  if (V8_UNLIKELY(FLAG_log_function_events)) timer.Start();
+
   DeserializeScopeChain(info, info->maybe_outer_scope_info());
   DCHECK_EQ(factory()->zone(), info->zone());
 
@@ -773,12 +775,18 @@ FunctionLiteral* Parser::ParseFunction(Isolate* isolate, ParseInfo* info,
     result->set_inferred_name(inferred_name);
   }
 
-  if (FLAG_trace_parse && result != nullptr) {
+  if (V8_UNLIKELY(FLAG_log_function_events) && result != nullptr) {
     double ms = timer.Elapsed().InMillisecondsF();
     // We need to make sure that the debug-name is available.
     ast_value_factory()->Internalize(isolate);
-    std::unique_ptr<char[]> name_chars = result->GetDebugName();
-    PrintF("[parsing function: %s - took %0.3f ms]\n", name_chars.get(), ms);
+    DeclarationScope* function_scope = result->scope();
+    Script* script = *info->script();
+    std::unique_ptr<char[]> function_name = result->GetDebugName();
+    LOG(script->GetIsolate(),
+        FunctionEvent("parse-function", script, -1, ms,
+                      function_scope->start_position(),
+                      function_scope->end_position(), function_name.get(),
+                      strlen(function_name.get())));
   }
   return result;
 }
@@ -2587,6 +2595,8 @@ FunctionLiteral* Parser::ParseFunctionLiteral(
       parsing_on_main_thread_
           ? &RuntimeCallStats::ParseFunctionLiteral
           : &RuntimeCallStats::ParseBackgroundFunctionLiteral);
+  base::ElapsedTimer timer;
+  if (V8_UNLIKELY(FLAG_log_function_events)) timer.Start();
 
   // Determine whether we can still lazy parse the inner function.
   // The preconditions are:
@@ -2687,13 +2697,17 @@ FunctionLiteral* Parser::ParseFunctionLiteral(
     }
 
     DCHECK_EQ(should_preparse, temp_zoned_);
-    if (V8_UNLIKELY(FLAG_trace_preparse)) {
-      PrintF("  [%s]: %i-%i %.*s\n",
-             should_preparse ? (is_top_level ? "Preparse no-resolution"
-                                             : "Preparse resolution")
-                             : "Full parse",
-             scope->start_position(), scope->end_position(),
-             function_name->byte_length(), function_name->raw_data());
+    if (V8_UNLIKELY(FLAG_log_function_events)) {
+      double ms = timer.Elapsed().InMillisecondsF();
+      const char* event_name = should_preparse
+                                   ? (is_top_level ? "preparse-no-resolution"
+                                                   : "preparse-resolution")
+                                   : "full-parse";
+      logger_->FunctionEvent(
+          event_name, nullptr, script_id(), ms, scope->start_position(),
+          scope->end_position(),
+          reinterpret_cast<const char*>(function_name->raw_data()),
+          function_name->byte_length());
     }
     if (V8_UNLIKELY(FLAG_runtime_stats)) {
       if (should_preparse) {
@@ -2821,7 +2835,7 @@ Parser::LazyParsingResult Parser::SkipFunction(
 
   PreParser::PreParseResult result = reusable_preparser()->PreParseFunction(
       function_name, kind, function_type, function_scope, is_inner_function,
-      may_abort, use_counts_, produced_preparsed_scope_data);
+      may_abort, use_counts_, produced_preparsed_scope_data, this->script_id());
 
   // Return immediately if pre-parser decided to abort parsing.
   if (result == PreParser::kPreParseAbort) return kLazyParsingAborted;
@@ -3463,6 +3477,9 @@ void Parser::UpdateStatistics(Isolate* isolate, Handle<Script> script) {
 
 void Parser::ParseOnBackground(ParseInfo* info) {
   parsing_on_main_thread_ = false;
+  if (!info->script().is_null()) {
+    set_script_id(info->script()->id());
+  }
 
   DCHECK_NULL(info->literal());
   FunctionLiteral* result = nullptr;

src/parsing/parser.h

@@ -285,8 +285,8 @@ class V8_EXPORT_PRIVATE Parser : public NON_EXPORTED_BASE(ParserBase<Parser>) {
     if (reusable_preparser_ == nullptr) {
       reusable_preparser_ =
           new PreParser(zone(), &scanner_, stack_limit_, ast_value_factory(),
-                        pending_error_handler(), runtime_call_stats_,
-                        parsing_module_, parsing_on_main_thread_);
+                        pending_error_handler(), runtime_call_stats_, logger_,
+                        -1, parsing_module_, parsing_on_main_thread_);
 #define SET_ALLOW(name) reusable_preparser_->set_allow_##name(allow_##name());
       SET_ALLOW(natives);
       SET_ALLOW(harmony_do_expressions);

src/parsing/preparser.cc

@@ -119,12 +119,13 @@ PreParser::PreParseResult PreParser::PreParseFunction(
     const AstRawString* function_name, FunctionKind kind,
     FunctionLiteral::FunctionType function_type,
     DeclarationScope* function_scope, bool is_inner_function, bool may_abort,
-    int* use_counts,
-    ProducedPreParsedScopeData** produced_preparsed_scope_data) {
+    int* use_counts, ProducedPreParsedScopeData** produced_preparsed_scope_data,
+    int script_id) {
   DCHECK_EQ(FUNCTION_SCOPE, function_scope->scope_type());
   use_counts_ = use_counts;
   DCHECK(!track_unresolved_variables_);
   track_unresolved_variables_ = is_inner_function;
+  set_script_id(script_id);
 #ifdef DEBUG
   function_scope->set_is_being_lazily_parsed(true);
 #endif
@@ -277,6 +278,9 @@ PreParser::Expression PreParser::ParseFunctionLiteral(
       runtime_call_stats_,
       counters[track_unresolved_variables_][parsing_on_main_thread_]);
 
+  base::ElapsedTimer timer;
+  if (V8_UNLIKELY(FLAG_log_function_events)) timer.Start();
+
   DeclarationScope* function_scope = NewFunctionScope(kind);
   function_scope->SetLanguageMode(language_mode);
 
@@ -342,11 +346,23 @@ PreParser::Expression PreParser::ParseFunctionLiteral(
     produced_preparsed_scope_data_scope->MarkFunctionAsSkippable(
         end_position, GetLastFunctionLiteralId() - func_id);
   }
-  if (FLAG_trace_preparse) {
-    PrintF("  [%s]: %i-%i\n",
-           track_unresolved_variables_ ? "Preparse resolution"
-                                       : "Preparse no-resolution",
-           function_scope->start_position(), function_scope->end_position());
+  if (V8_UNLIKELY(FLAG_log_function_events)) {
+    double ms = timer.Elapsed().InMillisecondsF();
+    const char* event_name = track_unresolved_variables_
+                                 ? "preparse-resolution"
+                                 : "preparse-no-resolution";
+    // We might not always get a function name here. However, it can be easily
+    // reconstructed from the script id and the byte range in the log processor.
+    const char* name = "";
+    size_t name_byte_length = 0;
+    const AstRawString* string = function_name.string_;
+    if (string != nullptr) {
+      name = reinterpret_cast<const char*>(string->raw_data());
+      name_byte_length = string->byte_length();
+    }
+    logger_->FunctionEvent(
+        event_name, nullptr, script_id(), ms, function_scope->start_position(),
+        function_scope->end_position(), name, name_byte_length);
   }
 
   return Expression::Default();

src/parsing/preparser.h

@@ -881,12 +881,13 @@ class PreParser : public ParserBase<PreParser> {
   PreParser(Zone* zone, Scanner* scanner, uintptr_t stack_limit,
             AstValueFactory* ast_value_factory,
             PendingCompilationErrorHandler* pending_error_handler,
-            RuntimeCallStats* runtime_call_stats, bool parsing_module = false,
+            RuntimeCallStats* runtime_call_stats, Logger* logger,
+            int script_id = -1, bool parsing_module = false,
             bool parsing_on_main_thread = true)
       : ParserBase<PreParser>(zone, scanner, stack_limit, nullptr,
-                              ast_value_factory, runtime_call_stats,
-                              parsing_module, pending_error_handler,
-                              parsing_on_main_thread),
+                              ast_value_factory, pending_error_handler,
+                              runtime_call_stats, logger, script_id,
+                              parsing_module, parsing_on_main_thread),
         use_counts_(nullptr),
         track_unresolved_variables_(false),
         produced_preparsed_scope_data_(nullptr) {}
@@ -914,7 +915,8 @@ class PreParser : public ParserBase<PreParser> {
       FunctionLiteral::FunctionType function_type,
       DeclarationScope* function_scope, bool track_unresolved_variables,
       bool may_abort, int* use_counts,
-      ProducedPreParsedScopeData** produced_preparser_scope_data);
+      ProducedPreParsedScopeData** produced_preparser_scope_data,
+      int script_id);
 
   ProducedPreParsedScopeData* produced_preparsed_scope_data() const {
     return produced_preparsed_scope_data_;

test/cctest/test-log.cc

@@ -68,11 +68,11 @@ static const char* StrNStr(const char* s1, const char* s2, size_t n) {
   return strstr(s1, s2);
 }
 
-// Look for a log line which starts with {prefix} and ends with {suffix}.
-static const char* FindLogLine(i::Vector<const char>* log, const char* prefix,
+static const char* FindLogLine(const char* start, const char* end,
+                               const char* prefix,
                                const char* suffix = nullptr) {
-  const char* start = log->start();
-  const char* end = start + log->length();
+  CHECK_LT(start, end);
+  // Look for a log line which starts with {prefix} and ends with {suffix}.
   CHECK_EQ(end[0], '\0');
   size_t prefixLength = strlen(prefix);
   // Loop through the input until we find /{prefix}[^\n]+{suffix}/.
@@ -123,7 +123,24 @@ class ScopedLoggerInitializer {
 
   Logger* logger() { return logger_; }
 
-  void PrintLog() { printf("%s", log_.start()); }
+  void PrintLog(int nofLines = 0) {
+    if (nofLines <= 0) {
+      printf("%s", log_.start());
+      return;
+    }
+    // Try to print the last {nofLines} of the log.
+    const char* start = log_.start();
+    const char* current = log_.end();
+    while (current > start && nofLines > 0) {
+      current--;
+      if (*current == '\n') nofLines--;
+    }
+    printf(
+        "======================================================\n"
+        "Last log lines:\n...%s\n"
+        "======================================================",
+        current);
+  }
 
   v8::Local<v8::String> GetLogString() {
     return v8::String::NewFromUtf8(isolate_, log_.start(),
@@ -137,21 +154,46 @@ class ScopedLoggerInitializer {
     CHECK(exists);
   }
 
-  const char* FindLine(const char* prefix, const char* suffix = nullptr) {
+  const char* FindLine(const char* prefix, const char* suffix = nullptr,
+                       const char* start = nullptr) {
     // Make sure that StopLogging() has been called before.
     CHECK(log_.size());
-    return FindLogLine(&log_, prefix, suffix);
+    if (start == nullptr) start = log_.start();
+    const char* end = log_.start() + log_.length();
+    return FindLogLine(start, end, prefix, suffix);
   }
 
   // Find all log lines specified by the {prefix, suffix} pairs and ensure they
   // occurr in the specified order.
-  void FindLogLines(const char* pairs[][2], size_t limit) {
-    const char* last_position = FindLine(pairs[0][0], pairs[0][1]);
+  void FindLogLines(const char* pairs[][2], size_t limit,
+                    const char* start = nullptr) {
+    const char* prefix = pairs[0][0];
+    const char* suffix = pairs[0][1];
+    const char* last_position = FindLine(prefix, suffix, start);
+    if (last_position == nullptr) {
+      PrintLog(50);
+      V8_Fatal(__FILE__, __LINE__, "Could not find log line: %s ... %s", prefix,
+               suffix);
+    }
     CHECK(last_position);
     for (size_t i = 1; i < limit; i++) {
-      const char* position = FindLine(pairs[i][0], pairs[i][1]);
+      prefix = pairs[i][0];
+      suffix = pairs[i][1];
+      const char* position = FindLine(prefix, suffix, start);
+      if (position == nullptr) {
+        PrintLog(50);
+        V8_Fatal(__FILE__, __LINE__, "Could not find log line: %s ... %s",
+                 prefix, suffix);
+      }
       // Check that all string positions are in order.
-      CHECK_LT(last_position, position);
+      if (position <= last_position) {
+        PrintLog(50);
+        V8_Fatal(__FILE__, __LINE__,
+                 "Log statements not in expected order (prev=%p, current=%p): "
+                 "%s ... %s",
+                 reinterpret_cast<const void*>(last_position),
+                 reinterpret_cast<const void*>(position), prefix, suffix);
+      }
       last_position = position;
     }
   }
@@ -192,21 +234,22 @@ TEST(FindLogLine) {
       "prefix2, stuff\n, suffix2\n"
       "prefix3suffix3\n"
       "prefix4 suffix4";
+  const char* end = string + strlen(string);
   // Make sure the vector contains the terminating \0 character.
-  i::Vector<const char> log(string, strlen(string));
-  CHECK(FindLogLine(&log, "prefix1, stuff,   suffix1"));
-  CHECK(FindLogLine(&log, "prefix1, stuff"));
-  CHECK(FindLogLine(&log, "prefix1"));
-  CHECK(FindLogLine(&log, "prefix1", "suffix1"));
-  CHECK(FindLogLine(&log, "prefix1", "suffix1"));
-  CHECK(!FindLogLine(&log, "prefix2", "suffix2"));
-  CHECK(!FindLogLine(&log, "prefix1", "suffix2"));
-  CHECK(!FindLogLine(&log, "prefix1", "suffix3"));
-  CHECK(FindLogLine(&log, "prefix3", "suffix3"));
-  CHECK(FindLogLine(&log, "prefix4", "suffix4"));
-  CHECK(!FindLogLine(&log, "prefix4", "suffix4XXXXXXXXXXXX"));
-  CHECK(!FindLogLine(&log, "prefix4XXXXXXXXXXXXXXXXXXXXXXxxx", "suffix4"));
-  CHECK(!FindLogLine(&log, "suffix", "suffix5XXXXXXXXXXXXXXXXXXXX"));
+  CHECK(FindLogLine(string, end, "prefix1, stuff,   suffix1"));
+  CHECK(FindLogLine(string, end, "prefix1, stuff"));
+  CHECK(FindLogLine(string, end, "prefix1"));
+  CHECK(FindLogLine(string, end, "prefix1", "suffix1"));
+  CHECK(FindLogLine(string, end, "prefix1", "suffix1"));
+  CHECK(!FindLogLine(string, end, "prefix2", "suffix2"));
+  CHECK(!FindLogLine(string, end, "prefix1", "suffix2"));
+  CHECK(!FindLogLine(string, end, "prefix1", "suffix3"));
+  CHECK(FindLogLine(string, end, "prefix3", "suffix3"));
+  CHECK(FindLogLine(string, end, "prefix4", "suffix4"));
+  CHECK(!FindLogLine(string, end, "prefix4", "suffix4XXXXXXXXXXXX"));
+  CHECK(
+      !FindLogLine(string, end, "prefix4XXXXXXXXXXXXXXXXXXXXXXxxx", "suffix4"));
+  CHECK(!FindLogLine(string, end, "suffix", "suffix5XXXXXXXXXXXXXXXXXXXX"));
 }
 
 // BUG(913). Need to implement support for profiling multiple VM threads.
@@ -785,22 +828,60 @@ TEST(LogFunctionEvents) {
   v8::Isolate* isolate = v8::Isolate::New(create_params);
   {
     ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
-    // Try to create many different kind of maps to make sure the logging won't
-    // crash. More detailed tests are implemented separately.
     const char* source_text =
         "function lazyNotExecutedFunction() { return 'lazy' };"
-        "function lazyFunction() { return 'lazy' };"
-        "lazyFunction();"
-        "(function eagerFunction(){ return 'eager' })();";
+        "function lazyFunction() { "
+        "  function lazyInnerFunction() { return 'lazy' };"
+        "  return lazyInnerFunction;"
+        "};"
+        "let innerFn = lazyFunction();"
+        "innerFn();"
+        "(function eagerFunction(){ return 'eager' })();"
+        "function Foo() { this.foo = function(){}; };"
+        "let i = new Foo(); i.foo();";
     CompileRun(source_text);
 
     logger.StopLogging();
 
-    // TODO(cbruni): Extend with parsing/first-execution log statements.
+    // TODO(cbruni): Extend with first-execution log statements.
     CHECK_NULL(
         logger.FindLine("function,compile-lazy,", ",lazyNotExecutedFunction"));
-    CHECK(logger.FindLine("function,compile-lazy,", ",lazyFunction"));
-    CHECK(logger.FindLine("function,compile,", ",eagerFunction"));
+    // Only consider the log starting from the first preparse statement on.
+    const char* start =
+        logger.FindLine("function,preparse-", ",lazyNotExecutedFunction");
+    const char* pairs[][2] = {
+        // Step 1: parsing top-level script, preparsing functions
+        {"function,preparse-", ",lazyNotExecutedFunction"},
+        // Missing name for preparsing lazyInnerFunction
+        // {"function,preparse-", nullptr},
+        {"function,preparse-", ",lazyFunction"},
+        {"function,full-parse,", ",eagerFunction"},
+        {"function,preparse-", ",Foo"},
+        // Missing name for inner preparsing of Foo.foo
+        // {"function,preparse-", nullptr},
+        // Missing name for top-level script.
+        {"function,parse-script,", nullptr},
+
+        // Step 2: compiling top-level script and eager functions
+        // - Compiling script without name.
+        {"function,compile,,", nullptr},
+        {"function,compile,", ",eagerFunction"},
+
+        // Step 3: start executing script
+        // Step 4. - lazy parse, lazy compiling and execute skipped functions
+        //         - execute eager functions.
+        {"function,parse-function,", ",lazyFunction"},
+        {"function,compile-lazy,", ",lazyFunction"},
+
+        {"function,parse-function,", ",lazyInnerFunction"},
+        {"function,compile-lazy,", ",lazyInnerFunction"},
+
+        {"function,parse-function,", ",Foo"},
+        {"function,compile-lazy,", ",Foo"},
+        {"function,parse-function,", ",Foo.foo"},
+        {"function,compile-lazy,", ",Foo.foo"},
+    };
+    logger.FindLogLines(pairs, arraysize(pairs), start);
   }
   i::FLAG_log_function_events = false;
   isolate->Dispose();

test/cctest/test-parsing.cc

@@ -134,6 +134,7 @@ TEST(ScanKeywords) {
 TEST(ScanHTMLEndComments) {
   v8::V8::Initialize();
   v8::Isolate* isolate = CcTest::isolate();
+  i::Isolate* i_isolate = CcTest::i_isolate();
   v8::HandleScope handles(isolate);
 
   // Regression test. See:
@@ -182,23 +183,23 @@ TEST(ScanHTMLEndComments) {
   // clang-format on
 
   // Parser/Scanner needs a stack limit.
-  CcTest::i_isolate()->stack_guard()->SetStackLimit(
-      i::GetCurrentStackPosition() - 128 * 1024);
-  uintptr_t stack_limit = CcTest::i_isolate()->stack_guard()->real_climit();
+  i_isolate->stack_guard()->SetStackLimit(i::GetCurrentStackPosition() -
+                                          128 * 1024);
+  uintptr_t stack_limit = i_isolate->stack_guard()->real_climit();
   for (int i = 0; tests[i]; i++) {
     const char* source = tests[i];
     auto stream = i::ScannerStream::ForTesting(source);
-    i::Scanner scanner(CcTest::i_isolate()->unicode_cache(), global_use_counts);
+    i::Scanner scanner(i_isolate->unicode_cache(), global_use_counts);
     scanner.Initialize(stream.get(), false);
-    i::Zone zone(CcTest::i_isolate()->allocator(), ZONE_NAME);
-    i::AstValueFactory ast_value_factory(
-        &zone, CcTest::i_isolate()->ast_string_constants(),
-        CcTest::i_isolate()->heap()->HashSeed());
+    i::Zone zone(i_isolate->allocator(), ZONE_NAME);
+    i::AstValueFactory ast_value_factory(&zone,
+                                         i_isolate->ast_string_constants(),
+                                         i_isolate->heap()->HashSeed());
     i::PendingCompilationErrorHandler pending_error_handler;
-    i::PreParser preparser(
-        &zone, &scanner, stack_limit, &ast_value_factory,
-        &pending_error_handler,
-        CcTest::i_isolate()->counters()->runtime_call_stats());
+    i::PreParser preparser(&zone, &scanner, stack_limit, &ast_value_factory,
+                           &pending_error_handler,
+                           i_isolate->counters()->runtime_call_stats(),
+                           i_isolate->logger());
     i::PreParser::PreParseResult result = preparser.PreParseProgram();
     CHECK_EQ(i::PreParser::kPreParseSuccess, result);
     CHECK(!pending_error_handler.has_pending_error());
@@ -207,17 +208,17 @@ TEST(ScanHTMLEndComments) {
   for (int i = 0; fail_tests[i]; i++) {
     const char* source = fail_tests[i];
     auto stream = i::ScannerStream::ForTesting(source);
-    i::Scanner scanner(CcTest::i_isolate()->unicode_cache(), global_use_counts);
+    i::Scanner scanner(i_isolate->unicode_cache(), global_use_counts);
     scanner.Initialize(stream.get(), false);
-    i::Zone zone(CcTest::i_isolate()->allocator(), ZONE_NAME);
-    i::AstValueFactory ast_value_factory(
-        &zone, CcTest::i_isolate()->ast_string_constants(),
-        CcTest::i_isolate()->heap()->HashSeed());
+    i::Zone zone(i_isolate->allocator(), ZONE_NAME);
+    i::AstValueFactory ast_value_factory(&zone,
+                                         i_isolate->ast_string_constants(),
+                                         i_isolate->heap()->HashSeed());
     i::PendingCompilationErrorHandler pending_error_handler;
-    i::PreParser preparser(
-        &zone, &scanner, stack_limit, &ast_value_factory,
-        &pending_error_handler,
-        CcTest::i_isolate()->counters()->runtime_call_stats());
+    i::PreParser preparser(&zone, &scanner, stack_limit, &ast_value_factory,
+                           &pending_error_handler,
+                           i_isolate->counters()->runtime_call_stats(),
+                           i_isolate->logger());
     i::PreParser::PreParseResult result = preparser.PreParseProgram();
     // Even in the case of a syntax error, kPreParseSuccess is returned.
     CHECK_EQ(i::PreParser::kPreParseSuccess, result);
@@ -383,9 +384,10 @@ TEST(PreparseFunctionDataIsUsed) {
 
 TEST(StandAlonePreParser) {
   v8::V8::Initialize();
+  i::Isolate* i_isolate = CcTest::i_isolate();
 
-  CcTest::i_isolate()->stack_guard()->SetStackLimit(
-      i::GetCurrentStackPosition() - 128 * 1024);
+  i_isolate->stack_guard()->SetStackLimit(i::GetCurrentStackPosition() -
+                                          128 * 1024);
 
   const char* programs[] = {"{label: 42}",
                             "var x = 42;",
@@ -395,21 +397,21 @@ TEST(StandAlonePreParser) {
                             "var f = (x, y) => x + y;",
                             nullptr};
 
-  uintptr_t stack_limit = CcTest::i_isolate()->stack_guard()->real_climit();
+  uintptr_t stack_limit = i_isolate->stack_guard()->real_climit();
   for (int i = 0; programs[i]; i++) {
     auto stream = i::ScannerStream::ForTesting(programs[i]);
-    i::Scanner scanner(CcTest::i_isolate()->unicode_cache(), global_use_counts);
+    i::Scanner scanner(i_isolate->unicode_cache(), global_use_counts);
     scanner.Initialize(stream.get(), false);
 
-    i::Zone zone(CcTest::i_isolate()->allocator(), ZONE_NAME);
-    i::AstValueFactory ast_value_factory(
-        &zone, CcTest::i_isolate()->ast_string_constants(),
-        CcTest::i_isolate()->heap()->HashSeed());
+    i::Zone zone(i_isolate->allocator(), ZONE_NAME);
+    i::AstValueFactory ast_value_factory(&zone,
+                                         i_isolate->ast_string_constants(),
+                                         i_isolate->heap()->HashSeed());
     i::PendingCompilationErrorHandler pending_error_handler;
-    i::PreParser preparser(
-        &zone, &scanner, stack_limit, &ast_value_factory,
-        &pending_error_handler,
-        CcTest::i_isolate()->counters()->runtime_call_stats());
+    i::PreParser preparser(&zone, &scanner, stack_limit, &ast_value_factory,
+                           &pending_error_handler,
+                           i_isolate->counters()->runtime_call_stats(),
+                           i_isolate->logger());
     preparser.set_allow_natives(true);
     i::PreParser::PreParseResult result = preparser.PreParseProgram();
     CHECK_EQ(i::PreParser::kPreParseSuccess, result);
@@ -442,7 +444,8 @@ TEST(StandAlonePreParserNoNatives) {
     i::PendingCompilationErrorHandler pending_error_handler;
     i::PreParser preparser(&zone, &scanner, stack_limit, &ast_value_factory,
                            &pending_error_handler,
-                           isolate->counters()->runtime_call_stats());
+                           isolate->counters()->runtime_call_stats(),
+                           isolate->logger());
     i::PreParser::PreParseResult result = preparser.PreParseProgram();
     CHECK_EQ(i::PreParser::kPreParseSuccess, result);
     CHECK(pending_error_handler.has_pending_error());
@@ -508,10 +511,10 @@ TEST(RegressChromium62639) {
       &zone, CcTest::i_isolate()->ast_string_constants(),
       CcTest::i_isolate()->heap()->HashSeed());
   i::PendingCompilationErrorHandler pending_error_handler;
-  i::PreParser preparser(&zone, &scanner,
-                         CcTest::i_isolate()->stack_guard()->real_climit(),
-                         &ast_value_factory, &pending_error_handler,
-                         isolate->counters()->runtime_call_stats());
+  i::PreParser preparser(
+      &zone, &scanner, CcTest::i_isolate()->stack_guard()->real_climit(),
+      &ast_value_factory, &pending_error_handler,
+      isolate->counters()->runtime_call_stats(), isolate->logger());
   i::PreParser::PreParseResult result = preparser.PreParseProgram();
   // Even in the case of a syntax error, kPreParseSuccess is returned.
   CHECK_EQ(i::PreParser::kPreParseSuccess, result);
@@ -584,9 +587,9 @@ TEST(PreParseOverflow) {
       &zone, CcTest::i_isolate()->ast_string_constants(),
       CcTest::i_isolate()->heap()->HashSeed());
   i::PendingCompilationErrorHandler pending_error_handler;
-  i::PreParser preparser(&zone, &scanner, stack_limit, &ast_value_factory,
-                         &pending_error_handler,
-                         isolate->counters()->runtime_call_stats());
+  i::PreParser preparser(
+      &zone, &scanner, stack_limit, &ast_value_factory, &pending_error_handler,
+      isolate->counters()->runtime_call_stats(), isolate->logger());
   i::PreParser::PreParseResult result = preparser.PreParseProgram();
   CHECK_EQ(i::PreParser::kPreParseStackOverflow, result);
 }
@@ -1374,7 +1377,7 @@ void TestParserSyncWithFlags(i::Handle<i::String> source,
     i::PreParser preparser(&zone, &scanner, stack_limit, &ast_value_factory,
                            &pending_error_handler,
                            isolate->counters()->runtime_call_stats(),
-                           is_module);
+                           isolate->logger(), -1, is_module);
     SetParserFlags(&preparser, flags);
     scanner.Initialize(stream.get(), is_module);
     i::PreParser::PreParseResult result = preparser.PreParseProgram();