Skip to content

Commit feffccc

Browse files
jakobkummerowCommit bot
jakobkummerow
authored and
Commit bot
committed
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}
1 parent e62d974 commit feffccc

13 files changed

Lines changed: 97 additions & 60 deletions

‎src/flag-definitions.h‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -860,6 +860,8 @@ DEFINE_BOOL(log_snapshot_positions, false,
860860
DEFINE_BOOL(log_suspect, false, "Log suspect operations.")
861861
DEFINE_BOOL(prof, false,
862862
"Log statistical profiling information (implies --log-code).")
863+
DEFINE_BOOL(prof_cpp, false, "Like --prof, but ignore generated code.")
864+
DEFINE_IMPLICATION(prof, prof_cpp)
863865
DEFINE_BOOL(prof_browser_mode, true,
864866
"Used with --prof, turns on browser-compatible mode for profiling.")
865867
DEFINE_BOOL(log_regexp, false, "Log regular expression execution.")

‎src/isolate.cc‎

Lines changed: 0 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -2115,19 +2115,6 @@ bool Isolate::Init(Deserializer* des) {
21152115
std::ofstream(GetTurboCfgFileName().c_str(), std::ios_base::trunc);
21162116
}
21172117

2118-
// If we are deserializing, log non-function code objects and compiled
2119-
// functions found in the snapshot.
2120-
if (!create_heap_objects &&
2121-
(FLAG_log_code ||
2122-
FLAG_ll_prof ||
2123-
FLAG_perf_jit_prof ||
2124-
FLAG_perf_basic_prof ||
2125-
logger_->is_logging_code_events())) {
2126-
HandleScope scope(this);
2127-
LOG(this, LogCodeObjects());
2128-
LOG(this, LogCompiledFunctions());
2129-
}
2130-
21312118
CHECK_EQ(static_cast<int>(OFFSET_OF(Isolate, embedder_data_)),
21322119
Internals::kIsolateEmbedderDataOffset);
21332120
CHECK_EQ(static_cast<int>(OFFSET_OF(Isolate, heap_.roots_)),

‎src/log-utils.h‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -22,10 +22,10 @@ class Log {
2222
void stop() { is_stopped_ = true; }
2323

2424
static bool InitLogAtStart() {
25-
return FLAG_log || FLAG_log_api || FLAG_log_code || FLAG_log_gc
26-
|| FLAG_log_handles || FLAG_log_suspect || FLAG_log_regexp
27-
|| FLAG_ll_prof || FLAG_perf_basic_prof || FLAG_perf_jit_prof
28-
|| FLAG_log_internal_timer_events;
25+
return FLAG_log || FLAG_log_api || FLAG_log_code || FLAG_log_gc ||
26+
FLAG_log_handles || FLAG_log_suspect || FLAG_log_regexp ||
27+
FLAG_ll_prof || FLAG_perf_basic_prof || FLAG_perf_jit_prof ||
28+
FLAG_log_internal_timer_events || FLAG_prof_cpp;
2929
}
3030

3131
// Frees all resources acquired in Initialize and Open... functions.

‎src/log.cc‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -903,7 +903,7 @@ void Logger::ApiNamedSecurityCheck(Object* key) {
903903
void Logger::SharedLibraryEvent(const std::string& library_path,
904904
uintptr_t start,
905905
uintptr_t end) {
906-
if (!log_->IsEnabled() || !FLAG_prof) return;
906+
if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
907907
Log::MessageBuilder msg(log_);
908908
msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR,
909909
library_path.c_str(), start, end);
@@ -1516,7 +1516,7 @@ void Logger::DebugEvent(const char* event_type, Vector<uint16_t> parameter) {
15161516

15171517

15181518
void Logger::TickEvent(TickSample* sample, bool overflow) {
1519-
if (!log_->IsEnabled() || !FLAG_prof) return;
1519+
if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
15201520
Log::MessageBuilder msg(log_);
15211521
msg.Append("%s,", kLogEventsNames[TICK_EVENT]);
15221522
msg.AppendAddress(sample->pc);
@@ -1861,9 +1861,9 @@ bool Logger::SetUp(Isolate* isolate) {
18611861
is_logging_ = true;
18621862
}
18631863

1864-
if (FLAG_log_internal_timer_events || FLAG_prof) timer_.Start();
1864+
if (FLAG_log_internal_timer_events || FLAG_prof_cpp) timer_.Start();
18651865

1866-
if (FLAG_prof) {
1866+
if (FLAG_prof_cpp) {
18671867
profiler_ = new Profiler(isolate);
18681868
is_logging_ = true;
18691869
profiler_->Engage();

‎src/runtime/runtime-date.cc‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -70,7 +70,7 @@ RUNTIME_FUNCTION(Runtime_ThrowNotDateError) {
7070
RUNTIME_FUNCTION(Runtime_DateCurrentTime) {
7171
HandleScope scope(isolate);
7272
DCHECK(args.length() == 0);
73-
if (FLAG_log_timer_events) LOG(isolate, CurrentTimeEvent());
73+
if (FLAG_log_timer_events || FLAG_prof_cpp) LOG(isolate, CurrentTimeEvent());
7474

7575
// According to ECMA-262, section 15.9.1, page 117, the precision of
7676
// the number in a Date object representing a particular instant in

‎test/mjsunit/tools/tickprocessor-test.default‎

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,6 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
77

88
[JavaScript]:
99
ticks total nonlib name
10-
1 7.7% 11.1% LazyCompile: exp native math.js:41
1110

1211
[C++]:
1312
ticks total nonlib name
@@ -18,7 +17,7 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
1817

1918
[Summary]:
2019
ticks total nonlib name
21-
1 7.7% 11.1% JavaScript
20+
0 0.0% 0.0% JavaScript
2221
5 38.5% 55.6% C++
2322
0 0.0% 0.0% GC
2423
4 30.8% Shared libraries
@@ -45,6 +44,10 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
4544
2 100.0% LazyCompile: exp native math.js:41
4645
2 100.0% Script: exp.js
4746

47+
2 15.4% UNKNOWN
48+
1 50.0% LazyCompile: exp native math.js:41
49+
1 100.0% Script: exp.js
50+
4851
1 7.7% v8::internal::JSObject::LookupOwnRealNamedProperty(v8::internal::String*, v8::internal::LookupResult*)
4952
1 100.0% Script: exp.js
5053

@@ -57,6 +60,3 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
5760
1 100.0% LazyCompile: exp native math.js:41
5861
1 100.0% Script: exp.js
5962

60-
1 7.7% LazyCompile: exp native math.js:41
61-
1 100.0% Script: exp.js
62-

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

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,6 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
77

88
[JavaScript]:
99
ticks total nonlib name
10-
1 9.1% 14.3% LazyCompile: exp native math.js:41
1110

1211
[C++]:
1312
ticks total nonlib name
@@ -18,7 +17,7 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
1817

1918
[Summary]:
2019
ticks total nonlib name
21-
1 9.1% 14.3% JavaScript
20+
0 0.0% 0.0% JavaScript
2221
5 45.5% 71.4% C++
2322
0 0.0% 0.0% GC
2423
4 36.4% Shared libraries
@@ -44,6 +43,10 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
4443
2 100.0% LazyCompile: exp native math.js:41
4544
2 100.0% Script: exp.js
4645

46+
2 18.2% UNKNOWN
47+
1 50.0% LazyCompile: exp native math.js:41
48+
1 100.0% Script: exp.js
49+
4750
1 9.1% v8::internal::JSObject::LookupOwnRealNamedProperty(v8::internal::String*, v8::internal::LookupResult*)
4851
1 100.0% Script: exp.js
4952

@@ -56,6 +59,3 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
5659
1 100.0% LazyCompile: exp native math.js:41
5760
1 100.0% Script: exp.js
5861

59-
1 9.1% LazyCompile: exp native math.js:41
60-
1 100.0% Script: exp.js
61-

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

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,6 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
99
ticks total nonlib name
1010
1 7.7% 11.1% LoadIC: j
1111
1 7.7% 11.1% LoadIC: i
12-
1 7.7% 11.1% LazyCompile: exp native math.js:41
1312

1413
[C++]:
1514
ticks total nonlib name
@@ -20,7 +19,7 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
2019

2120
[Summary]:
2221
ticks total nonlib name
23-
3 23.1% 33.3% JavaScript
22+
2 15.4% 22.2% JavaScript
2423
5 38.5% 55.6% C++
2524
0 0.0% 0.0% GC
2625
4 30.8% Shared libraries
@@ -47,6 +46,10 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
4746
2 100.0% LazyCompile: exp native math.js:41
4847
2 100.0% Script: exp.js
4948

49+
2 15.4% UNKNOWN
50+
1 50.0% LazyCompile: exp native math.js:41
51+
1 100.0% Script: exp.js
52+
5053
1 7.7% v8::internal::JSObject::LookupOwnRealNamedProperty(v8::internal::String*, v8::internal::LookupResult*)
5154
1 100.0% Script: exp.js
5255

@@ -63,6 +66,3 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded).
6366

6467
1 7.7% LoadIC: i
6568

66-
1 7.7% LazyCompile: exp native math.js:41
67-
1 100.0% Script: exp.js
68-

‎test/mjsunit/tools/tickprocessor.js‎

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -323,7 +323,7 @@ CppEntriesProviderMock.prototype.parseVmSymbols = function(
323323

324324

325325
function PrintMonitor(outputOrFileName) {
326-
var expectedOut = typeof outputOrFileName == 'string' ?
326+
var expectedOut = this.expectedOut = typeof outputOrFileName == 'string' ?
327327
this.loadExpectedOutput(outputOrFileName) : outputOrFileName;
328328
var outputPos = 0;
329329
var diffs = this.diffs = [];
@@ -359,7 +359,10 @@ PrintMonitor.prototype.loadExpectedOutput = function(fileName) {
359359
PrintMonitor.prototype.finish = function() {
360360
print = this.oldPrint;
361361
if (this.diffs.length > 0 || this.unexpectedOut != null) {
362+
print("===== actual output: =====");
362363
print(this.realOut.join('\n'));
364+
print("===== expected output: =====");
365+
print(this.expectedOut.join('\n'));
363366
assertEquals([], this.diffs);
364367
assertNull(this.unexpectedOut);
365368
}
@@ -383,7 +386,8 @@ function driveTickProcessorTest(
383386
stateFilter,
384387
undefined,
385388
"0",
386-
"auto,auto");
389+
"auto,auto",
390+
false);
387391
var pm = new PrintMonitor(testsPath + refOutput);
388392
tp.processLogFileInTest(testsPath + logInput);
389393
tp.printStatistics();

‎tools/logreader.js‎

Lines changed: 37 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -35,14 +35,20 @@
3535
*
3636
* @param {Array.<Object>} dispatchTable A table used for parsing and processing
3737
* log records.
38+
* @param {boolean} timedRange Ignore ticks outside timed range.
3839
* @constructor
3940
*/
40-
function LogReader(dispatchTable) {
41+
function LogReader(dispatchTable, timedRange) {
4142
/**
4243
* @type {Array.<Object>}
4344
*/
4445
this.dispatchTable_ = dispatchTable;
4546

47+
/**
48+
* @type {boolean}
49+
*/
50+
this.timedRange_ = timedRange;
51+
4652
/**
4753
* Current line.
4854
* @type {number}
@@ -54,6 +60,18 @@ function LogReader(dispatchTable) {
5460
* @type {CsvParser}
5561
*/
5662
this.csvParser_ = new CsvParser();
63+
64+
/**
65+
* Keeps track of whether we've seen a "current-time" tick yet.
66+
* @type {boolean}
67+
*/
68+
this.hasSeenTimerMarker_ = false;
69+
70+
/**
71+
* List of log lines seen since last "current-time" tick.
72+
* @type {Array.<String>}
73+
*/
74+
this.logLinesSinceLastTimerMarker_ = [];
5775
};
5876

5977

@@ -83,7 +101,24 @@ LogReader.prototype.processLogChunk = function(chunk) {
83101
* @param {string} line A line of log.
84102
*/
85103
LogReader.prototype.processLogLine = function(line) {
86-
this.processLog_([line]);
104+
if (!this.timedRange_) {
105+
this.processLog_([line]);
106+
return;
107+
}
108+
if (line.startsWith("current-time")) {
109+
if (this.hasSeenTimerMarker_) {
110+
this.processLog_(this.logLinesSinceLastTimerMarker_);
111+
this.logLinesSinceLastTimerMarker_ = [];
112+
} else {
113+
this.hasSeenTimerMarker_ = true;
114+
}
115+
} else {
116+
if (this.hasSeenTimerMarker_) {
117+
this.logLinesSinceLastTimerMarker_.push(line);
118+
} else if (!line.startsWith("tick")) {
119+
this.processLog_([line]);
120+
}
121+
}
87122
};
88123

89124

0 commit comments

Comments
 (0)