[log] Support logging basic function events

This CL contains the base implementation for logging function events.
Currently only compiler events are support (compile, compile-lazy...),
future CLs will enable log events for parsing and first-time exeuction
of functions.

Bug: chromium:757467
Change-Id: Ia705979190a3ebc1009989610483a7a141bc504b
Reviewed-on: https://chromium-review.googlesource.com/743921
Reviewed-by: Igor Sheludko <ishell@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/master@{#49040}

src/compiler.cc

@@ -179,43 +179,74 @@ void CompilationJob::RecordOptimizedCompilationStats() const {
   }
 }
 
+void CompilationJob::RecordFunctionCompilation(
+    CodeEventListener::LogEventsAndTags tag) const {
+  // Log the code generation. If source information is available include
+  // script name and line number. Check explicitly whether logging is
+  // enabled as finding the line number is not free.
+  CompilationInfo* compilation_info = this->compilation_info();
+  Isolate* isolate = compilation_info->isolate();
+  if (!isolate->logger()->is_logging_code_events() &&
+      !isolate->is_profiling() && !FLAG_log_function_events) {
+    return;
+  }
+
+  Handle<SharedFunctionInfo> shared = compilation_info->shared_info();
+  Handle<Script> script = parse_info()->script();
+  Handle<AbstractCode> abstract_code =
+      compilation_info->has_bytecode_array()
+          ? Handle<AbstractCode>::cast(compilation_info->bytecode_array())
+          : Handle<AbstractCode>::cast(compilation_info->code());
+
+  if (abstract_code.is_identical_to(
+          BUILTIN_CODE(compilation_info->isolate(), CompileLazy))) {
+    return;
+  }
+
+  int line_num = Script::GetLineNumber(script, shared->start_position()) + 1;
+  int column_num =
+      Script::GetColumnNumber(script, shared->start_position()) + 1;
+  String* script_name = script->name()->IsString()
+                            ? String::cast(script->name())
+                            : isolate->heap()->empty_string();
+  CodeEventListener::LogEventsAndTags log_tag =
+      Logger::ToNativeByScript(tag, *script);
+  PROFILE(isolate, CodeCreateEvent(log_tag, *abstract_code, *shared,
+                                   script_name, line_num, column_num));
+  if (!FLAG_log_function_events) return;
+
+  DisallowHeapAllocation no_gc;
+
+  double ms = time_taken_to_prepare_.InMillisecondsF();
+  ms += time_taken_to_execute_.InMillisecondsF();
+  ms += time_taken_to_finalize_.InMillisecondsF();
+
+  std::string name = compilation_info->IsOptimizing() ? "optimize" : "compile";
+  switch (tag) {
+    case CodeEventListener::EVAL_TAG:
+      name += "-eval";
+      break;
+    case CodeEventListener::SCRIPT_TAG:
+      break;
+    case CodeEventListener::LAZY_COMPILE_TAG:
+      name += "-lazy";
+      break;
+    case CodeEventListener::FUNCTION_TAG:
+      break;
+    default:
+      UNREACHABLE();
+  }
+
+  LOG(isolate, FunctionEvent(name.c_str(), nullptr, script->id(), ms,
+                             shared->start_position(), shared->end_position(),
+                             shared->name()));
+}
+
 // ----------------------------------------------------------------------------
 // Local helper methods that make up the compilation pipeline.
 
 namespace {
 
-void RecordFunctionCompilation(CodeEventListener::LogEventsAndTags tag,
-                               Handle<Script> script,
-                               CompilationInfo* compilation_info) {
-  // Log the code generation. If source information is available include
-  // script name and line number. Check explicitly whether logging is
-  // enabled as finding the line number is not free.
-  if (compilation_info->isolate()->logger()->is_logging_code_events() ||
-      compilation_info->isolate()->is_profiling()) {
-    Handle<SharedFunctionInfo> shared = compilation_info->shared_info();
-    Handle<AbstractCode> abstract_code =
-        compilation_info->has_bytecode_array()
-            ? Handle<AbstractCode>::cast(compilation_info->bytecode_array())
-            : Handle<AbstractCode>::cast(compilation_info->code());
-    if (abstract_code.is_identical_to(
-            BUILTIN_CODE(compilation_info->isolate(), CompileLazy))) {
-      return;
-    }
-    int line_num = Script::GetLineNumber(script, shared->start_position()) + 1;
-    int column_num =
-        Script::GetColumnNumber(script, shared->start_position()) + 1;
-    String* script_name =
-        script->name()->IsString()
-            ? String::cast(script->name())
-            : compilation_info->isolate()->heap()->empty_string();
-    CodeEventListener::LogEventsAndTags log_tag =
-        Logger::ToNativeByScript(tag, *script);
-    PROFILE(compilation_info->isolate(),
-            CodeCreateEvent(log_tag, *abstract_code, *shared, script_name,
-                            line_num, column_num));
-  }
-}
-
 void EnsureFeedbackMetadata(CompilationInfo* compilation_info) {
   DCHECK(compilation_info->has_shared_info());
 
@@ -333,7 +364,7 @@ CompilationJob::Status FinalizeUnoptimizedCompilationJob(CompilationJob* job) {
       log_tag = parse_info->lazy_compile() ? CodeEventListener::LAZY_COMPILE_TAG
                                            : CodeEventListener::FUNCTION_TAG;
     }
-    RecordFunctionCompilation(log_tag, parse_info->script(), compilation_info);
+    job->RecordFunctionCompilation(log_tag);
     job->RecordUnoptimizedCompilationStats();
   }
   return status;
@@ -536,8 +567,7 @@ bool GetOptimizedCodeNow(CompilationJob* job) {
   job->RecordOptimizedCompilationStats();
   DCHECK(!isolate->has_pending_exception());
   InsertCodeIntoOptimizedCodeCache(compilation_info);
-  RecordFunctionCompilation(CodeEventListener::LAZY_COMPILE_TAG,
+  job->RecordFunctionCompilation(CodeEventListener::LAZY_COMPILE_TAG);
-                            job->parse_info()->script(), compilation_info);
   return true;
 }
 
@@ -713,8 +743,7 @@ CompilationJob::Status FinalizeOptimizedCompilationJob(CompilationJob* job) {
       job->RetryOptimization(kBailedOutDueToDependencyChange);
     } else if (job->FinalizeJob() == CompilationJob::SUCCEEDED) {
       job->RecordOptimizedCompilationStats();
-      RecordFunctionCompilation(CodeEventListener::LAZY_COMPILE_TAG,
+      job->RecordFunctionCompilation(CodeEventListener::LAZY_COMPILE_TAG);
-                                job->parse_info()->script(), compilation_info);
       InsertCodeIntoOptimizedCodeCache(compilation_info);
       if (FLAG_trace_opt) {
         PrintF("[completed optimizing ");

src/compiler.h

@@ -9,6 +9,7 @@
 
 #include "src/allocation.h"
 #include "src/bailout-reason.h"
+#include "src/code-events.h"
 #include "src/contexts.h"
 #include "src/isolate.h"
 #include "src/zone/zone.h"
@@ -189,6 +190,7 @@ class V8_EXPORT_PRIVATE CompilationJob {
 
   void RecordOptimizedCompilationStats() const;
   void RecordUnoptimizedCompilationStats() const;
+  void RecordFunctionCompilation(CodeEventListener::LogEventsAndTags tag) const;
 
   void set_stack_limit(uintptr_t stack_limit) { stack_limit_ = stack_limit; }
   uintptr_t stack_limit() const { return stack_limit_; }

src/flag-definitions.h

@@ -1097,6 +1097,9 @@ DEFINE_BOOL(log_gc, false,
 DEFINE_BOOL(log_handles, false, "Log global handle events.")
 DEFINE_BOOL(log_suspect, false, "Log suspect operations.")
 DEFINE_BOOL(log_source_code, false, "Log source code.")
+DEFINE_BOOL(log_function_events, false,
+            "Log function events "
+            "(parse, compile, execute) separately.")
 DEFINE_BOOL(prof, false,
             "Log statistical profiling information (implies --log-code).")
 

src/log-utils.cc

@@ -46,6 +46,7 @@ Log::Log(Logger* logger, const char* file_name)
     FLAG_log_suspect = true;
     FLAG_log_handles = true;
     FLAG_log_internal_timer_events = true;
+    FLAG_log_function_events = true;
   }
 
   // --prof implies --log-code.

src/log-utils.h

@@ -33,7 +33,8 @@ class Log {
     return FLAG_log || FLAG_log_api || FLAG_log_code || FLAG_log_gc ||
            FLAG_log_handles || FLAG_log_suspect || FLAG_ll_prof ||
            FLAG_perf_basic_prof || FLAG_perf_prof || FLAG_log_source_code ||
-           FLAG_log_internal_timer_events || FLAG_prof_cpp || FLAG_trace_ic;
+           FLAG_log_internal_timer_events || FLAG_prof_cpp || FLAG_trace_ic ||
+           FLAG_log_function_events;
   }
 
   // Frees all resources acquired in Initialize and Open... functions.

src/log.cc

@@ -1264,6 +1264,50 @@ void Logger::SuspectReadEvent(Name* name, Object* obj) {
   msg.WriteToLogFile();
 }
 
+namespace {
+void AppendFunctionMessage(Log::MessageBuilder& msg, const char* reason,
+                           Script* script, int script_id, double time_delta,
+                           int start_position, int end_position,
+                           base::ElapsedTimer* timer) {
+  msg << "function" << Logger::kNext << reason << Logger::kNext;
+  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
+      << timer->Elapsed().InMicroseconds() << Logger::kNext;
+}
+}  // namespace
+
+void Logger::FunctionEvent(const char* reason, Script* script, int script_id,
+                           double time_delta, int start_position,
+                           int end_position, String* function_name) {
+  if (!log_->IsEnabled() || !FLAG_log_function_events) return;
+  Log::MessageBuilder msg(log_);
+  AppendFunctionMessage(msg, reason, script, script_id, time_delta,
+                        start_position, end_position, &timer_);
+  if (function_name) msg << function_name;
+  msg.WriteToLogFile();
+}
+
+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) {
+  if (!log_->IsEnabled() || !FLAG_log_function_events) return;
+  Log::MessageBuilder msg(log_);
+  AppendFunctionMessage(msg, reason, script, script_id, time_delta,
+                        start_position, end_position, &timer_);
+  if (function_name_length > 0) {
+    msg.AppendStringPart(function_name, function_name_length);
+  }
+  msg.WriteToLogFile();
+}
 
 void Logger::HeapSampleBeginEvent(const char* space, const char* kind) {
   if (!log_->IsEnabled() || !FLAG_log_gc) return;

src/log.h

@@ -145,6 +145,14 @@ class Logger : public CodeEventListener {
   // object.
   void SuspectReadEvent(Name* name, Object* obj);
 
+  void FunctionEvent(const char* reason, Script* script, int script_id,
+                     double time_delta_ms, int start_position = -1,
+                     int end_position = -1, String* function_name = nullptr);
+  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);
+
   // ==== Events logged by --log-api. ====
   void ApiSecurityCheck();
   void ApiNamedPropertyAccess(const char* tag, JSObject* holder, Object* name);

test/cctest/test-log.cc

@@ -776,3 +776,32 @@ TEST(ConsoleTimeEvents) {
 
   isolate->Dispose();
 }
+
+TEST(LogFunctionEvents) {
+  SETUP_FLAGS();
+  i::FLAG_log_function_events = true;
+  v8::Isolate::CreateParams create_params;
+  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
+  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' })();";
+    CompileRun(source_text);
+
+    logger.StopLogging();
+
+    // TODO(cbruni): Extend with parsing/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"));
+  }
+  i::FLAG_log_function_events = false;
+  isolate->Dispose();
+}