[tools] parse-processor improvements

- display script size overview
- color scripts in overview depending on eval, streaming or other scripts
- fix stats to always take own-bytes into accout
- rename all *Time properties to *Duration for consistency
- extract ScriptSource log event into separate method
- support script source events in parse-processor

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

src/log.cc

@@ -1301,40 +1301,20 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                              Name* source, int line, int column) {
   if (!is_listening_to_code_events()) return;
   if (!FLAG_log_code || !log_->IsEnabled()) return;
-
-  Log::MessageBuilder msg(log_);
-  AppendCodeCreateHeader(msg, tag, code, &timer_);
-  msg << shared->DebugName() << " " << source << ":" << line << ":" << column
-      << kNext << reinterpret_cast<void*>(shared->address()) << kNext
-      << ComputeMarker(shared, code);
-  msg.WriteToLogFile();
+  {
+    Log::MessageBuilder msg(log_);
+    AppendCodeCreateHeader(msg, tag, code, &timer_);
+    msg << shared->DebugName() << " " << source << ":" << line << ":" << column
+        << kNext << reinterpret_cast<void*>(shared->address()) << kNext
+        << ComputeMarker(shared, code);
+    msg.WriteToLogFile();
+  }
 
   if (!FLAG_log_source_code) return;
   Object* script_object = shared->script();
   if (!script_object->IsScript()) return;
-  // Make sure the script is written to the log file.
   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()) {
-      String* source_code = String::cast(source_object);
-      msg << "script" << kNext << script_id << kNext;
-
-      // Log the script name.
-      if (script->name()->IsString()) {
-        msg << String::cast(script->name()) << kNext;
-      } else {
-        msg << "<unknown>" << kNext;
-      }
-
-      // Log the source code.
-      msg << source_code;
-      msg.WriteToLogFile();
-    }
-  }
+  if (!EnsureLogScriptSource(script)) return;
 
   // We log source code information in the form:
   //
@@ -1357,10 +1337,11 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
   //         <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>
+  Log::MessageBuilder msg(log_);
   msg << "code-source-info" << kNext
-      << reinterpret_cast<void*>(code->InstructionStart()) << kNext << script_id
-      << kNext << shared->StartPosition() << kNext << shared->EndPosition()
-      << kNext;
+      << reinterpret_cast<void*>(code->InstructionStart()) << kNext
+      << script->id() << kNext << shared->StartPosition() << kNext
+      << shared->EndPosition() << kNext;
 
   SourcePositionTableIterator iterator(code->source_position_table());
   bool is_first = true;
@@ -1624,6 +1605,34 @@ void Logger::ScriptDetails(Script* script) {
   msg.WriteToLogFile();
 }
 
+bool Logger::EnsureLogScriptSource(Script* script) {
+  if (!log_->IsEnabled()) return false;
+  Log::MessageBuilder msg(log_);
+  // Make sure the script is written to the log file.
+  int script_id = script->id();
+  if (logged_source_code_.find(script_id) != logged_source_code_.end()) {
+    return false;
+  }
+  // This script has not been logged yet.
+  logged_source_code_.insert(script_id);
+  Object* source_object = script->source();
+  if (!source_object->IsString()) return false;
+  String* source_code = String::cast(source_object);
+  msg << "script-source" << kNext << script_id << kNext;
+
+  // Log the script name.
+  if (script->name()->IsString()) {
+    msg << String::cast(script->name()) << kNext;
+  } else {
+    msg << "<unknown>" << kNext;
+  }
+
+  // Log the source code.
+  msg << source_code;
+  msg.WriteToLogFile();
+  return true;
+}
+
 void Logger::RuntimeCallTimerEvent() {
   RuntimeCallStats* stats = isolate_->counters()->runtime_call_stats();
   RuntimeCallCounter* counter = stats->current_counter();

src/log.h

@@ -327,6 +327,10 @@ class Logger : public CodeEventListener {
   // Logs an IntPtrTEvent regardless of whether FLAG_log is true.
   void UncheckedIntPtrTEvent(const char* name, intptr_t value);
 
+  // Logs a scripts sources. Keeps track of all logged scripts to ensure that
+  // each script is logged only once.
+  bool EnsureLogScriptSource(Script* script);
+
   Isolate* isolate_;
 
   // The sampler used by the profiler and the sliding state window.

tools/parse-processor.html

@@ -62,10 +62,39 @@ code is governed by a BSD-style license that can be found in the LICENSE file.
     overflow-y: scroll;
   }
 
-
   .funktion {
   }
 
+  .script-size {
+    display: inline-block;
+    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 {
+    background-color: #008aff;
+  }
+
+  .script-id {
+    display: inline;
+    padding-right: 2px;
+    margin-right: 2px;
+    border-right: 1px grey dotted;
+  }
+  .script-url {
+    display: inline;
+    text-overflow: ellipis;
+  }
 </style>
 <script src="./splaytree.js" type="text/javascript"></script>
 <script src="./codemap.js" type="text/javascript"></script>
@@ -156,12 +185,13 @@ function renderParseResults(parseProcessor) {
   let result = $('#result');
   // clear out all existing result pages;
   result.innerHTML = '';
-  const start = parseProcessor.firstEvent;
-  const end = parseProcessor.lastEvent;
+  const start = parseProcessor.firstEventTimestamp;
+  const end = parseProcessor.lastEventTimestamp;
   renderScript(result, parseProcessor.totalScript, start, end);
   // Build up the graphs lazily to keep the page responsive.
   parseProcessor.scripts.forEach(
       script => renderScript(result, script, start, end));
+  renderScriptSizes(parseProcessor);
   // Install an intersection observer to lazily load the graphs when the script
   // div becomes visible for the first time.
   var io = new IntersectionObserver((entries, observer) => {
@@ -198,7 +228,31 @@ function renderScript(result, script, start, end) {
   summary.appendChild(text(script.summary));
   scriptDiv.appendChild(summary);
   result.appendChild(scriptDiv);
-  return scriptDiv;
+}
+
+function renderScriptSizes(parseProcessor) {
+  let scriptsDiv = $('#scripts');
+  parseProcessor.scripts.forEach(
+    script => {
+      let scriptDiv = a('#script'+script.id, '', 'script-size');
+      let scriptId = div('script-id');
+      scriptId.innerText = script.id;
+      scriptDiv.appendChild(scriptId);
+      let scriptUrl = div('script-url');
+      if (script.isEval) {
+        scriptUrl.innerText = "eval";
+        scriptDiv.classList.add('eval');
+      } else {
+        scriptUrl.innerText = script.file.split("/").pop();
+      }
+      if (script.isBackgroundCompiled ) {
+        scriptDiv.classList.add('background');
+      }
+      scriptDiv.appendChild(scriptUrl);
+      scriptDiv.style.width = script.bytesTotal * 0.001;
+      scriptsDiv.appendChild(scriptDiv);
+  
+    });
 }
 
 const kMaxTime = 120 * kSecondsToMillis;
@@ -206,13 +260,13 @@ const kMaxTime = 120 * kSecondsToMillis;
 const kTimeIncrement = 1;
 const kSelectionTimespan = 2;
 const series = [
-//    ['firstParseEvent', 'Any Parse Event'],
+    ['firstParseEvent', 'Any Parse Event'],
+    ['execution', 'First Execution'],
     ['parse', 'Parsing'],
-//    ['preparse', 'Preparsing'],
-//    ['resolution', 'Preparsing with Var. Resolution'],
+    ['preparse', 'Preparsing'],
+    ['resolution', 'Preparsing with Var. Resolution'],
     ['lazyCompile', 'Lazy Compilation'],
     ['compile', 'Eager Compilation'],
-    ['execution', 'First Execution'],
 ];
 const metricNames = series.map(each => each[0]);
 
@@ -223,18 +277,21 @@ function appendGraph(script, parentNode, start, end) {
 
   console.time(timerLabel);
   let data = new google.visualization.DataTable();
-  data.addColumn('number', 'Time');
+  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 color = colors.shift();
     // Add the bytes column.
     data.addColumn('number', description + ' Bytes');
-    seriesOptions.push({targetAxisIndex: 0});
+    seriesOptions.push({targetAxisIndex: 0, color: color});
     // Add the time column.
-    data.addColumn('number', description + ' Time');
-    seriesOptions.push({targetAxisIndex: 1, lineDashStyle: [3, 2]});
+    data.addColumn('number', description + ' Duration');
+    seriesOptions.push({targetAxisIndex: 1, color: color, lineDashStyle: [3, 2]});
   });
   // The first entry contains the total.
   seriesOptions[0].type = 'area';
@@ -257,7 +314,7 @@ function appendGraph(script, parentNode, start, end) {
     },
     vAxes: {
       0: {title: 'Bytes Touched', format: 'short'},
-      1: {title: 'Time', format: '#,###ms'}
+      1: {title: 'Duration', format: '#,###ms'}
     },
     height: 400,
     width: 1000,
@@ -275,6 +332,7 @@ function appendGraph(script, parentNode, start, end) {
   google.visualization.events.addListener(chart, 'select',
       () => selectGraphPointHandler(chart, data, script, parentNode));
   chart.draw(data, options);
+  // Add event listeners 
   console.timeEnd(timerLabel);
 }
 
@@ -311,8 +369,6 @@ function createFunktionList(metric, time, funktions) {
   container.appendChild(listNode);
   return container;
 }
-
-
 </script>
 </head>
 
@@ -330,6 +386,10 @@ function createFunktionList(metric, time, funktions) {
     </p>
   </form>
 
+
+  <h2>Scripts</h2>
+  <div id="scripts"></div>
+
   <h2>Result</h2>
   <div id="result"></div>
 </body>

tools/tickprocessor.js

@@ -120,9 +120,9 @@ function TickProcessor(
           parsers: [parseInt, parseInt, parseInt, parseInt, parseString,
                     parseString, parseString],
           processor: this.processCodeSourceInfo },
-      'script': {
+      'script-source': {
           parsers: [parseInt, parseString, parseString],
-          processor: this.processCodeScript },
+          processor: this.processScriptSource },
       'sfi-move': { parsers: [parseInt, parseInt],
           processor: this.processFunctionMove },
       'active-runtime-timer': {
@@ -333,7 +333,7 @@ TickProcessor.prototype.processCodeSourceInfo = function(
     endPos, sourcePositions, inliningPositions, inlinedFunctions);
 };
 
-TickProcessor.prototype.processCodeScript = function(script, url, source) {
+TickProcessor.prototype.processScriptSource = function(script, url, source) {
   this.profile_.addScriptSource(script, url, source);
 };