[tools] Improve function event logging and parse processor

- Log script sources with --log-function-events
- Don't show confusing duration in graphs
- Introduce separate compilation category
- Log script details after deserialization
- Log parse times for eval scripts
- Display deserialized scripts and functions

Change-Id: I58f3bf8efe3955632322f958716c36ad38761fd0
Bug: chromium:757467, chromium:850038
Reviewed-on: https://chromium-review.googlesource.com/1128082Reviewed-by: Yang Guo <yangguo@chromium.org>
Reviewed-by: Sathya Gunasekaran <gsathya@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/master@{#54465}

src/compiler.cc

@@ -970,7 +970,7 @@ BackgroundCompileTask::BackgroundCompileTask(ScriptStreamingData* source,
   // Prepare the data for the internalization phase and compilation phase, which
   // will happen in the main thread after parsing.
   ParseInfo* info = new ParseInfo(isolate);
-  LOG(isolate, ScriptEvent(Logger::ScriptEventType::kBackgroundCompile,
+  LOG(isolate, ScriptEvent(Logger::ScriptEventType::kStreamingCompile,
                            info->script_id()));
   if (V8_UNLIKELY(FLAG_runtime_stats)) {
     info->set_runtime_call_stats(new (info->zone()) RuntimeCallStats());

src/log.cc

@@ -1549,25 +1549,18 @@ void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
   msg.WriteToLogFile();
 }
 
-namespace {
-void AppendCompilationCacheMessage(Log::MessageBuilder& msg,
+void Logger::CompilationCacheEvent(const char* action, const char* cache_type,
                                    SharedFunctionInfo* sfi) {
+  if (!log_->IsEnabled() || !FLAG_log_function_events) return;
+  Log::MessageBuilder msg(log_);
   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);
+      << cache_type << Logger::kNext << script_id << Logger::kNext
+      << sfi->StartPosition() << Logger::kNext << sfi->EndPosition()
+      << Logger::kNext << timer_.Elapsed().InMicroseconds();
   msg.WriteToLogFile();
 }
 
@@ -1588,24 +1581,31 @@ void Logger::ScriptEvent(ScriptEventType type, int script_id) {
     case ScriptEventType::kBackgroundCompile:
       msg << "background-compile";
       break;
+    case ScriptEventType::kStreamingCompile:
+      msg << "streaming-compile";
+      break;
   }
-  msg << Logger::kNext << script_id;
+  msg << Logger::kNext << script_id << Logger::kNext
+      << timer_.Elapsed().InMicroseconds();
   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());
+  {
+    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();
   }
-  msg.WriteToLogFile();
+  EnsureLogScriptSource(script);
 }
 
 bool Logger::EnsureLogScriptSource(Script* script) {

src/log.h

@@ -128,7 +128,8 @@ class Logger : public CodeEventListener {
     kReserveId,
     kCreate,
     kDeserialize,
-    kBackgroundCompile
+    kBackgroundCompile,
+    kStreamingCompile
   };
 
   // The separator is used to write an unescaped "," into the log.

src/snapshot/code-serializer.cc

@@ -276,7 +276,7 @@ MaybeHandle<SharedFunctionInfo> CodeSerializer::Deserialize(
     Isolate* isolate, ScriptData* cached_data, Handle<String> source,
     ScriptOriginOptions origin_options) {
   base::ElapsedTimer timer;
-  if (FLAG_profile_deserialization) timer.Start();
+  if (FLAG_profile_deserialization || FLAG_log_function_events) timer.Start();
 
   HandleScope scope(isolate);
 
@@ -311,15 +311,24 @@ MaybeHandle<SharedFunctionInfo> CodeSerializer::Deserialize(
     PrintF("[Deserializing from %d bytes took %0.3f ms]\n", length, ms);
   }
 
-  if (isolate->logger()->is_listening_to_code_events() ||
-      isolate->is_profiling()) {
+  bool log_code_creation = isolate->logger()->is_listening_to_code_events() ||
+                           isolate->is_profiling();
+  if (log_code_creation || FLAG_log_function_events) {
     String* name = ReadOnlyRoots(isolate).empty_string();
     if (result->script()->IsScript()) {
       Script* script = Script::cast(result->script());
       if (script->name()->IsString()) name = String::cast(script->name());
+      if (FLAG_log_function_events) {
+        LOG(isolate, FunctionEvent("deserialize", script->id(),
+                                   timer.Elapsed().InMillisecondsF(),
+                                   result->StartPosition(),
+                                   result->EndPosition(), name));
+      }
+    }
+    if (log_code_creation) {
+      PROFILE(isolate, CodeCreateEvent(CodeEventListener::SCRIPT_TAG,
+                                       result->abstract_code(), *result, name));
     }
-    PROFILE(isolate, CodeCreateEvent(CodeEventListener::SCRIPT_TAG,
-                                     result->abstract_code(), *result, name));
   }
 
   if (isolate->NeedsSourcePositionsForProfiling()) {

src/snapshot/deserializer.cc

@@ -172,6 +172,7 @@ HeapObject* Deserializer<AllocatorT>::PostProcessNewObject(HeapObject* obj,
   } else if (obj->IsScript()) {
     LOG(isolate_, ScriptEvent(Logger::ScriptEventType::kDeserialize,
                               Script::cast(obj)->id()));
+    LOG(isolate_, ScriptDetails(Script::cast(obj)));
   }
 
   if (obj->IsAllocationSite()) {

src/snapshot/object-deserializer.cc

@@ -83,6 +83,7 @@ void ObjectDeserializer::CommitPostProcessedObjects() {
     script->set_id(isolate()->heap()->NextScriptId());
     LOG(isolate(),
         ScriptEvent(Logger::ScriptEventType::kDeserialize, script->id()));
+    LOG(isolate(), ScriptDetails(*script));
     // Add script to list.
     Handle<Object> list =
         FixedArrayOfWeakCells::Add(isolate(), factory->script_list(), script);

tools/parse-processor.html

@@ -66,34 +66,38 @@ code is governed by a BSD-style license that can be found in the LICENSE file.
   }
 
   .script-size {
-    display: inline-block;
+    display: inline-flex;
     background-color: #505050;
     border-radius: 3px;
     padding: 3px;
     margin: 2px;
     white-space: nowrap;
     overflow: hidden;
-    min-width: 2em;
     text-decoration: none;
     color: white;
   }
   .script-size.eval {
     background-color: #ee6300fc;
-
   }
-  .script-size.background {
+  .script-size.streaming {
     background-color: #008aff;
   }
+  .script-size.deserialized {
+    background-color: #1fad00fc;
+  }
 
-  .script-id {
-    display: inline;
-    padding-right: 2px;
-    margin-right: 2px;
-    border-right: 1px grey dotted;
+  .script-details {
+    padding-right: 5px;
+    margin-right: 4px;
   }
-  .script-url {
-    display: inline;
-    text-overflow: ellipis;
+  /* all but the last need a border  */
+  .script-details:nth-last-child(n+2) {
+    border-right: 1px white solid;
+  }
+
+  .script-details.id {
+    min-width: 2em;
+    text-align: right;
   }
 </style>
 <script src="./splaytree.js" type="text/javascript"></script>
@@ -115,7 +119,6 @@ function $(query) {
   return document.querySelector(query);
 }
 
-
 function loadFile() {
   let files = $('#uploadInput').files;
 
@@ -202,11 +205,10 @@ function renderParseResults(parseProcessor) {
       appendGraph(target.script, target, start, end);
       observer.unobserve(entry.target);
     });
-  }, {});
+  }, {rootMargin: '400px'});
   document.querySelectorAll('.script').forEach(div => io.observe(div));
 }
 
-
 const kTimeFactor = 10;
 const kHeight = 20;
 const kFunktionTopOffset = 50;
@@ -219,11 +221,11 @@ function renderScript(result, script, start, end) {
   scriptDiv.script = script;
 
   let scriptTitle = h3();
-  if (script.file) scriptTitle.appendChild(a(script.file, script.file));
-  let anchor = a("", ' id=' + script.id);
+  let anchor = a("", 'Script #' + script.id);
   anchor.name = "script"+script.id
   scriptTitle.appendChild(anchor);
   scriptDiv.appendChild(scriptTitle);
+  if (script.file) scriptTitle.appendChild(a(script.file, script.file));
   let summary = createNode('pre', 'script-details');
   summary.appendChild(text(script.summary));
   scriptDiv.appendChild(summary);
@@ -235,23 +237,28 @@ function renderScriptSizes(parseProcessor) {
   parseProcessor.scripts.forEach(
     script => {
       let scriptDiv = a('#script'+script.id, '', 'script-size');
-      let scriptId = div('script-id');
+      let scriptId = div('script-details');
+      scriptId.classList.add('id');
       scriptId.innerText = script.id;
       scriptDiv.appendChild(scriptId);
-      let scriptUrl = div('script-url');
+      let scriptSize = div('script-details');
+      scriptSize.innerText = BYTES(script.bytesTotal);
+      scriptDiv.appendChild(scriptSize);
+      let scriptUrl = div('script-details');
       if (script.isEval) {
         scriptUrl.innerText = "eval";
         scriptDiv.classList.add('eval');
       } else {
         scriptUrl.innerText = script.file.split("/").pop();
       }
-      if (script.isBackgroundCompiled ) {
-        scriptDiv.classList.add('background');
+      if (script.isStreamingCompiled ) {
+        scriptDiv.classList.add('streaming');
+      } else if (script.deserializationTimestamp > 0) {
+        scriptDiv.classList.add('deserialized');
       }
       scriptDiv.appendChild(scriptUrl);
       scriptDiv.style.width = script.bytesTotal * 0.001;
       scriptsDiv.appendChild(scriptDiv);
-  
     });
 }
 
@@ -259,16 +266,24 @@ const kMaxTime = 120 * kSecondsToMillis;
 // Resolution of the graphs
 const kTimeIncrement = 1;
 const kSelectionTimespan = 2;
+// TODO(cbruni): support compilation cache hit.
 const series = [
-    ['firstParseEvent', 'Any Parse Event'],
-    ['execution', 'First Execution'],
+    ['firstParseEvent', 'Any Parse', 'area'],
+    ['execution', '1st Exec', 'area'],
+    ['firstCompileEvent', 'Any Compile', 'area'],
+    ['compile', 'Eager Compile'],
+    ['lazyCompile', 'Lazy Compile'],
     ['parse', 'Parsing'],
-    ['preparse', 'Preparsing'],
-    ['resolution', 'Preparsing with Var. Resolution'],
-    ['lazyCompile', 'Lazy Compilation'],
-    ['compile', 'Eager Compilation'],
+    ['preparse', 'Preparse'],
+    ['resolution', 'Preparse with Var. Resolution'],
+    ['deserialization', 'Deserialization'],
+    ['optimization', 'Optimize'],
 ];
 const metricNames = series.map(each => each[0]);
+// Display cumulative values (useuful for bytes).
+const kCumulative = true;
+// Include durations in the graphs.
+const kUseDuration = false;
 
 
 function appendGraph(script, parentNode, start, end) {
@@ -279,28 +294,32 @@ function appendGraph(script, parentNode, start, end) {
   let data = new google.visualization.DataTable();
   data.addColumn('number', 'Duration');
   // The series are interleave bytes processed, time spent and thus have two
-  // different vAxes. 
+  // different vAxes.
   let seriesOptions = [];
-  let colors = ['#4D4D4D', '#5DA5DA', '#FAA43A', '#60BD68', '#F17CB0',
-      '#B2912F', '#B276B2', '#DECF3F', '#F15854'];
-  series.forEach(each => {
-    let description = each[1];
+  let colors = ['#4D4D4D', '#fff700', '#5DA5DA', '#FAA43A', '#60BD68',
+      '#F17CB0', '#B2912F', '#B276B2', '#DECF3F', '#F15854'];
+  series.forEach(([metric, description, type]) => {
     let color = colors.shift();
     // Add the bytes column.
-    data.addColumn('number', description + ' Bytes');
-    seriesOptions.push({targetAxisIndex: 0, color: color});
+    data.addColumn('number', description);
+    let options = {targetAxisIndex: 0, color: color};
+    if (type == 'area') options.type = 'area';
+    seriesOptions.push(options)
     // Add the time column.
-    data.addColumn('number', description + ' Duration');
-    seriesOptions.push({targetAxisIndex: 1, color: color, lineDashStyle: [3, 2]});
+    if (kUseDuration) {
+      data.addColumn('number', description + ' Duration');
+      seriesOptions.push(
+          {targetAxisIndex: 1, color: color, lineDashStyle: [3, 2]});
+    }
   });
-  // The first entry contains the total.
-  seriesOptions[0].type = 'area';
 
   const maxTime = Math.min(kMaxTime, end);
   console.time('metrics');
   let metricValues =
-    script.getAccumulatedTimeMetrics(metricNames , 0, maxTime, kTimeIncrement);
+    script.getAccumulatedTimeMetrics(metricNames , 0, maxTime, kTimeIncrement,
+        kCumulative, kUseDuration);
   console.timeEnd('metrics');
+  // Make sure that the series added to the graph matches the returned values.
   console.assert(metricValues[0].length == seriesOptions.length + 1);
   data.addRows(metricValues);
 
@@ -318,7 +337,7 @@ function appendGraph(script, parentNode, start, end) {
     },
     height: 400,
     width: 1000,
-    chartArea: {left: '5%', top: '15%', width: "85%", height: "75%"},
+    chartArea: {left: 70, top: 0, right: 160, height: "90%"},
     // The first series should be a area chart (total bytes touched),
     series: seriesOptions,
     // everthing else is a line.
@@ -332,28 +351,29 @@ function appendGraph(script, parentNode, start, end) {
   google.visualization.events.addListener(chart, 'select',
       () => selectGraphPointHandler(chart, data, script, parentNode));
   chart.draw(data, options);
-  // Add event listeners 
+  // Add event listeners
   console.timeEnd(timerLabel);
 }
 
-
 function selectGraphPointHandler(chart, data, script, parentNode) {
   let selection = chart.getSelection();
   if (selection.length <= 0) return;
   // Display a list of funktions with events at the given time.
   let {row, column} = selection[0];
   if (row === null|| column === null) return;
-  let name = series[((column-1)/2) | 0][0];
+  const kEntrySize = kUseDuration ? 2 : 1;
+  let [metric, description] = series[((column-1)/ kEntrySize) | 0];
   let time = data.getValue(row, 0);
   let funktions = script.getFunktionsAtTime(
-        time * kSecondsToMillis, kSelectionTimespan, name);
+        time * kSecondsToMillis, kSelectionTimespan, metric);
   let oldList = parentNode.querySelector('.funktion-list');
-  parentNode.replaceChild(createFunktionList(name, time, funktions), oldList);
+  parentNode.replaceChild(
+      createFunktionList(metric, description, time, funktions), oldList);
 }
 
-function createFunktionList(metric, time, funktions) {
+function createFunktionList(metric, description, time, funktions) {
   let container = createNode('div', 'funktion-list');
-  container.appendChild(h3('Changes of ' + metric + ' at ' +
+  container.appendChild(h3('Changes of "' + description + '" at ' +
         time + 's: ' + funktions.length));
   let listNode = createNode('ul');
   funktions.forEach(funktion => {