[tools][system-analyzer] Support time logging for IC Events

This CL modifies the logging pipeline of V8 to track
timestamps of the IC events across the log file.

Modifies the current IC-explorer's code to make it
compatible with the IC event time processing.

Change-Id: I2a0f652e2657bdebe8cecd7862a7545f7b050cdb
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2274613
Commit-Queue: Zeynep Cankara <zcankara@google.com>
Reviewed-by: Camillo Bruni <cbruni@chromium.org>
Reviewed-by: Sathya Gunasekaran  <gsathya@chromium.org>
Cr-Commit-Position: refs/heads/master@{#68849}

src/logging/log.cc

@@ -1659,8 +1659,9 @@ void Logger::ICEvent(const char* type, bool keyed, Handle<Map> map,
   int line;
   int column;
   Address pc = isolate_->GetAbstractPC(&line, &column);
-  msg << type << kNext << reinterpret_cast<void*>(pc) << kNext << line << kNext
-      << column << kNext << old_state << kNext << new_state << kNext
+  msg << type << kNext << reinterpret_cast<void*>(pc) << kNext
+      << timer_.Elapsed().InMicroseconds() << kNext << line << kNext << column
+      << kNext << old_state << kNext << new_state << kNext
       << AsHex::Address(map.is_null() ? kNullAddress : map->ptr()) << kNext;
   if (key->IsSmi()) {
     msg << Smi::ToInt(*key);

tools/ic-explorer.html

@@ -71,78 +71,80 @@ code is governed by a BSD-style license that can be found in the LICENSE file.
     // For compatibility with console scripts:
     print = console.log;
 
-    class CustomIcProcessor extends IcProcessor {
-      constructor() {
-        super();
-        this.entries = [];
-      }
-
-      functionName(pc) {
-        let entry = this.profile_.findEntry(pc);
-        return this.formatName(entry);
-      }
-
-      processPropertyIC(type, pc, line, column, old_state, new_state, map, key,
-          modifier, slow_reason) {
-        let fnName = this.functionName(pc);
-        this.entries.push(new Entry(type, fnName, line, column, key,
-          old_state, new_state, map, slow_reason));
-
-      }
-    };
-
-
-    class Entry {
-      constructor(type, fn_file, line, column, key, oldState, newState,
-          map, reason, additional) {
-        this.type = type;
-        this.category = "other";
-        if (this.type.indexOf("Store") !== -1) {
-          this.category = "Store";
-        } else if (this.type.indexOf("Load") !== -1) {
-          this.category = "Load";
-        }
-        let parts = fn_file.split(" ");
-        this.functionName = parts[0];
-        this.file = parts[1];
-        let position = line + ":" + column;
-        this.filePosition = this.file + ":" + position;
-        this.oldState = oldState;
-        this.newState = newState;
-        this.state = this.oldState + " → " + this.newState;
-        this.key = key;
-        this.map = map.toString(16);
-        this.reason = reason;
-        this.additional = additional;
-      }
+  class CustomIcProcessor extends IcProcessor {
+    constructor() {
+      super();
+      this.entries = [];
+    }
 
-      parseMapProperties(parts, offset) {
-        let next = parts[++offset];
-        if (!next.startsWith('dict')) return offset;
-        this.propertiesMode =
-          next.substr(5) == "0" ? "fast" : "slow";
-        this.numberOfOwnProperties = parts[++offset].substr(4);
-        next = parts[++offset];
-        this.instanceType = next.substr(5, next.length - 6);
-        return offset;
-      }
+    functionName(pc) {
+      let entry = this.profile_.findEntry(pc);
+      return this.formatName(entry);
+    }
 
-      parsePositionAndFile(parts, start) {
-        // find the position of 'at' in the parts array.
-        let offset = start;
-        for (let i = start + 1; i < parts.length; i++) {
-          offset++;
-          if (parts[i] == 'at') break;
-        }
-        if (parts[offset] !== 'at') return -1;
-        this.position = parts.slice(start, offset).join(' ');
-        offset += 1;
-        this.isNative = parts[offset] == "native"
-        offset += this.isNative ? 1 : 0;
-        this.file = parts[offset];
-        return offset;
-      }
+    processPropertyIC(
+        type, pc, time, line, column, old_state, new_state, map, key, modifier,
+        slow_reason) {
+      let fnName = this.functionName(pc);
+      this.entries.push(new Entry(
+          type, fnName, time, line, column, key, old_state, new_state, map,
+          slow_reason));
+    }
+  };
+
+
+  class Entry {
+  constructor(
+      type, fn_file, time, line, column, key, oldState, newState, map, reason,
+      additional) {
+    this.time = time;
+    this.type = type;
+    this.category = 'other';
+    if (this.type.indexOf('Store') !== -1) {
+      this.category = 'Store';
+    } else if (this.type.indexOf('Load') !== -1) {
+      this.category = 'Load';
+    }
+    let parts = fn_file.split(' ');
+    this.functionName = parts[0];
+    this.file = parts[1];
+    let position = line + ':' + column;
+    this.filePosition = this.file + ':' + position;
+    this.oldState = oldState;
+    this.newState = newState;
+    this.state = this.oldState + ' → ' + this.newState;
+    this.key = key;
+    this.map = map.toString(16);
+    this.reason = reason;
+    this.additional = additional;
+  }
+
+  parseMapProperties(parts, offset) {
+    let next = parts[++offset];
+    if (!next.startsWith('dict')) return offset;
+    this.propertiesMode = next.substr(5) == '0' ? 'fast' : 'slow';
+    this.numberOfOwnProperties = parts[++offset].substr(4);
+    next = parts[++offset];
+    this.instanceType = next.substr(5, next.length - 6);
+    return offset;
+  }
+
+  parsePositionAndFile(parts, start) {
+    // find the position of 'at' in the parts array.
+    let offset = start;
+    for (let i = start + 1; i < parts.length; i++) {
+      offset++;
+      if (parts[i] == 'at') break;
     }
+    if (parts[offset] !== 'at') return -1;
+    this.position = parts.slice(start, offset).join(' ');
+    offset += 1;
+    this.isNative = parts[offset] == 'native'
+    offset += this.isNative ? 1 : 0;
+    this.file = parts[offset];
+    return offset;
+  }
+}
 
     function loadFile() {
       let files = document.getElementById("uploadInput").files;

tools/ic-processor.js

@@ -32,8 +32,9 @@ function parseState(s) {
 
 
 function IcProcessor() {
-  var propertyICParser = [parseInt, parseInt, parseInt, parseString,
-      parseString, parseInt, parseString, parseString, parseString];
+  var propertyICParser = [
+    parseInt, parseInt, parseInt, parseInt, parseString, parseString,
+    parseInt, parseString, parseString, parseString];
   LogReader.call(this, {
       'code-creation': {
           parsers: [parseString, parseInt, parseInt, parseInt, parseInt,
@@ -161,17 +162,19 @@ IcProcessor.prototype.formatName = function(entry) {
 }
 
 IcProcessor.prototype.processPropertyIC = function (
-    type, pc, line, column, old_state, new_state, map, name, modifier,
-    slow_reason) {
-  this[type]++;
-  var entry = this.profile_.findEntry(pc);
-  print(type + " (" + old_state + "->" + new_state + modifier + ") at " +
-        this.formatName(entry) + ":" + line + ":" + column + " " + name +
-        " (map 0x" + map.toString(16) + ")" +
-        (slow_reason ? " " + slow_reason : ""));
+  type, pc, time, line, column, old_state, new_state, map, name, modifier,
+  slow_reason) {
+this[type]++;
+let entry = this.profile_.findEntry(pc);
+print(
+    type + ' (' + old_state + '->' + new_state + modifier + ') at ' +
+    this.formatName(entry) + ':' + line + ':' + column + ' ' + name +
+    ' (map 0x' + map.toString(16) + ')' +
+    (slow_reason ? ' ' + slow_reason : '') + 'time: ' + time);
 }
 
 
+
 class ArgumentsProcessor extends BaseArgumentsProcessor {
   getArgsDispatch() {
     return {

tools/system-analyzer/ic-model.mjs

@@ -38,7 +38,7 @@ export class Group {
       let entry = entries[i];
       let key = entry[property];
       if (accumulator[key] == undefined) {
-        accumulator[key] = new Group(property, key, entry)
+        accumulator[key] = new Group(property, key, entry);
       } else {
         let group = accumulator[key];
         if (group.entries == undefined) console.log([group, entry]);
@@ -54,4 +54,5 @@ export class Group {
     result.sort((a, b) => {return b.count - a.count});
     return result;
   }
+
 }

tools/system-analyzer/ic-processor.mjs

@@ -21,8 +21,8 @@ class IcProcessor extends LogReader {
   constructor() {
     super();
     let propertyICParser = [
-      parseInt, parseInt, parseInt, parseString, parseString, parseInt,
-      parseString, parseString, parseString
+      parseInt, parseInt, parseInt, parseInt, parseString, parseString,
+      parseInt, parseString, parseString, parseString
     ];
     LogReader.call(this, {
       'code-creation': {
@@ -145,9 +145,9 @@ class IcProcessor extends LogReader {
     if (!array) return name;
     return entry.getState() + array[1];
   }
-  // TODO(zc): Process the IC event togather with time
+
   processPropertyIC(
-      type, pc, line, column, old_state, new_state, map, name, modifier,
+      type, pc, time, line, column, old_state, new_state, map, name, modifier,
       slow_reason) {
     this[type]++;
     let entry = this.profile_.findEntry(pc);
@@ -155,7 +155,7 @@ class IcProcessor extends LogReader {
         type + ' (' + old_state + '->' + new_state + modifier + ') at ' +
         this.formatName(entry) + ':' + line + ':' + column + ' ' + name +
         ' (map 0x' + map.toString(16) + ')' +
-        (slow_reason ? ' ' + slow_reason : ''));
+        (slow_reason ? ' ' + slow_reason : '') + 'time: ' + time);
   }
 }
 
@@ -185,19 +185,20 @@ class CustomIcProcessor extends IcProcessor {
   }
 
   processPropertyIC(
-      type, pc, line, column, old_state, new_state, map, key, modifier,
+      type, pc, time, line, column, old_state, new_state, map, key, modifier,
       slow_reason) {
     let fnName = this.functionName(pc);
     this.entries.push(new Entry(
-        type, fnName, line, column, key, old_state, new_state, map,
+        type, fnName, time, line, column, key, old_state, new_state, map,
         slow_reason));
   }
 };
 
 class Entry {
   constructor(
-      type, fn_file, line, column, key, oldState, newState, map, reason,
+      type, fn_file, time, line, column, key, oldState, newState, map, reason,
       additional) {
+    this.time = time;
     this.type = type;
     this.category = 'other';
     if (this.type.indexOf('Store') !== -1) {