[logging] Add an option to log source code in v8.log.

Bug: v8:6239
Change-Id: I87f72cb97616e28cb44f7160d5170ff740422419
Reviewed-on: https://chromium-review.googlesource.com/584612
Commit-Queue: Jaroslav Sevcik <jarin@chromium.org>
Reviewed-by: Benedikt Meurer <bmeurer@chromium.org>
Cr-Commit-Position: refs/heads/master@{#46958}

src/flag-definitions.h

@@ -1126,6 +1126,7 @@ DEFINE_BOOL(log_gc, false,
             "Log heap samples on garbage collection for the hp2ps tool.")
 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(prof, false,
             "Log statistical profiling information (implies --log-code).")
 

src/log-utils.cc

@@ -18,14 +18,11 @@ namespace internal {
 const char* const Log::kLogToTemporaryFile = "&";
 const char* const Log::kLogToConsole = "-";
 
-
 Log::Log(Logger* logger)
-  : is_stopped_(false),
-    output_handle_(NULL),
-    message_buffer_(NULL),
-    logger_(logger) {
-}
-
+    : is_stopped_(false),
+      output_handle_(NULL),
+      message_buffer_(NULL),
+      logger_(logger) {}
 
 void Log::Initialize(const char* log_file_name) {
   message_buffer_ = NewArray<char>(kMessageBufferSize);
@@ -81,7 +78,6 @@ void Log::OpenFile(const char* name) {
   output_handle_ = base::OS::FOpen(name, base::OS::LogFileOpenMode);
 }
 
-
 FILE* Log::Close() {
   FILE* result = NULL;
   if (output_handle_ != NULL) {
@@ -211,6 +207,41 @@ void Log::MessageBuilder::AppendDetailed(String* str, bool show_impl_info) {
   }
 }
 
+void Log::MessageBuilder::AppendUnbufferedHeapString(String* str) {
+  if (str == NULL) return;
+  DisallowHeapAllocation no_gc;  // Ensure string stay valid.
+  ScopedVector<char> buffer(16);
+  int len = str->length();
+  for (int i = 0; i < len; i++) {
+    uc32 c = str->Get(i);
+    if (c >= 32 && c <= 126) {
+      if (c == '\"') {
+        AppendUnbufferedCString("\"\"");
+      } else if (c == '\\') {
+        AppendUnbufferedCString("\\\\");
+      } else {
+        AppendUnbufferedChar(c);
+      }
+    } else if (c > 0xff) {
+      int length = v8::internal::SNPrintF(buffer, "\\u%04x", c);
+      DCHECK_EQ(6, length);
+      log_->WriteToFile(buffer.start(), length);
+    } else {
+      DCHECK(c <= 0xffff);
+      int length = v8::internal::SNPrintF(buffer, "\\x%02x", c);
+      DCHECK_EQ(4, length);
+      log_->WriteToFile(buffer.start(), length);
+    }
+  }
+}
+
+void Log::MessageBuilder::AppendUnbufferedChar(char c) {
+  log_->WriteToFile(&c, 1);
+}
+
+void Log::MessageBuilder::AppendUnbufferedCString(const char* str) {
+  log_->WriteToFile(str, static_cast<int>(strlen(str)));
+}
 
 void Log::MessageBuilder::AppendStringPart(const char* str, int len) {
   if (pos_ + len > Log::kMessageBufferSize) {
@@ -225,7 +256,6 @@ void Log::MessageBuilder::AppendStringPart(const char* str, int len) {
   DCHECK(pos_ <= Log::kMessageBufferSize);
 }
 
-
 void Log::MessageBuilder::WriteToLogFile() {
   DCHECK(pos_ <= Log::kMessageBufferSize);
   // Assert that we do not already have a new line at the end.
@@ -239,6 +269,5 @@ void Log::MessageBuilder::WriteToLogFile() {
   }
 }
 
-
 }  // namespace internal
 }  // namespace v8

src/log-utils.h

@@ -31,7 +31,7 @@ class Log {
   static bool InitLogAtStart() {
     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_perf_basic_prof || FLAG_perf_prof || FLAG_log_source_code ||
            FLAG_log_internal_timer_events || FLAG_prof_cpp || FLAG_trace_ic;
   }
 
@@ -87,6 +87,13 @@ class Log {
     // Append a portion of a string.
     void AppendStringPart(const char* str, int len);
 
+    // Helpers for appending char, C-string and heap string without
+    // buffering. This is useful for entries that can exceed the 2kB
+    // limit.
+    void AppendUnbufferedChar(char c);
+    void AppendUnbufferedCString(const char* str);
+    void AppendUnbufferedHeapString(String* source);
+
     // Write the log message to the log file currently opened.
     void WriteToLogFile();
 
@@ -114,7 +121,6 @@ class Log {
     size_t rv = fwrite(msg, 1, length, output_handle_);
     DCHECK_EQ(length, rv);
     USE(rv);
-    fflush(output_handle_);
     return length;
   }
 

src/log.cc

@@ -1119,22 +1119,131 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                              Name* source, int line, int column) {
   if (!is_logging_code_events()) return;
   if (!FLAG_log_code || !log_->IsEnabled()) return;
-  Log::MessageBuilder msg(log_);
-  AppendCodeCreateHeader(&msg, tag, code, &timer_);
-  std::unique_ptr<char[]> name =
-      shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
-  msg.Append("\"%s ", name.get());
-  if (source->IsString()) {
-    std::unique_ptr<char[]> sourcestr = String::cast(source)->ToCString(
-        DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
-    msg.Append("%s", sourcestr.get());
-  } else {
-    msg.AppendSymbolName(Symbol::cast(source));
+
+  {
+    Log::MessageBuilder msg(log_);
+    AppendCodeCreateHeader(&msg, tag, code, &timer_);
+    std::unique_ptr<char[]> name =
+        shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
+    msg.Append("\"%s ", name.get());
+    if (source->IsString()) {
+      std::unique_ptr<char[]> sourcestr = String::cast(source)->ToCString(
+          DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
+      msg.Append("%s", sourcestr.get());
+    } else {
+      msg.AppendSymbolName(Symbol::cast(source));
+    }
+    msg.Append(":%d:%d\",", line, column);
+    msg.AppendAddress(shared->address());
+    msg.Append(",%s", ComputeMarker(shared, code));
+    msg.WriteToLogFile();
+  }
+
+  if (FLAG_log_source_code) {
+    Object* script_object = shared->script();
+    if (script_object->IsScript()) {
+      // Make sure the script is written to the log file.
+      std::ostringstream os;
+      Script* script = Script::cast(script_object);
+      int script_id = script->id();
+      if (logged_source_code_.find(script_id) == logged_source_code_.end()) {
+        // This script has not been logged yet.
+        logged_source_code_.insert(script_id);
+        Object* source_object = script->source();
+        if (source_object->IsString()) {
+          Log::MessageBuilder msg(log_);
+          String* source_code = String::cast(source_object);
+          os << "script," << script_id << ",\"";
+          msg.AppendUnbufferedCString(os.str().c_str());
+          msg.AppendUnbufferedHeapString(source_code);
+          os.str("");
+          os << "\"" << std::endl;
+          msg.AppendUnbufferedCString(os.str().c_str());
+          os.str("");
+        }
+      }
+
+      // We log source code information in the form:
+      //
+      // code-source-info <addr>,<script>,<start>,<end>,<pos>,<inline-pos>,<fns>
+      //
+      // where
+      //   <addr> is code object address
+      //   <script> is script id
+      //   <start> is the starting position inside the script
+      //   <end> is the end position inside the script
+      //   <pos> is source position table encoded in the string,
+      //      it is a sequence of C<code-offset>O<script-offset>[I<inlining-id>]
+      //      where
+      //        <code-offset> is the offset within the code object
+      //        <script-offset> is the position within the script
+      //        <inlining-id> is the offset in the <inlining> table
+      //   <inlining> table is a sequence of strings of the form
+      //      F<function-id>O<script-offset>[I<inlining-id>
+      //      where
+      //         <function-id> is an index into the <fns> function table
+      //   <fns> is the function table encoded as a sequence of strings
+      //      S<shared-function-info-address>
+      os << "code-source-info," << static_cast<void*>(code->address()) << ","
+         << script_id << "," << shared->start_position() << ","
+         << shared->end_position() << ",";
+
+      SourcePositionTableIterator iterator(code->source_position_table());
+      bool is_first = true;
+      bool hasInlined = false;
+      for (; !iterator.done(); iterator.Advance()) {
+        if (is_first) {
+          is_first = false;
+        }
+        SourcePosition pos = iterator.source_position();
+        os << "C" << iterator.code_offset();
+        os << "O" << pos.ScriptOffset();
+        if (pos.isInlined()) {
+          os << "I" << pos.InliningId();
+          hasInlined = true;
+        }
+      }
+      os << ",";
+      int maxInlinedId = -1;
+      if (hasInlined) {
+        PodArray<InliningPosition>* inlining_positions =
+            DeoptimizationInputData::cast(
+                Code::cast(code)->deoptimization_data())
+                ->InliningPositions();
+        for (int i = 0; i < inlining_positions->length(); i++) {
+          InliningPosition inlining_pos = inlining_positions->get(i);
+          os << "F";
+          if (inlining_pos.inlined_function_id != -1) {
+            os << inlining_pos.inlined_function_id;
+            if (inlining_pos.inlined_function_id > maxInlinedId) {
+              maxInlinedId = inlining_pos.inlined_function_id;
+            }
+          }
+          SourcePosition pos = inlining_pos.position;
+          os << "O" << pos.ScriptOffset();
+          if (pos.isInlined()) {
+            os << "I" << pos.InliningId();
+          }
+        }
+      }
+      os << ",";
+      if (hasInlined) {
+        DeoptimizationInputData* deopt_data = DeoptimizationInputData::cast(
+            Code::cast(code)->deoptimization_data());
+
+        os << std::hex;
+        for (int i = 0; i <= maxInlinedId; i++) {
+          os << "S"
+             << static_cast<void*>(
+                    deopt_data->GetInlinedFunction(i)->address());
+        }
+        os << std::dec;
+      }
+      os << std::endl;
+      Log::MessageBuilder msg(log_);
+      msg.AppendUnbufferedCString(os.str().c_str());
+    }
   }
-  msg.Append(":%d:%d\",", line, column);
-  msg.AppendAddress(shared->address());
-  msg.Append(",%s", ComputeMarker(shared, code));
-  msg.WriteToLogFile();
 }
 
 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
@@ -1750,6 +1859,7 @@ bool Logger::SetUp(Isolate* isolate) {
   is_initialized_ = true;
 
   std::ostringstream log_file_name;
+  std::ostringstream source_log_file_name;
   PrepareLogFileName(log_file_name, isolate, FLAG_logfile);
   log_->Initialize(log_file_name.str().c_str());
 

src/log.h

@@ -5,6 +5,7 @@
 #ifndef V8_LOG_H_
 #define V8_LOG_H_
 
+#include <set>
 #include <string>
 
 #include "src/allocation.h"
@@ -322,6 +323,8 @@ class Logger : public CodeEventListener {
   JitLogger* jit_logger_;
   std::unique_ptr<ProfilerListener> profiler_listener_;
   List<CodeEventListener*> listeners_;
+  std::set<int> logged_source_code_;
+  uint32_t next_source_info_id_ = 0;
 
   // Guards against multiple calls to TearDown() that can happen in some tests.
   // 'true' between SetUp() and TearDown().

tools/profile.js

@@ -210,6 +210,21 @@ Profile.prototype.deleteCode = function(start) {
   }
 };
 
+/**
+ * Adds source positions for given code.
+ */
+Profile.prototype.addSourcePositions = function(
+    start, script, startPos, endPos, sourcePositions, inliningPositions,
+    inlinedFunctions) {
+  // CLI does not need source code => ignore.
+};
+
+/**
+ * Adds script source code.
+ */
+Profile.prototype.addScriptSource = function(script, source) {
+  // CLI does not need source code => ignore.
+};
 
 /**
  * Reports about moving of a dynamic code entry.
@@ -850,6 +865,7 @@ function JsonProfile() {
   this.codeEntries_ = [];
   this.functionEntries_ = [];
   this.ticks_ = [];
+  this.scripts_ = [];
 }
 
 JsonProfile.prototype.addLibrary = function(
@@ -952,6 +968,68 @@ JsonProfile.prototype.moveCode = function(from, to) {
   }
 };
 
+JsonProfile.prototype.addSourcePositions = function(
+    start, script, startPos, endPos, sourcePositions, inliningPositions,
+    inlinedFunctions) {
+  var entry = this.codeMap_.findDynamicEntryByStartAddress(start);
+  if (!entry) return;
+  var codeId = entry.codeId;
+
+  // Resolve the inlined fucntions list.
+  if (inlinedFunctions.length > 0) {
+    inlinedFunctions = inlinedFunctions.substring(1).split("S");
+    for (var i = 0; i < inlinedFunctions.length; i++) {
+      var funcAddr = parseInt(inlinedFunctions[i]);
+      var func = this.codeMap_.findDynamicEntryByStartAddress(funcAddr);
+      if (!func || func.funcId === undefined) {
+        printErr("Could not find function " + inlinedFunctions[i]);
+        inlinedFunctions[i] = null;
+      } else {
+        inlinedFunctions[i] = func.funcId;
+      }
+    }
+  } else {
+    inlinedFunctions = [];
+  }
+
+  this.codeEntries_[entry.codeId].source = {
+    script : script,
+    start : startPos,
+    end : endPos,
+    positions : sourcePositions,
+    inlined : inliningPositions,
+    fns : inlinedFunctions
+  };
+};
+
+function unescapeString(s) {
+  s = s.split("\\");
+  for (var i = 1; i < s.length; i++) {
+    if (s[i] === "") {
+      // Double backslash.
+      s[i] = "\\";
+    } else if (i > 0 && s[i].startsWith("x")) {
+      // Escaped Ascii character.
+      s[i] = String.fromCharCode(parseInt(s[i].substring(1, 3), 16)) +
+          s[i].substring(3);
+    } else if (i > 0 && s[i].startsWith("u")) {
+      // Escaped unicode character.
+      s[i] = String.fromCharCode(parseInt(s[i].substring(1, 5), 16)) +
+          s[i].substring(5);
+    } else {
+      if (i > 0 && s[i - 1] !== "\\") {
+        printErr("Malformed source string");
+      }
+    }
+  }
+  return s.join("");
+}
+
+JsonProfile.prototype.addScriptSource = function(script, source) {
+  this.scripts_[script] = unescapeString(source);
+};
+
+
 JsonProfile.prototype.deoptCode = function(
     timestamp, code, inliningId, scriptOffset, bailoutType,
     sourcePositionText, deoptReasonText) {
@@ -1007,21 +1085,37 @@ JsonProfile.prototype.recordTick = function(time_ns, vmState, stack) {
   this.ticks_.push({ tm : time_ns, vm : vmState, s : processedStack });
 };
 
+function writeJson(s) {
+  write(JSON.stringify(s, null, 2));
+}
+
 JsonProfile.prototype.writeJson = function() {
   // Write out the JSON in a partially manual way to avoid creating too-large
   // strings in one JSON.stringify call when there are a lot of ticks.
   write('{\n')
-  write('  "code": ' + JSON.stringify(this.codeEntries_) + ',\n');
-  write('  "functions": ' + JSON.stringify(this.functionEntries_) + ',\n');
+
+  write('  "code": ');
+  writeJson(this.codeEntries_);
+  write(',\n');
+
+  write('  "functions": ');
+  writeJson(this.functionEntries_);
+  write(',\n');
+
   write('  "ticks": [\n');
   for (var i = 0; i < this.ticks_.length; i++) {
-    write('    ' + JSON.stringify(this.ticks_[i]));
+    write('    ');
+    writeJson(this.ticks_[i]);
     if (i < this.ticks_.length - 1) {
       write(',\n');
     } else {
       write('\n');
     }
   }
-  write('  ]\n');
+  write('  ],\n');
+
+  write('  "scripts": ');
+  writeJson(this.scripts_);
+
   write('}\n');
 };

tools/tickprocessor.js

@@ -116,6 +116,12 @@ function TickProcessor(
           processor: this.processCodeMove },
       'code-delete': { parsers: [parseInt],
           processor: this.processCodeDelete },
+      'code-source-info': {
+          parsers: [parseInt, parseInt, parseInt, parseInt, null, null, null],
+          processor: this.processCodeSourceInfo },
+      'script': {
+          parsers: [parseInt, null],
+          processor: this.processCodeScript },
       'sfi-move': { parsers: [parseInt, parseInt],
           processor: this.processFunctionMove },
       'active-runtime-timer': {
@@ -313,11 +319,20 @@ TickProcessor.prototype.processCodeMove = function(from, to) {
   this.profile_.moveCode(from, to);
 };
 
-
 TickProcessor.prototype.processCodeDelete = function(start) {
   this.profile_.deleteCode(start);
 };
 
+TickProcessor.prototype.processCodeSourceInfo = function(
+    start, script, startPos, endPos, sourcePositions, inliningPositions,
+    inlinedFunctions) {
+  this.profile_.addSourcePositions(start, script, startPos,
+    endPos, sourcePositions, inliningPositions, inlinedFunctions);
+};
+
+TickProcessor.prototype.processCodeScript = function(script, source) {
+  this.profile_.addScriptSource(script, source);
+};
 
 TickProcessor.prototype.processFunctionMove = function(from, to) {
   this.profile_.moveFunc(from, to);