[tools][system-analyzer] Support profiling ticks

This adds a first crude version of displaying a flamechart in the
system-analyzer.

- Basic function types are distinguishable by colors.
- Tooltip information is available as well

Bug: v8:11835
Change-Id: I87e092f749d4c16aa5017af39df8d2f7bd7e2edd
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2928179
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Reviewed-by: Patrick Thier <pthier@chromium.org>
Cr-Commit-Position: refs/heads/master@{#74860}

tools/codemap.mjs

@@ -184,7 +184,7 @@ export class CodeMap {
         result = this.findInTree_(this.libraries_, addr);
         if (!result) return null;
       }
-      return { entry : result.value, offset : addr - result.key };
+      return {entry: result.value, offset: addr - result.key};
     }
     const min = this.dynamics_.findMin();
     const max = this.dynamics_.findMax();
@@ -197,7 +197,7 @@ export class CodeMap {
         entry.name = this.dynamicsNameGen_.getName(entry.name);
         entry.nameUpdated_ = true;
       }
-      return { entry, offset : addr - dynaEntry.key };
+      return {entry, offset: addr - dynaEntry.key};
     }
     return null;
   }

tools/logreader.mjs

@@ -160,7 +160,7 @@ export class LogReader {
       } else if (firstChar != 'o') {
         fullStack.push(parseInt(frame, 16));
       } else {
-        this.printError(`dropping: ${frame}`);
+        console.error(`dropping: ${frame}`);
       }
     }
     return fullStack;

tools/profile.mjs

@@ -158,6 +158,14 @@ class SourceInfo {
   }
 }
 
+class Tick {
+  constructor(time_ns, vmState, processedStack) {
+    this.time = time_ns;
+    this.state = vmState;
+    this.stack = processedStack;
+  }
+}
+
 /**
  * Creates a profile object for processing profiling-related events
  * and calculating function execution times.
@@ -216,6 +224,23 @@ export class Profile {
     TURBOFAN: 5,
   }
 
+  static VMState = {
+    JS: 0,
+    GC: 1,
+    PARSER: 2,
+    BYTECODE_COMPILER: 3,
+    // TODO(cbruni): add BASELINE_COMPILER
+    COMPILER: 4,
+    OTHER: 5,
+    EXTERNAL: 6,
+    IDLE: 7,
+  }
+
+  static CodeType = {
+    CPP: 0,
+    SHARED_LIB: 1
+  }
+
   /**
    * Parser for dynamic code optimization state.
    */
@@ -461,10 +486,11 @@ export class Profile {
    * @param {Array<number>} stack Stack sample.
    */
   recordTick(time_ns, vmState, stack) {
-    const processedStack = this.resolveAndFilterFuncs_(stack);
-    this.bottomUpTree_.addPath(processedStack);
-    processedStack.reverse();
-    this.topDownTree_.addPath(processedStack);
+    const {nameStack, entryStack} = this.resolveAndFilterFuncs_(stack);
+    this.bottomUpTree_.addPath(nameStack);
+    nameStack.reverse();
+    this.topDownTree_.addPath(nameStack);
+    this.ticks_.push(new Tick(time_ns, vmState, entryStack));
   }
 
   /**
@@ -474,12 +500,15 @@ export class Profile {
    * @param {Array<number>} stack Stack sample.
    */
   resolveAndFilterFuncs_(stack) {
-    const result = [];
+    const nameStack = [];
+    const entryStack = [];
     let last_seen_c_function = '';
     let look_for_first_c_function = false;
     for (let i = 0; i < stack.length; ++i) {
-      const entry = this.codeMap_.findEntry(stack[i]);
+      const pc = stack[i];
+      const entry = this.codeMap_.findEntry(pc);
       if (entry) {
+        entryStack.push(entry);
         const name = entry.getName();
         if (i === 0 && (entry.type === 'CPP' || entry.type === 'SHARED_LIB')) {
           look_for_first_c_function = true;
@@ -488,16 +517,15 @@ export class Profile {
           last_seen_c_function = name;
         }
         if (!this.skipThisFunction(name)) {
-          result.push(name);
+          nameStack.push(name);
         }
       } else {
-        this.handleUnknownCode(Profile.Operation.TICK, stack[i], i);
-        if (i === 0) result.push("UNKNOWN");
+        this.handleUnknownCode(Profile.Operation.TICK, pc, i);
+        if (i === 0) nameStack.push("UNKNOWN");
+        entryStack.push(pc);
       }
-      if (look_for_first_c_function &&
-        i > 0 &&
-        (!entry || entry.type !== 'CPP') &&
-        last_seen_c_function !== '') {
+      if (look_for_first_c_function && i > 0 &&
+          (!entry || entry.type !== 'CPP') && last_seen_c_function !== '') {
         if (this.c_entries_[last_seen_c_function] === undefined) {
           this.c_entries_[last_seen_c_function] = 0;
         }
@@ -505,7 +533,7 @@ export class Profile {
         look_for_first_c_function = false;  // Found it, we're done.
       }
     }
-    return result;
+    return {nameStack, entryStack};
   }
 
   /**

tools/system-analyzer/index.html

@@ -55,6 +55,7 @@ found in the LICENSE file. -->
 
   <section id="container" class="initial">
     <timeline-panel id="timeline-panel">
+      <timeline-track id="sample-track" title="Samples"></timeline-track>
       <timeline-track id="map-track" title="Map"></timeline-track>
       <timeline-track id="ic-track" title="IC"></timeline-track>
       <timeline-track id="deopt-track" title="Deopt"></timeline-track>

tools/system-analyzer/index.mjs

@@ -12,6 +12,7 @@ import {IcLogEntry} from './log/ic.mjs';
 import {LogEntry} from './log/log.mjs';
 import {MapLogEntry} from './log/map.mjs';
 import {Processor} from './processor.mjs';
+import {Timeline} from './timeline.mjs'
 import {FocusEvent, SelectionEvent, SelectRelatedEvent, SelectTimeEvent, ToolTipEvent,} from './view/events.mjs';
 import {$, CSSColor, groupBy} from './view/helper.mjs';
 
@@ -26,6 +27,7 @@ class App {
       logFileReader: $('#log-file-reader'),
 
       timelinePanel: $('#timeline-panel'),
+      sampleTrack: $('#sample-track'),
       mapTrack: $('#map-track'),
       icTrack: $('#ic-track'),
       deoptTrack: $('#deopt-track'),
@@ -334,6 +336,12 @@ class App {
   }
 
   refreshTimelineTrackView() {
+    const ticks = this._state.profile.ticks_;
+    if (ticks.length > 0) {
+      this._view.sampleTrack.data = new Timeline(
+          Object, ticks, ticks[0].time, ticks[ticks.length - 1].time);
+      this._view.sampleTrack.ticks = ticks;
+    }
     this._view.mapTrack.data = this._state.mapTimeline;
     this._view.icTrack.data = this._state.icTimeline;
     this._view.deoptTrack.data = this._state.deoptTimeline;

tools/system-analyzer/log/code.mjs

@@ -50,6 +50,7 @@ export class CodeLogEntry extends LogEntry {
     this._kind = kind;
     this._kindName = kindName;
     this._entry = entry;
+    entry.logEntry = this;
   }
 
   get kind() {
@@ -92,7 +93,7 @@ export class CodeLogEntry extends LogEntry {
 
   static get propertyNames() {
     return [
-      'type', 'kind', 'kindName', 'size', 'functionName', 'sourcePosition',
+      'functionName', 'sourcePosition', 'kindName', 'size', 'type', 'kind',
       'script', 'source', 'code'
     ];
   }

tools/system-analyzer/processor.mjs

@@ -78,6 +78,16 @@ export class Processor extends LogReader {
       },
       'sfi-move':
           {parsers: [parseInt, parseInt], processor: this.processFunctionMove},
+      'tick': {
+        parsers:
+            [parseInt, parseInt, parseInt, parseInt, parseInt, parseVarArgs],
+        processor: this.processTick
+      },
+      'active-runtime-timer': undefined,
+      'heap-sample-begin': undefined,
+      'heap-sample-end': undefined,
+      'timer-event-start': undefined,
+      'timer-event-end': undefined,
       'map-create':
           {parsers: [parseInt, parseString], processor: this.processMapCreate},
       'map': {
@@ -264,6 +274,29 @@ export class Processor extends LogReader {
     this._profile.moveFunc(from, to);
   }
 
+  processTick(
+      pc, ns_since_start, is_external_callback, tos_or_external_callback,
+      vmState, stack) {
+    if (is_external_callback) {
+      // Don't use PC when in external callback code, as it can point
+      // inside callback's code, and we will erroneously report
+      // that a callback calls itself. Instead we use tos_or_external_callback,
+      // as simply resetting PC will produce unaccounted ticks.
+      pc = tos_or_external_callback;
+      tos_or_external_callback = 0;
+    } else if (tos_or_external_callback) {
+      // Find out, if top of stack was pointing inside a JS function
+      // meaning that we have encountered a frameless invocation.
+      const funcEntry = this._profile.findEntry(tos_or_external_callback);
+      if (!funcEntry?.isJSFunction?.()) {
+        tos_or_external_callback = 0;
+      }
+    }
+    this._profile.recordTick(
+        ns_since_start, vmState,
+        this.processStack(pc, tos_or_external_callback, stack));
+  }
+
   processCodeSourceInfo(
       start, scriptId, startPos, endPos, sourcePositions, inliningPositions,
       inlinedFunctions) {

tools/system-analyzer/view/timeline/timeline-track-template.html

@@ -25,7 +25,7 @@ found in the LICENSE file. -->
     opacity: 0.5;
   }
 
-  #timelineChunks {
+  #timelineSamples, #timelineChunks {
     height: 200px;
     position: absolute;
     margin-right: 100px;
@@ -152,7 +152,6 @@ found in the LICENSE file. -->
     position: absolute;
   }
 
-
   .content {
     display: flex;
     position: relative;
@@ -172,6 +171,22 @@ found in the LICENSE file. -->
     flex: initial;
   }
 
+  .flame {
+    background-color: gray;
+    overflow: hidden;
+    height: 10px;
+    position: absolute;
+    font-size: 8px;
+  }
+  .flame.Opt{
+    background-color: red;
+  }
+  .flame.Baseline{
+    background-color: blue;
+  }
+  .flame.default {
+    background-color: black;
+  }
 </style>
 
 <div class="content">
@@ -187,6 +202,7 @@ found in the LICENSE file. -->
     </div>
     <div id="timelineLabel">Frequency</div>
     <div id="timelineChunks"></div>
+    <div id="timelineSamples"></div>
     <canvas id="timelineCanvas"></canvas>
   </div>
 

tools/system-analyzer/view/timeline/timeline-track.mjs

@@ -2,11 +2,25 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+import {Profile} from '../../../profile.mjs'
+import {delay} from '../../helper.mjs';
 import {kChunkHeight, kChunkWidth} from '../../log/map.mjs';
 import {MapLogEntry} from '../../log/map.mjs';
 import {FocusEvent, SelectionEvent, SelectTimeEvent, SynchronizeSelectionEvent, ToolTipEvent,} from '../events.mjs';
 import {CSSColor, DOM, gradientStopsFromGroups, V8CustomElement} from '../helper.mjs';
 
+class Flame {
+  constructor(time, entry) {
+    this.start = time;
+    this.end = this.start;
+    this.entry = entry;
+  }
+  stop(time) {
+    this.end = time;
+    this.duration = time - this.start
+  }
+}
+
 DOM.defineCustomElement('view/timeline/timeline-track',
                         (templateText) =>
                             class TimelineTrack extends V8CustomElement {
@@ -21,6 +35,7 @@ DOM.defineCustomElement('view/timeline/timeline-track',
   _chunkMouseMoveHandler = this._handleChunkMouseMove.bind(this);
   _chunkClickHandler = this._handleChunkClick.bind(this);
   _chunkDoubleClickHandler = this._handleChunkDoubleClick.bind(this);
+  _flameMouseOverHandler = this._handleFlameMouseOver.bind(this);
 
   constructor() {
     super(templateText);
@@ -91,6 +106,10 @@ DOM.defineCustomElement('view/timeline/timeline-track',
     return this.$('#timelineChunks');
   }
 
+  get timelineSamples() {
+    return this.$('#timelineSamples');
+  }
+
   get timelineNode() {
     return this.$('#timeline');
   }
@@ -98,6 +117,63 @@ DOM.defineCustomElement('view/timeline/timeline-track',
   _update() {
     this._updateTimeline();
     this._legend.update();
+    // TODO(cbruni: Create separate component for profile ticks
+    if (this.ticks) {
+      this.drawFlamechart()
+    }
+  }
+
+  async drawFlamechart() {
+    await delay(100);
+    // TODO(cbruni): Use dynamic drawing strategy here that scales
+    DOM.removeAllChildren(this.timelineSamples);
+    const stack = [];
+    const kMaxNumOfDisplayedFlames = 2000
+    const kIncrement = Math.max(1, this.ticks.length / 5000) | 0;
+    for (let i = 0; i < this.ticks.length; i += kIncrement) {
+      if (i % 500 == 0) {
+        await delay(10);
+      }
+      const tick = this.ticks[i];
+      for (let j = 0; j < tick.stack.length; j++) {
+        const entry = tick.stack[j];
+        if (typeof entry !== 'object') continue;
+        if (stack.length <= j) {
+          stack.push(new Flame(tick.time, entry));
+        } else {
+          const flame = stack[j];
+          if (flame.entry !== entry) {
+            for (let k = j; k < stack.length; k++) {
+              stack[k].stop(tick.time);
+              this.drawFlame(stack[k], k);
+            }
+            stack.length = j;
+            stack[j] = new Flame(tick.time, entry);
+          }
+        }
+      }
+    }
+  }
+
+  drawFlame(flame, depth) {
+    let type = 'default';
+    if (flame.entry.state) {
+      type = Profile.getKindFromState(flame.entry.state);
+    }
+    const node = DOM.div(['flame', type]);
+    node.data = flame.entry;
+    node.onmouseover = this._flameMouseOverHandler
+    const style = node.style;
+    style.top = `${depth * 10}px`;
+    style.left = `${flame.start * this._timeToPixel}px`;
+    style.width = `${flame.duration * this._timeToPixel}px`;
+    node.innerText = flame.entry.getRawName();
+    this.timelineSamples.appendChild(node);
+  }
+
+  _handleFlameMouseOver(event) {
+    const codeEntry = event.target.data;
+    this.dispatchEvent(new ToolTipEvent(codeEntry.logEntry, event.target));
   }
 
   set nofChunks(count) {
@@ -163,6 +239,8 @@ DOM.defineCustomElement('view/timeline/timeline-track',
     let duration = end - start;
     this._timeToPixel = chunks.length * kChunkWidth / duration;
     this._timeStartOffset = start * this._timeToPixel;
+    // TODO(cbruni: Create separate component for profile ticks
+    if (this.ticks) return;
     for (let i = 0; i < chunks.length; i++) {
       let chunk = chunks[i];
       let height = (chunk.size() / max * kChunkHeight);

tools/system-analyzer/view/tool-tip-template.html

@@ -36,6 +36,7 @@ found in the LICENSE file. -->
   #body {
     display: none;
     position: absolute;
+    z-index: 99999;
     --tip-offset: 10px;
     --tip-width: 10px;
     --tip-height: 15px;
@@ -84,6 +85,9 @@ found in the LICENSE file. -->
   .properties > tbody > tr > td:nth-child(2n+1):after {
     content: ':';
   }
+  .properties {
+    min-width: 350px;
+  }
 </style>
 
 <div id="body">

tools/system-analyzer/view/tool-tip.mjs

@@ -34,9 +34,7 @@ DOM.defineCustomElement(
         rect.x += rect.width / 2;
         let atRight = this._useRight(rect.x);
         let atBottom = this._useBottom(rect.y);
-        if (atBottom) {
-          rect.y += rect.height;
-        }
+        if (atBottom) rect.y += rect.height;
         this._setPosition(rect, atRight, atBottom);
         this.requestUpdate(true);
       }
@@ -174,6 +172,7 @@ class TableBuilder {
   _addFooter() {
     if (this._instance === undefined) return;
     const td = this._table.createTFoot().insertRow().insertCell();
+    td.colSpan = 2;
     let button =
         td.appendChild(DOM.button('Show', this._tooltip._logEntryClickHandler));
     button.data = this._instance;