From c186399e5f1af0aa3742e809b2a50d05b124753c Mon Sep 17 00:00:00 2001 From: "jkummerow@chromium.org" Date: Fri, 17 Oct 2014 15:44:02 +0000 Subject: [PATCH] Tick processor: Print C++ entry points R=loislo@chromium.org, yangguo@chromium.org, yurys@chromium.org Review URL: https://codereview.chromium.org/638633002 git-svn-id: https://v8.googlecode.com/svn/branches/bleeding_edge@24700 ce2b1a6d-e550-0410-aec6-3dcde31c8c00 --- src/api.cc | 4 +- src/cpu-profiler.cc | 2 +- src/ia32/macro-assembler-ia32.cc | 2 + src/isolate.h | 6 +++ src/sampler.cc | 14 +++++-- src/sampler.h | 9 +++- src/x64/macro-assembler-x64.cc | 1 + test/cctest/trace-extension.cc | 3 +- test/mjsunit/tools/tickprocessor-test.default | 7 ++++ test/mjsunit/tools/tickprocessor-test.func-info | 3 ++ test/mjsunit/tools/tickprocessor-test.gc-state | 3 ++ .../tools/tickprocessor-test.ignore-unknown | 7 ++++ test/mjsunit/tools/tickprocessor-test.separate-ic | 7 ++++ tools/codemap.js | 4 +- tools/logreader.js | 2 + tools/profile.js | 49 +++++++++++++++++++--- tools/tickprocessor.js | 9 ++++ 17 files changed, 116 insertions(+), 16 deletions(-) diff --git a/src/api.cc b/src/api.cc index b190925..0c78b5f 100644 --- a/src/api.cc +++ b/src/api.cc @@ -6657,8 +6657,8 @@ void Isolate::GetHeapStatistics(HeapStatistics* heap_statistics) { void Isolate::GetStackSample(const RegisterState& state, void** frames, size_t frames_limit, SampleInfo* sample_info) { i::Isolate* isolate = reinterpret_cast(this); - i::TickSample::GetStackSample(isolate, state, frames, frames_limit, - sample_info); + i::TickSample::GetStackSample(isolate, state, i::TickSample::kSkipCEntryFrame, + frames, frames_limit, sample_info); } diff --git a/src/cpu-profiler.cc b/src/cpu-profiler.cc index 8bd3e4d..5b5b67a 100644 --- a/src/cpu-profiler.cc +++ b/src/cpu-profiler.cc @@ -48,7 +48,7 @@ void ProfilerEventsProcessor::AddCurrentStack(Isolate* isolate) { regs.fp = frame->fp(); regs.pc = frame->pc(); } - record.sample.Init(isolate, regs); + record.sample.Init(isolate, regs, TickSample::kSkipCEntryFrame); ticks_from_vm_buffer_.Enqueue(record); } diff --git a/src/ia32/macro-assembler-ia32.cc b/src/ia32/macro-assembler-ia32.cc index 9c0a355..098415e 100644 --- a/src/ia32/macro-assembler-ia32.cc +++ b/src/ia32/macro-assembler-ia32.cc @@ -942,8 +942,10 @@ void MacroAssembler::EnterExitFramePrologue() { // Save the frame pointer and the context in top. ExternalReference c_entry_fp_address(Isolate::kCEntryFPAddress, isolate()); ExternalReference context_address(Isolate::kContextAddress, isolate()); + ExternalReference c_function_address(Isolate::kCFunctionAddress, isolate()); mov(Operand::StaticVariable(c_entry_fp_address), ebp); mov(Operand::StaticVariable(context_address), esi); + mov(Operand::StaticVariable(c_function_address), ebx); } diff --git a/src/isolate.h b/src/isolate.h index 7fd4a82..2e7f459 100644 --- a/src/isolate.h +++ b/src/isolate.h @@ -169,6 +169,7 @@ typedef ZoneList > ZoneObjectList; #define FOR_EACH_ISOLATE_ADDRESS_NAME(C) \ C(Handler, handler) \ C(CEntryFP, c_entry_fp) \ + C(CFunction, c_function) \ C(Context, context) \ C(PendingException, pending_exception) \ C(ExternalCaughtException, external_caught_exception) \ @@ -288,6 +289,7 @@ class ThreadLocalTop BASE_EMBEDDED { // Stack. Address c_entry_fp_; // the frame pointer of the top c entry frame Address handler_; // try-blocks are chained through the stack + Address c_function_; // C function that was called at c entry. // Throwing an exception may cause a Promise rejection. For this purpose // we keep track of a stack of nested promises and the corresponding @@ -652,11 +654,15 @@ class Isolate { return thread->c_entry_fp_; } static Address handler(ThreadLocalTop* thread) { return thread->handler_; } + Address c_function() { return thread_local_top_.c_function_; } inline Address* c_entry_fp_address() { return &thread_local_top_.c_entry_fp_; } inline Address* handler_address() { return &thread_local_top_.handler_; } + inline Address* c_function_address() { + return &thread_local_top_.c_function_; + } // Bottom JS entry. Address js_entry_sp() { diff --git a/src/sampler.cc b/src/sampler.cc index 95b7f4b..763b065 100644 --- a/src/sampler.cc +++ b/src/sampler.cc @@ -570,7 +570,8 @@ SamplerThread* SamplerThread::instance_ = NULL; // StackTracer implementation // DISABLE_ASAN void TickSample::Init(Isolate* isolate, - const v8::RegisterState& regs) { + const v8::RegisterState& regs, + RecordCEntryFrame record_c_entry_frame) { timestamp = base::TimeTicks::HighResolutionNow(); pc = reinterpret_cast
(regs.pc); state = isolate->current_vm_state(); @@ -601,13 +602,14 @@ DISABLE_ASAN void TickSample::Init(Isolate* isolate, top_frame_type = it.top_frame_type(); SampleInfo info; - GetStackSample(isolate, regs, reinterpret_cast(&stack[0]), - kMaxFramesCount, &info); + GetStackSample(isolate, regs, record_c_entry_frame, + reinterpret_cast(&stack[0]), kMaxFramesCount, &info); frames_count = static_cast(info.frames_count); } void TickSample::GetStackSample(Isolate* isolate, const v8::RegisterState& regs, + RecordCEntryFrame record_c_entry_frame, void** frames, size_t frames_limit, v8::SampleInfo* sample_info) { sample_info->frames_count = 0; @@ -620,6 +622,10 @@ void TickSample::GetStackSample(Isolate* isolate, const v8::RegisterState& regs, SafeStackFrameIterator it(isolate, reinterpret_cast
(regs.fp), reinterpret_cast
(regs.sp), js_entry_sp); size_t i = 0; + if (record_c_entry_frame == kIncludeCEntryFrame && !it.done() && + it.top_frame_type() == StackFrame::EXIT) { + frames[i++] = isolate->c_function(); + } while (!it.done() && i < frames_limit) { frames[i++] = it.frame()->pc(); it.Advance(); @@ -696,7 +702,7 @@ void Sampler::SampleStack(const v8::RegisterState& state) { TickSample* sample = isolate_->cpu_profiler()->StartTickSample(); TickSample sample_obj; if (sample == NULL) sample = &sample_obj; - sample->Init(isolate_, state); + sample->Init(isolate_, state, TickSample::kIncludeCEntryFrame); if (is_counting_samples_) { if (sample->state == JS || sample->state == EXTERNAL) { ++js_and_external_sample_count_; diff --git a/src/sampler.h b/src/sampler.h index 7b84af2..120260d 100644 --- a/src/sampler.h +++ b/src/sampler.h @@ -25,6 +25,11 @@ class Isolate; // TickSample captures the information collected for each sample. struct TickSample { + // Internal profiling (with --prof + tools/$OS-tick-processor) wants to + // include the runtime function we're calling. Externally exposed tick + // samples don't care. + enum RecordCEntryFrame { kIncludeCEntryFrame, kSkipCEntryFrame }; + TickSample() : state(OTHER), pc(NULL), @@ -32,8 +37,10 @@ struct TickSample { frames_count(0), has_external_callback(false), top_frame_type(StackFrame::NONE) {} - void Init(Isolate* isolate, const v8::RegisterState& state); + void Init(Isolate* isolate, const v8::RegisterState& state, + RecordCEntryFrame record_c_entry_frame); static void GetStackSample(Isolate* isolate, const v8::RegisterState& state, + RecordCEntryFrame record_c_entry_frame, void** frames, size_t frames_limit, v8::SampleInfo* sample_info); StateTag state; // The state of the VM. diff --git a/src/x64/macro-assembler-x64.cc b/src/x64/macro-assembler-x64.cc index 7c0a690..21b0f9b 100644 --- a/src/x64/macro-assembler-x64.cc +++ b/src/x64/macro-assembler-x64.cc @@ -4093,6 +4093,7 @@ void MacroAssembler::EnterExitFramePrologue(bool save_rax) { Store(ExternalReference(Isolate::kCEntryFPAddress, isolate()), rbp); Store(ExternalReference(Isolate::kContextAddress, isolate()), rsi); + Store(ExternalReference(Isolate::kCFunctionAddress, isolate()), rbx); } diff --git a/test/cctest/trace-extension.cc b/test/cctest/trace-extension.cc index 8f390e4..0a1ff87 100644 --- a/test/cctest/trace-extension.cc +++ b/test/cctest/trace-extension.cc @@ -91,7 +91,8 @@ void TraceExtension::DoTrace(Address fp) { // sp is only used to define stack high bound regs.sp = reinterpret_cast
(trace_env.sample) - 10240; - trace_env.sample->Init(CcTest::i_isolate(), regs); + trace_env.sample->Init(CcTest::i_isolate(), regs, + TickSample::kSkipCEntryFrame); } diff --git a/test/mjsunit/tools/tickprocessor-test.default b/test/mjsunit/tools/tickprocessor-test.default index 3e01532..c2fe441 100644 --- a/test/mjsunit/tools/tickprocessor-test.default +++ b/test/mjsunit/tools/tickprocessor-test.default @@ -24,6 +24,13 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded). 4 30.8% Shared libraries 2 15.4% Unaccounted + [C++ entry points]: + ticks cpp total name + 2 40.0% 15.4% v8::internal::Runtime_Math_exp(v8::internal::Arguments) + 1 20.0% 7.7% v8::internal::JSObject::LookupOwnRealNamedProperty(v8::internal::String*, v8::internal::LookupResult*) + 1 20.0% 7.7% v8::internal::HashTable::FindEntry(v8::internal::String*) + 1 20.0% 7.7% exp + [Bottom up (heavy) profile]: Note: percentage shows a share of a particular caller in the total amount of its parent calls. diff --git a/test/mjsunit/tools/tickprocessor-test.func-info b/test/mjsunit/tools/tickprocessor-test.func-info index c93b6ec..1f34cfb 100644 --- a/test/mjsunit/tools/tickprocessor-test.func-info +++ b/test/mjsunit/tools/tickprocessor-test.func-info @@ -18,6 +18,9 @@ Statistical profiling result from v8.log, (3 ticks, 0 unaccounted, 0 excluded). 0 0.0% 0.0% GC 0 0.0% Shared libraries + [C++ entry points]: + ticks cpp total name + [Bottom up (heavy) profile]: Note: percentage shows a share of a particular caller in the total amount of its parent calls. diff --git a/test/mjsunit/tools/tickprocessor-test.gc-state b/test/mjsunit/tools/tickprocessor-test.gc-state index 6b1a6a3..d96acf5 100644 --- a/test/mjsunit/tools/tickprocessor-test.gc-state +++ b/test/mjsunit/tools/tickprocessor-test.gc-state @@ -16,6 +16,9 @@ Statistical profiling result from v8.log, (13 ticks, 0 unaccounted, 13 excluded) 0 0.0% 0.0% GC 0 0.0% Shared libraries + [C++ entry points]: + ticks cpp total name + [Bottom up (heavy) profile]: Note: percentage shows a share of a particular caller in the total amount of its parent calls. diff --git a/test/mjsunit/tools/tickprocessor-test.ignore-unknown b/test/mjsunit/tools/tickprocessor-test.ignore-unknown index de70527..263cec5 100644 --- a/test/mjsunit/tools/tickprocessor-test.ignore-unknown +++ b/test/mjsunit/tools/tickprocessor-test.ignore-unknown @@ -23,6 +23,13 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded). 0 0.0% 0.0% GC 4 36.4% Shared libraries + [C++ entry points]: + ticks cpp total name + 2 40.0% 18.2% v8::internal::Runtime_Math_exp(v8::internal::Arguments) + 1 20.0% 9.1% v8::internal::JSObject::LookupOwnRealNamedProperty(v8::internal::String*, v8::internal::LookupResult*) + 1 20.0% 9.1% v8::internal::HashTable::FindEntry(v8::internal::String*) + 1 20.0% 9.1% exp + [Bottom up (heavy) profile]: Note: percentage shows a share of a particular caller in the total amount of its parent calls. diff --git a/test/mjsunit/tools/tickprocessor-test.separate-ic b/test/mjsunit/tools/tickprocessor-test.separate-ic index 119ccbe..aee1d1f 100644 --- a/test/mjsunit/tools/tickprocessor-test.separate-ic +++ b/test/mjsunit/tools/tickprocessor-test.separate-ic @@ -26,6 +26,13 @@ Statistical profiling result from v8.log, (13 ticks, 2 unaccounted, 0 excluded). 4 30.8% Shared libraries 2 15.4% Unaccounted + [C++ entry points]: + ticks cpp total name + 2 40.0% 15.4% v8::internal::Runtime_Math_exp(v8::internal::Arguments) + 1 20.0% 7.7% v8::internal::JSObject::LookupOwnRealNamedProperty(v8::internal::String*, v8::internal::LookupResult*) + 1 20.0% 7.7% v8::internal::HashTable::FindEntry(v8::internal::String*) + 1 20.0% 7.7% exp + [Bottom up (heavy) profile]: Note: percentage shows a share of a particular caller in the total amount of its parent calls. diff --git a/tools/codemap.js b/tools/codemap.js index 129179e..fa6c36b 100644 --- a/tools/codemap.js +++ b/tools/codemap.js @@ -258,11 +258,13 @@ CodeMap.prototype.getAllLibrariesEntries = function() { * * @param {number} size Code entry size in bytes. * @param {string} opt_name Code entry name. + * @param {string} opt_type Code entry type, e.g. SHARED_LIB, CPP. * @constructor */ -CodeMap.CodeEntry = function(size, opt_name) { +CodeMap.CodeEntry = function(size, opt_name, opt_type) { this.size = size; this.name = opt_name || ''; + this.type = opt_type || ''; this.nameUpdated_ = false; }; diff --git a/tools/logreader.js b/tools/logreader.js index a8141da..5f0ec7f 100644 --- a/tools/logreader.js +++ b/tools/logreader.js @@ -108,6 +108,8 @@ LogReader.prototype.processStack = function(pc, func, stack) { // Filter out possible 'overflow' string. } else if (firstChar != 'o') { fullStack.push(parseInt(frame, 16)); + } else { + print("dropping: " + frame); } } return fullStack; diff --git a/tools/profile.js b/tools/profile.js index 10a07f8..a06cd3a 100644 --- a/tools/profile.js +++ b/tools/profile.js @@ -36,6 +36,7 @@ function Profile() { this.codeMap_ = new CodeMap(); this.topDownTree_ = new CallTree(); this.bottomUpTree_ = new CallTree(); + this.c_entries_ = {}; }; @@ -102,7 +103,7 @@ Profile.prototype.handleUnknownCode = function( Profile.prototype.addLibrary = function( name, startAddr, endAddr) { var entry = new CodeMap.CodeEntry( - endAddr - startAddr, name); + endAddr - startAddr, name, 'SHARED_LIB'); this.codeMap_.addLibrary(startAddr, entry); return entry; }; @@ -118,7 +119,7 @@ Profile.prototype.addLibrary = function( Profile.prototype.addStaticCode = function( name, startAddr, endAddr) { var entry = new CodeMap.CodeEntry( - endAddr - startAddr, name); + endAddr - startAddr, name, 'CPP'); this.codeMap_.addStaticCode(startAddr, entry); return entry; }; @@ -250,10 +251,26 @@ Profile.prototype.recordTick = function(stack) { */ Profile.prototype.resolveAndFilterFuncs_ = function(stack) { var result = []; + var last_seen_c_function = ''; + var look_for_first_c_function = false; for (var i = 0; i < stack.length; ++i) { var entry = this.codeMap_.findEntry(stack[i]); if (entry) { var name = entry.getName(); + 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 (!this.skipThisFunction(name)) { result.push(name); } @@ -381,6 +398,28 @@ Profile.prototype.getFlatProfile = function(opt_label) { }; +Profile.CEntryNode = function(name, ticks) { + this.name = name; + this.ticks = ticks; +} + + +Profile.prototype.getCEntryProfile = function() { + var result = [new Profile.CEntryNode("TOTAL", 0)]; + var total_ticks = 0; + for (var f in this.c_entries_) { + var ticks = this.c_entries_[f]; + total_ticks += ticks; + result.push(new Profile.CEntryNode(f, ticks)); + } + result[0].ticks = total_ticks; // Sorting will keep this at index 0. + result.sort(function(n1, n2) { + return n2.ticks - n1.ticks || (n2.name < n1.name ? -1 : 1) + }); + return result; +} + + /** * Cleans up function entries that are not referenced by code entries. */ @@ -415,8 +454,7 @@ Profile.prototype.cleanUpFuncEntries = function() { * @constructor */ Profile.DynamicCodeEntry = function(size, type, name) { - CodeMap.CodeEntry.call(this, size, name); - this.type = type; + CodeMap.CodeEntry.call(this, size, name, type); }; @@ -456,8 +494,7 @@ Profile.DynamicCodeEntry.prototype.toString = function() { * @constructor */ Profile.DynamicFuncCodeEntry = function(size, type, func, state) { - CodeMap.CodeEntry.call(this, size); - this.type = type; + CodeMap.CodeEntry.call(this, size, '', type); this.func = func; this.state = state; }; diff --git a/tools/tickprocessor.js b/tools/tickprocessor.js index acd7a71..d544717 100644 --- a/tools/tickprocessor.js +++ b/tools/tickprocessor.js @@ -485,6 +485,15 @@ TickProcessor.prototype.printStatistics = function() { this.ticks_.total, null); } + print('\n [C++ entry points]:'); + print(' ticks cpp total name'); + var c_entry_functions = this.profile_.getCEntryProfile(); + var total_c_entry = c_entry_functions[0].ticks; + for (var i = 1; i < c_entry_functions.length; i++) { + c = c_entry_functions[i]; + this.printLine(c.name, c.ticks, total_c_entry, totalTicks); + } + this.printHeavyProfHeader(); var heavyProfile = this.profile_.getBottomUpProfile(); var heavyView = this.viewBuilder_.buildView(heavyProfile); -- 2.7.4