Profiler improvements

(1) --prof-cpp: Collects ticks like --prof, but ignores code creation events to reduce distortion (so all JS ticks will be "unaccounted"). Useful for profiling C++ code.
(2) --timed-range flag for tick processor: Ignores ticks before the first and after the last call to Date.now(). Useful for focusing on the timed section of a test.

Review URL: https://codereview.chromium.org/802333002

Cr-Commit-Position: refs/heads/master@{#26168}

src/flag-definitions.h

@@ -860,6 +860,8 @@ DEFINE_BOOL(log_snapshot_positions, false,
 DEFINE_BOOL(log_suspect, false, "Log suspect operations.")
 DEFINE_BOOL(prof, false,
             "Log statistical profiling information (implies --log-code).")
+DEFINE_BOOL(prof_cpp, false, "Like --prof, but ignore generated code.")
+DEFINE_IMPLICATION(prof, prof_cpp)
 DEFINE_BOOL(prof_browser_mode, true,
             "Used with --prof, turns on browser-compatible mode for profiling.")
 DEFINE_BOOL(log_regexp, false, "Log regular expression execution.")

src/isolate.cc

@@ -2115,19 +2115,6 @@ bool Isolate::Init(Deserializer* des) {
     std::ofstream(GetTurboCfgFileName().c_str(), std::ios_base::trunc);
   }
 
-  // If we are deserializing, log non-function code objects and compiled
-  // functions found in the snapshot.
-  if (!create_heap_objects &&
-      (FLAG_log_code ||
-       FLAG_ll_prof ||
-       FLAG_perf_jit_prof ||
-       FLAG_perf_basic_prof ||
-       logger_->is_logging_code_events())) {
-    HandleScope scope(this);
-    LOG(this, LogCodeObjects());
-    LOG(this, LogCompiledFunctions());
-  }
-
   CHECK_EQ(static_cast<int>(OFFSET_OF(Isolate, embedder_data_)),
            Internals::kIsolateEmbedderDataOffset);
   CHECK_EQ(static_cast<int>(OFFSET_OF(Isolate, heap_.roots_)),

src/log-utils.h

@@ -22,10 +22,10 @@ class Log {
   void stop() { is_stopped_ = true; }
 
   static bool InitLogAtStart() {
-    return FLAG_log || FLAG_log_api || FLAG_log_code || FLAG_log_gc
-        || FLAG_log_handles || FLAG_log_suspect || FLAG_log_regexp
-        || FLAG_ll_prof || FLAG_perf_basic_prof || FLAG_perf_jit_prof
-        || FLAG_log_internal_timer_events;
+    return FLAG_log || FLAG_log_api || FLAG_log_code || FLAG_log_gc ||
+           FLAG_log_handles || FLAG_log_suspect || FLAG_log_regexp ||
+           FLAG_ll_prof || FLAG_perf_basic_prof || FLAG_perf_jit_prof ||
+           FLAG_log_internal_timer_events || FLAG_prof_cpp;
   }
 
   // Frees all resources acquired in Initialize and Open... functions.

src/log.cc

@@ -903,7 +903,7 @@ void Logger::ApiNamedSecurityCheck(Object* key) {
 void Logger::SharedLibraryEvent(const std::string& library_path,
                                 uintptr_t start,
                                 uintptr_t end) {
-  if (!log_->IsEnabled() || !FLAG_prof) return;
+  if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
   Log::MessageBuilder msg(log_);
   msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR,
              library_path.c_str(), start, end);
@@ -1516,7 +1516,7 @@ void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
 
 
 void Logger::TickEvent(TickSample* sample, bool overflow) {
-  if (!log_->IsEnabled() || !FLAG_prof) return;
+  if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
   Log::MessageBuilder msg(log_);
   msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
   msg.AppendAddress(sample->pc);
@@ -1861,9 +1861,9 @@ bool Logger::SetUp(Isolate* isolate) {
     is_logging_ = true;
   }
 
-  if (FLAG_log_internal_timer_events || FLAG_prof) timer_.Start();
+  if (FLAG_log_internal_timer_events || FLAG_prof_cpp) timer_.Start();
 
-  if (FLAG_prof) {
+  if (FLAG_prof_cpp) {
     profiler_ = new Profiler(isolate);
     is_logging_ = true;
     profiler_->Engage();

src/runtime/runtime-date.cc

@@ -70,7 +70,7 @@ RUNTIME_FUNCTION(Runtime_ThrowNotDateError) {
 RUNTIME_FUNCTION(Runtime_DateCurrentTime) {
   HandleScope scope(isolate);
   DCHECK(args.length() == 0);
-  if (FLAG_log_timer_events) LOG(isolate, CurrentTimeEvent());
+  if (FLAG_log_timer_events || FLAG_prof_cpp) LOG(isolate, CurrentTimeEvent());
 
   // According to ECMA-262, section 15.9.1, page 117, the precision of
   // the number in a Date object representing a particular instant in

test/mjsunit/tools/tickprocessor-test.default

@@ -7,7 +7,6 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
 
  [JavaScript]:
    ticks  total  nonlib   name
-      1    7.7%   11.1%  LazyCompile: exp native math.js:41
 
  [C++]:
    ticks  total  nonlib   name
@@ -18,7 +17,7 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
 
  [Summary]:
    ticks  total  nonlib   name
-      1    7.7%   11.1%  JavaScript
+      0    0.0%    0.0%  JavaScript
       5   38.5%   55.6%  C++
       0    0.0%    0.0%  GC
       4   30.8%          Shared libraries
@@ -45,6 +44,10 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
       2  100.0%    LazyCompile: exp native math.js:41
       2  100.0%      Script: exp.js
 
+      2   15.4%  UNKNOWN
+      1   50.0%    LazyCompile: exp native math.js:41
+      1  100.0%      Script: exp.js
+
       1    7.7%  v8::internal::JSObject::LookupOwnRealNamedProperty(v8::internal::String*, v8::internal::LookupResult*)
       1  100.0%    Script: exp.js
 
@@ -57,6 +60,3 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
       1  100.0%    LazyCompile: exp native math.js:41
       1  100.0%      Script: exp.js
 
-      1    7.7%  LazyCompile: exp native math.js:41
-      1  100.0%    Script: exp.js
-

test/mjsunit/tools/tickprocessor-test.ignore-unknown

@@ -7,7 +7,6 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
 
  [JavaScript]:
    ticks  total  nonlib   name
-      1    9.1%   14.3%  LazyCompile: exp native math.js:41
 
  [C++]:
    ticks  total  nonlib   name
@@ -18,7 +17,7 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
 
  [Summary]:
    ticks  total  nonlib   name
-      1    9.1%   14.3%  JavaScript
+      0    0.0%    0.0%  JavaScript
       5   45.5%   71.4%  C++
       0    0.0%    0.0%  GC
       4   36.4%          Shared libraries
@@ -44,6 +43,10 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
       2  100.0%    LazyCompile: exp native math.js:41
       2  100.0%      Script: exp.js
 
+      2   18.2%  UNKNOWN
+      1   50.0%    LazyCompile: exp native math.js:41
+      1  100.0%      Script: exp.js
+
       1    9.1%  v8::internal::JSObject::LookupOwnRealNamedProperty(v8::internal::String*, v8::internal::LookupResult*)
       1  100.0%    Script: exp.js
 
@@ -56,6 +59,3 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
       1  100.0%    LazyCompile: exp native math.js:41
       1  100.0%      Script: exp.js
 
-      1    9.1%  LazyCompile: exp native math.js:41
-      1  100.0%    Script: exp.js
-

test/mjsunit/tools/tickprocessor-test.separate-ic

@@ -9,7 +9,6 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
    ticks  total  nonlib   name
       1    7.7%   11.1%  LoadIC: j
       1    7.7%   11.1%  LoadIC: i
-      1    7.7%   11.1%  LazyCompile: exp native math.js:41
 
  [C++]:
    ticks  total  nonlib   name
@@ -20,7 +19,7 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
 
  [Summary]:
    ticks  total  nonlib   name
-      3   23.1%   33.3%  JavaScript
+      2   15.4%   22.2%  JavaScript
       5   38.5%   55.6%  C++
       0    0.0%    0.0%  GC
       4   30.8%          Shared libraries
@@ -47,6 +46,10 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
       2  100.0%    LazyCompile: exp native math.js:41
       2  100.0%      Script: exp.js
 
+      2   15.4%  UNKNOWN
+      1   50.0%    LazyCompile: exp native math.js:41
+      1  100.0%      Script: exp.js
+
       1    7.7%  v8::internal::JSObject::LookupOwnRealNamedProperty(v8::internal::String*, v8::internal::LookupResult*)
       1  100.0%    Script: exp.js
 
@@ -63,6 +66,3 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
 
       1    7.7%  LoadIC: i
 
-      1    7.7%  LazyCompile: exp native math.js:41
-      1  100.0%    Script: exp.js
-

test/mjsunit/tools/tickprocessor.js

@@ -323,7 +323,7 @@ CppEntriesProviderMock.prototype.parseVmSymbols = function(
 
 
 function PrintMonitor(outputOrFileName) {
-  var expectedOut = typeof outputOrFileName == 'string' ?
+  var expectedOut = this.expectedOut = typeof outputOrFileName == 'string' ?
       this.loadExpectedOutput(outputOrFileName) : outputOrFileName;
   var outputPos = 0;
   var diffs = this.diffs = [];
@@ -359,7 +359,10 @@ PrintMonitor.prototype.loadExpectedOutput = function(fileName) {
 PrintMonitor.prototype.finish = function() {
   print = this.oldPrint;
   if (this.diffs.length > 0 || this.unexpectedOut != null) {
+    print("===== actual output: =====");
     print(this.realOut.join('\n'));
+    print("===== expected output: =====");
+    print(this.expectedOut.join('\n'));
     assertEquals([], this.diffs);
     assertNull(this.unexpectedOut);
   }
@@ -383,7 +386,8 @@ function driveTickProcessorTest(
                              stateFilter,
                              undefined,
                              "0",
-                             "auto,auto");
+                             "auto,auto",
+                             false);
   var pm = new PrintMonitor(testsPath + refOutput);
   tp.processLogFileInTest(testsPath + logInput);
   tp.printStatistics();

tools/logreader.js

@@ -35,14 +35,20 @@
  *
  * @param {Array.<Object>} dispatchTable A table used for parsing and processing
  *     log records.
+ * @param {boolean} timedRange Ignore ticks outside timed range.
  * @constructor
  */
-function LogReader(dispatchTable) {
+function LogReader(dispatchTable, timedRange) {
   /**
    * @type {Array.<Object>}
    */
   this.dispatchTable_ = dispatchTable;
 
+  /**
+   * @type {boolean}
+   */
+  this.timedRange_ = timedRange;
+
   /**
    * Current line.
    * @type {number}
@@ -54,6 +60,18 @@ function LogReader(dispatchTable) {
    * @type {CsvParser}
    */
   this.csvParser_ = new CsvParser();
+
+  /**
+   * Keeps track of whether we've seen a "current-time" tick yet.
+   * @type {boolean}
+   */
+  this.hasSeenTimerMarker_ = false;
+
+  /**
+   * List of log lines seen since last "current-time" tick.
+   * @type {Array.<String>}
+   */
+  this.logLinesSinceLastTimerMarker_ = [];
 };
 
 
@@ -83,7 +101,24 @@ LogReader.prototype.processLogChunk = function(chunk) {
  * @param {string} line A line of log.
  */
 LogReader.prototype.processLogLine = function(line) {
-  this.processLog_([line]);
+  if (!this.timedRange_) {
+    this.processLog_([line]);
+    return;
+  }
+  if (line.startsWith("current-time")) {
+    if (this.hasSeenTimerMarker_) {
+      this.processLog_(this.logLinesSinceLastTimerMarker_);
+      this.logLinesSinceLastTimerMarker_ = [];
+    } else {
+      this.hasSeenTimerMarker_ = true;
+    }
+  } else {
+    if (this.hasSeenTimerMarker_) {
+      this.logLinesSinceLastTimerMarker_.push(line);
+    } else if (!line.startsWith("tick")) {
+      this.processLog_([line]);
+    }
+  }
 };
 
 

tools/profile.js

@@ -257,26 +257,28 @@ Profile.prototype.resolveAndFilterFuncs_ = function(stack) {
     var entry = this.codeMap_.findEntry(stack[i]);
     if (entry) {
       var name = entry.getName();
-      if (i == 0 && (entry.type == 'CPP' || entry.type == 'SHARED_LIB')) {
+      if (i === 0 && (entry.type === 'CPP' || entry.type === 'SHARED_LIB')) {
         look_for_first_c_function = true;
       }
-      if (look_for_first_c_function) {
-        if (entry.type == 'CPP') {
-          last_seen_c_function = name;
-        } else if (i > 0 && last_seen_c_function != '') {
-          if (this.c_entries_[last_seen_c_function] === undefined) {
-            this.c_entries_[last_seen_c_function] = 0;
-          }
-          this.c_entries_[last_seen_c_function]++;
-          look_for_first_c_function = false;  // Found it, we're done.
-        }
+      if (look_for_first_c_function && entry.type === 'CPP') {
+        last_seen_c_function = name;
       }
       if (!this.skipThisFunction(name)) {
         result.push(name);
       }
     } else {
-      this.handleUnknownCode(
-          Profile.Operation.TICK, stack[i], i);
+      this.handleUnknownCode(Profile.Operation.TICK, stack[i], i);
+      if (i === 0) result.push("UNKNOWN");
+    }
+    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;
+      }
+      this.c_entries_[last_seen_c_function]++;
+      look_for_first_c_function = false;  // Found it, we're done.
     }
   }
   return result;

tools/tickprocessor-driver.js

@@ -75,6 +75,7 @@ var tickProcessor = new TickProcessor(
   snapshotLogProcessor,
   params.distortion,
   params.range,
-  sourceMap);
+  sourceMap,
+  params.timedRange);
 tickProcessor.processLogFile(params.logFileName);
 tickProcessor.printStatistics();

tools/tickprocessor.js

@@ -154,7 +154,8 @@ function TickProcessor(
     snapshotLogProcessor,
     distortion,
     range,
-    sourceMap) {
+    sourceMap,
+    timedRange) {
   LogReader.call(this, {
       'shared-library': { parsers: [null, parseInt, parseInt],
           processor: this.processSharedLibrary },
@@ -187,10 +188,12 @@ function TickProcessor(
       'function-move': null,
       'function-delete': null,
       'heap-sample-item': null,
+      'current-time': null,  // Handled specially, not parsed.
       // Obsolete row types.
       'code-allocate': null,
       'begin-code-region': null,
-      'end-code-region': null });
+      'end-code-region': null },
+      timedRange);
 
   this.cppEntriesProvider_ = cppEntriesProvider;
   this.callGraphSize_ = callGraphSize;
@@ -292,7 +295,7 @@ TickProcessor.prototype.isCppCode = function(name) {
 
 
 TickProcessor.prototype.isJsCode = function(name) {
-  return !(name in this.codeTypes_);
+  return name !== "UNKNOWN" && !(name in this.codeTypes_);
 };
 
 
@@ -875,7 +878,9 @@ function ArgumentsProcessor(args) {
     '--distortion': ['distortion', 0,
         'Specify the logging overhead in picoseconds'],
     '--source-map': ['sourceMap', null,
-        'Specify the source map that should be used for output']
+        'Specify the source map that should be used for output'],
+    '--timed-range': ['timedRange', true,
+        'Ignore ticks before first and after last Date.now() call']
   };
   this.argsDispatch_['--js'] = this.argsDispatch_['-j'];
   this.argsDispatch_['--gc'] = this.argsDispatch_['-g'];
@@ -896,7 +901,8 @@ ArgumentsProcessor.DEFAULTS = {
   targetRootFS: '',
   nm: 'nm',
   range: 'auto,auto',
-  distortion: 0
+  distortion: 0,
+  timedRange: false
 };