From cbbe713464284e2477d42811867a0f463d636310 Mon Sep 17 00:00:00 2001 From: "mikhail.naganov@gmail.com" Date: Mon, 21 Mar 2011 18:13:27 +0000 Subject: [PATCH] Change the way sampler / profiler handle external callbacks. This should fix test-profile-generator/RecordStackTraceAtStartProfiling flakinness. R=vitalyr@chromium.org BUG=1261 TEST=test-profile-generator/RecordStackTraceAtStartProfiling Review URL: http://codereview.chromium.org/6708056 git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@7294 ce2b1a6d-e550-0410-aec6-3dcde31c8c00 --- src/log.cc | 27 +++++++++++++--------- src/platform.h | 14 +++++++---- src/profile-generator.cc | 10 +++++++- test/cctest/cctest.status | 3 --- test/cctest/test-log-stack-tracer.cc | 16 +++++-------- .../mjsunit/tools/tickprocessor-test-func-info.log | 6 ++--- test/mjsunit/tools/tickprocessor-test.log | 26 ++++++++++----------- tools/tickprocessor.js | 27 ++++++++++++++++------ 8 files changed, 76 insertions(+), 53 deletions(-) diff --git a/src/log.cc b/src/log.cc index 6013506..310e197 100644 --- a/src/log.cc +++ b/src/log.cc @@ -160,22 +160,21 @@ void StackTracer::Trace(Isolate* isolate, TickSample* sample) { return; } - // Sample potential return address value for frameless invocation of - // stubs (we'll figure out later, if this value makes sense). - sample->tos = Memory::Address_at(sample->sp); - - int i = 0; const Address callback = isolate->external_callback(); - // Surprisingly, PC can point _exactly_ to callback start, with good - // probability, and this will result in reporting fake nested - // callback call. - if (callback != NULL && callback != sample->pc) { - sample->stack[i++] = callback; + if (callback != NULL) { + sample->external_callback = callback; + sample->has_external_callback = true; + } else { + // Sample potential return address value for frameless invocation of + // stubs (we'll figure out later, if this value makes sense). + sample->tos = Memory::Address_at(sample->sp); + sample->has_external_callback = false; } SafeStackTraceFrameIterator it(isolate, sample->fp, sample->sp, sample->sp, js_entry_sp); + int i = 0; while (!it.done() && i < TickSample::kMaxFramesCount) { sample->stack[i++] = it.frame()->pc(); it.Advance(); @@ -1134,7 +1133,13 @@ void Logger::TickEvent(TickSample* sample, bool overflow) { msg.Append(','); msg.AppendAddress(sample->sp); msg.Append(','); - msg.AppendAddress(sample->tos); + if (sample->has_external_callback) { + msg.Append(",1,"); + msg.AppendAddress(sample->external_callback); + } else { + msg.Append(",0,"); + msg.AppendAddress(sample->tos); + } msg.Append(",%d", static_cast(sample->state)); if (overflow) { msg.Append(",overflow"); diff --git a/src/platform.h b/src/platform.h index a6f5fb7..43291cf 100644 --- a/src/platform.h +++ b/src/platform.h @@ -581,13 +581,17 @@ class TickSample { tos(NULL), frames_count(0) {} StateTag state; // The state of the VM. - Address pc; // Instruction pointer. - Address sp; // Stack pointer. - Address fp; // Frame pointer. - Address tos; // Top stack value (*sp). + Address pc; // Instruction pointer. + Address sp; // Stack pointer. + Address fp; // Frame pointer. + union { + Address tos; // Top stack value (*sp). + Address external_callback; + }; static const int kMaxFramesCount = 64; Address stack[kMaxFramesCount]; // Call stack. - int frames_count; // Number of captured frames. + int frames_count : 8; // Number of captured frames. + bool has_external_callback : 1; }; #ifdef ENABLE_LOGGING_AND_PROFILING diff --git a/src/profile-generator.cc b/src/profile-generator.cc index 78b35e2..f836583 100644 --- a/src/profile-generator.cc +++ b/src/profile-generator.cc @@ -813,7 +813,15 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) { if (sample.pc != NULL) { *entry++ = code_map_.FindEntry(sample.pc); - if (sample.tos != NULL) { + if (sample.has_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. + *(entries.start()) = NULL; + *entry++ = code_map_.FindEntry(sample.external_callback); + } else if (sample.tos != NULL) { + // Find out, if top of stack was pointing inside a JS function + // meaning that we have encountered a frameless invocation. *entry = code_map_.FindEntry(sample.tos); if (*entry != NULL && !(*entry)->is_js_function()) { *entry = NULL; diff --git a/test/cctest/cctest.status b/test/cctest/cctest.status index fcf0fbf..f3433d7 100644 --- a/test/cctest/cctest.status +++ b/test/cctest/cctest.status @@ -46,9 +46,6 @@ test-heap-profiler/HeapSnapshotsDiff: PASS || FAIL test-serialize/TestThatAlwaysFails: FAIL test-serialize/DependentTestThatAlwaysFails: FAIL -# BUG(1261): Flakey test. -test-profile-generator/RecordStackTraceAtStartProfiling: PASS || FAIL - ############################################################################## [ $arch == arm ] diff --git a/test/cctest/test-log-stack-tracer.cc b/test/cctest/test-log-stack-tracer.cc index e87da3e..df0806f 100644 --- a/test/cctest/test-log-stack-tracer.cc +++ b/test/cctest/test-log-stack-tracer.cc @@ -303,13 +303,11 @@ TEST(CFromJSStackTrace) { // DoTrace(EBP) [native] // StackTracer::Trace - // The VM state tracking keeps track of external callbacks and puts - // them at the top of the sample stack. - int base = 0; - CHECK(sample.stack[0] == FUNCTION_ADDR(TraceExtension::Trace)); - base++; + CHECK(sample.has_external_callback); + CHECK_EQ(FUNCTION_ADDR(TraceExtension::Trace), sample.external_callback); // Stack tracing will start from the first JS function, i.e. "JSFuncDoTrace" + int base = 0; CHECK_GT(sample.frames_count, base + 1); CHECK(IsAddressWithinFuncCode("JSFuncDoTrace", sample.stack[base + 0])); CHECK(IsAddressWithinFuncCode("JSTrace", sample.stack[base + 1])); @@ -354,13 +352,11 @@ TEST(PureJSStackTrace) { // StackTracer::Trace // - // The VM state tracking keeps track of external callbacks and puts - // them at the top of the sample stack. - int base = 0; - CHECK(sample.stack[0] == FUNCTION_ADDR(TraceExtension::JSTrace)); - base++; + CHECK(sample.has_external_callback); + CHECK_EQ(FUNCTION_ADDR(TraceExtension::JSTrace), sample.external_callback); // Stack sampling will start from the caller of JSFuncDoTrace, i.e. "JSTrace" + int base = 0; CHECK_GT(sample.frames_count, base + 1); CHECK(IsAddressWithinFuncCode("JSTrace", sample.stack[base + 0])); CHECK(IsAddressWithinFuncCode("OuterJSTrace", sample.stack[base + 1])); diff --git a/test/mjsunit/tools/tickprocessor-test-func-info.log b/test/mjsunit/tools/tickprocessor-test-func-info.log index 755fbb2..e4015d4 100644 --- a/test/mjsunit/tools/tickprocessor-test-func-info.log +++ b/test/mjsunit/tools/tickprocessor-test-func-info.log @@ -5,7 +5,7 @@ profiler,"begin",1 code-creation,Stub,0x424260,348,"CompareStub_GE" code-creation,LazyCompile,0x2a8100,18535,"DrawQube 3d-cube.js:188",0xf43abcac, code-creation,LazyCompile,0x480100,3908,"DrawLine 3d-cube.js:17",0xf43abc50, -tick,0x424284,0xbfffeea0,0x480600,0,0x2aaaa5 -tick,0x42429f,0xbfffed88,0x480600,0,0x2aacb4 -tick,0x48063d,0xbfffec7c,0x2d0f7c,0,0x2aaec6 +tick,0x424284,0xbfffeea0,0,0x480600,0,0x2aaaa5 +tick,0x42429f,0xbfffed88,0,0x480600,0,0x2aacb4 +tick,0x48063d,0xbfffec7c,0,0x2d0f7c,0,0x2aaec6 profiler,"end" diff --git a/test/mjsunit/tools/tickprocessor-test.log b/test/mjsunit/tools/tickprocessor-test.log index 80e7ec1..db8be79 100644 --- a/test/mjsunit/tools/tickprocessor-test.log +++ b/test/mjsunit/tools/tickprocessor-test.log @@ -9,17 +9,17 @@ code-creation,LazyCompile,0xf541d120,145,"exp native math.js:41" function-creation,0xf441d280,0xf541d120 code-creation,LoadIC,0xf541d280,117,"j" code-creation,LoadIC,0xf541d360,63,"i" -tick,0x80f82d1,0xffdfe880,0,0,0xf541ce5c -tick,0x80f89a1,0xffdfecf0,0,0,0xf541ce5c -tick,0x8123b5c,0xffdff1a0,0,0,0xf541d1a1,0xf541ceea -tick,0x8123b65,0xffdff1a0,0,0,0xf541d1a1,0xf541ceea -tick,0xf541d2be,0xffdff1e4,0,0 -tick,0xf541d320,0xffdff1dc,0,0 -tick,0xf541d384,0xffdff1d8,0,0 -tick,0xf7db94da,0xffdff0ec,0,0,0xf541d1a1,0xf541ceea -tick,0xf7db951c,0xffdff0f0,0,0,0xf541d1a1,0xf541ceea -tick,0xf7dbc508,0xffdff14c,0,0,0xf541d1a1,0xf541ceea -tick,0xf7dbff21,0xffdff198,0,0,0xf541d1a1,0xf541ceea -tick,0xf7edec90,0xffdff0ec,0,0,0xf541d1a1,0xf541ceea -tick,0xffffe402,0xffdff488,0,0 +tick,0x80f82d1,0xffdfe880,0,0,0,0xf541ce5c +tick,0x80f89a1,0xffdfecf0,0,0,0,0xf541ce5c +tick,0x8123b5c,0xffdff1a0,0,0,0,0xf541d1a1,0xf541ceea +tick,0x8123b65,0xffdff1a0,0,0,0,0xf541d1a1,0xf541ceea +tick,0xf541d2be,0xffdff1e4,0,0,0 +tick,0xf541d320,0xffdff1dc,0,0,0 +tick,0xf541d384,0xffdff1d8,0,0,0 +tick,0xf7db94da,0xffdff0ec,0,0,0,0xf541d1a1,0xf541ceea +tick,0xf7db951c,0xffdff0f0,0,0,0,0xf541d1a1,0xf541ceea +tick,0xf7dbc508,0xffdff14c,0,0,0,0xf541d1a1,0xf541ceea +tick,0xf7dbff21,0xffdff198,0,0,0,0xf541d1a1,0xf541ceea +tick,0xf7edec90,0xffdff0ec,0,0,0,0xf541d1a1,0xf541ceea +tick,0xffffe402,0xffdff488,0,0,0 profiler,"end" diff --git a/tools/tickprocessor.js b/tools/tickprocessor.js index f105a21..7a05ef1 100644 --- a/tools/tickprocessor.js +++ b/tools/tickprocessor.js @@ -161,7 +161,9 @@ function TickProcessor( processor: this.processFunctionMove }, 'snapshot-pos': { parsers: [parseInt, parseInt], processor: this.processSnapshotPosition }, - 'tick': { parsers: [parseInt, parseInt, parseInt, parseInt, 'var-args'], + 'tick': { + parsers: [parseInt, parseInt, parseInt, + parseInt, parseInt, 'var-args'], processor: this.processTick }, 'heap-sample-begin': { parsers: [null, null, parseInt], processor: this.processHeapSampleBegin }, @@ -344,22 +346,33 @@ TickProcessor.prototype.includeTick = function(vmState) { }; -TickProcessor.prototype.processTick = function(pc, sp, tos, vmState, stack) { +TickProcessor.prototype.processTick = function(pc, + sp, + is_external_callback, + tos_or_external_callback, + vmState, + stack) { this.ticks_.total++; if (vmState == TickProcessor.VmStates.GC) this.ticks_.gc++; if (!this.includeTick(vmState)) { this.ticks_.excluded++; return; } - - if (tos) { - var funcEntry = this.profile_.findEntry(tos); + 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. + pc = 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. + var funcEntry = this.profile_.findEntry(tos_or_external_callback); if (!funcEntry || !funcEntry.isJSFunction || !funcEntry.isJSFunction()) { - tos = 0; + tos_or_external_callback = 0; } } - this.profile_.recordTick(this.processStack(pc, tos, stack)); + this.profile_.recordTick(this.processStack(pc, tos_or_external_callback, stack)); }; -- 2.7.4