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

@@ -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<int>(sample->state));
   if (overflow) {
     msg.Append(",overflow");

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

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;

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 ]
 

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]));

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"

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"

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));
 };