CPUProfiler: Improve line numbers support in profiler.

1) report line number even if a script has no resource_name (evals);
  a) do that for already compiled functions in log.cc;
  b) do that for fresh evals in compiler.cc;

2) Implement the test for LineNumbers and make it fast and stable, otherwise we have to wait for tick samples;
  a) move processor_->Join() call into new Processor::StopSynchronously method;
  b) Process all the CodeEvents even if we are stopping Processor thread;
  c) make getters for generator and processor;

3) Fix the test for Jit that didn't expect line numbers;

4) Minor refactoring:
  a) in ProcessTicks;
  b) rename enqueue_order_ to last_code_event_id_ for better readability;
  c) rename dequeue_order_ to last_processed_code_event_id_ and make it a member for better readability;

BUG=
TEST=test-profile-generator/LineNumber
R=jkummerow@chromium.org, yurys@chromium.org

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

git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@15530 ce2b1a6d-e550-0410-aec6-3dcde31c8c00

src/compiler.cc

@@ -1200,9 +1200,9 @@ void Compiler::RecordFunctionCompilation(Logger::LogEventsAndTags tag,
     Handle<Code> code = info->code();
     if (*code == info->isolate()->builtins()->builtin(Builtins::kLazyCompile))
       return;
+    int line_num = GetScriptLineNumber(script, shared->start_position()) + 1;
+    USE(line_num);
     if (script->name()->IsString()) {
-      int line_num = GetScriptLineNumber(script, shared->start_position()) + 1;
-      USE(line_num);
       PROFILE(info->isolate(),
               CodeCreateEvent(Logger::ToNativeByScript(tag, *script),
                               *code,
@@ -1216,7 +1216,8 @@ void Compiler::RecordFunctionCompilation(Logger::LogEventsAndTags tag,
                               *code,
                               *shared,
                               info,
-                              shared->DebugName()));
+                              info->isolate()->heap()->empty_string(),
+                              line_num));
     }
   }
 

src/cpu-profiler-inl.h

@@ -70,7 +70,7 @@ void ReportBuiltinEventRecord::UpdateCodeMap(CodeMap* code_map) {
 TickSample* ProfilerEventsProcessor::TickSampleEvent() {
   generator_->Tick();
   TickSampleEventRecord* evt =
-      new(ticks_buffer_.Enqueue()) TickSampleEventRecord(enqueue_order_);
+      new(ticks_buffer_.Enqueue()) TickSampleEventRecord(last_code_event_id_);
   return &evt->sample;
 }
 

src/cpu-profiler.cc

@@ -52,18 +52,18 @@ ProfilerEventsProcessor::ProfilerEventsProcessor(ProfileGenerator* generator)
       ticks_buffer_(sizeof(TickSampleEventRecord),
                     kTickSamplesBufferChunkSize,
                     kTickSamplesBufferChunksCount),
-      enqueue_order_(0) {
+      last_code_event_id_(0), last_processed_code_event_id_(0) {
 }
 
 
 void ProfilerEventsProcessor::Enqueue(const CodeEventsContainer& event) {
-  event.generic.order = ++enqueue_order_;
+  event.generic.order = ++last_code_event_id_;
   events_buffer_.Enqueue(event);
 }
 
 
 void ProfilerEventsProcessor::AddCurrentStack(Isolate* isolate) {
-  TickSampleEventRecord record(enqueue_order_);
+  TickSampleEventRecord record(last_code_event_id_);
   TickSample* sample = &record.sample;
   sample->state = isolate->current_vm_state();
   sample->pc = reinterpret_cast<Address>(sample);  // Not NULL.
@@ -76,7 +76,14 @@ void ProfilerEventsProcessor::AddCurrentStack(Isolate* isolate) {
 }
 
 
-bool ProfilerEventsProcessor::ProcessCodeEvent(unsigned* dequeue_order) {
+void ProfilerEventsProcessor::StopSynchronously() {
+  if (!running_) return;
+  running_ = false;
+  Join();
+}
+
+
+bool ProfilerEventsProcessor::ProcessCodeEvent() {
   CodeEventsContainer record;
   if (events_buffer_.Dequeue(&record)) {
     switch (record.generic.type) {
@@ -90,17 +97,18 @@ bool ProfilerEventsProcessor::ProcessCodeEvent(unsigned* dequeue_order) {
 #undef PROFILER_TYPE_CASE
       default: return true;  // Skip record.
     }
-    *dequeue_order = record.generic.order;
+    last_processed_code_event_id_ = record.generic.order;
     return true;
   }
   return false;
 }
 
 
-bool ProfilerEventsProcessor::ProcessTicks(unsigned dequeue_order) {
+bool ProfilerEventsProcessor::ProcessTicks() {
   while (true) {
     if (!ticks_from_vm_buffer_.IsEmpty()
-        && ticks_from_vm_buffer_.Peek()->order == dequeue_order) {
+        && ticks_from_vm_buffer_.Peek()->order ==
+           last_processed_code_event_id_) {
       TickSampleEventRecord record;
       ticks_from_vm_buffer_.Dequeue(&record);
       generator_->RecordTickSample(record.sample);
@@ -115,38 +123,35 @@ bool ProfilerEventsProcessor::ProcessTicks(unsigned dequeue_order) {
     // will get far behind, a record may be modified right under its
     // feet.
     TickSampleEventRecord record = *rec;
-    if (record.order == dequeue_order) {
-      // A paranoid check to make sure that we don't get a memory overrun
-      // in case of frames_count having a wild value.
-      if (record.sample.frames_count < 0
-          || record.sample.frames_count > TickSample::kMaxFramesCount)
-        record.sample.frames_count = 0;
-      generator_->RecordTickSample(record.sample);
-      ticks_buffer_.FinishDequeue();
-    } else {
-      return true;
-    }
+    if (record.order != last_processed_code_event_id_) return true;
+
+    // A paranoid check to make sure that we don't get a memory overrun
+    // in case of frames_count having a wild value.
+    if (record.sample.frames_count < 0
+        || record.sample.frames_count > TickSample::kMaxFramesCount)
+      record.sample.frames_count = 0;
+    generator_->RecordTickSample(record.sample);
+    ticks_buffer_.FinishDequeue();
   }
 }
 
 
 void ProfilerEventsProcessor::Run() {
-  unsigned dequeue_order = 0;
-
   while (running_) {
     // Process ticks until we have any.
-    if (ProcessTicks(dequeue_order)) {
-      // All ticks of the current dequeue_order are processed,
+    if (ProcessTicks()) {
+      // All ticks of the current last_processed_code_event_id_ are processed,
       // proceed to the next code event.
-      ProcessCodeEvent(&dequeue_order);
+      ProcessCodeEvent();
     }
     YieldCPU();
   }
 
   // Process remaining tick events.
   ticks_buffer_.FlushResidualRecords();
-  // Perform processing until we have tick events, skip remaining code events.
-  while (ProcessTicks(dequeue_order) && ProcessCodeEvent(&dequeue_order)) { }
+  do {
+    ProcessTicks();
+  } while (ProcessCodeEvent());
 }
 
 
@@ -480,8 +485,7 @@ void CpuProfiler::StopProcessor() {
     need_to_stop_sampler_ = false;
   }
   is_profiling_ = false;
-  processor_->Stop();
-  processor_->Join();
+  processor_->StopSynchronously();
   delete processor_;
   delete generator_;
   processor_ = NULL;

src/cpu-profiler.h

@@ -155,7 +155,7 @@ class ProfilerEventsProcessor : public Thread {
 
   // Thread control.
   virtual void Run();
-  inline void Stop() { running_ = false; }
+  void StopSynchronously();
   INLINE(bool running()) { return running_; }
   void Enqueue(const CodeEventsContainer& event);
 
@@ -170,15 +170,16 @@ class ProfilerEventsProcessor : public Thread {
 
  private:
   // Called from events processing thread (Run() method.)
-  bool ProcessCodeEvent(unsigned* dequeue_order);
-  bool ProcessTicks(unsigned dequeue_order);
+  bool ProcessCodeEvent();
+  bool ProcessTicks();
 
   ProfileGenerator* generator_;
   bool running_;
   UnboundQueue<CodeEventsContainer> events_buffer_;
   SamplingCircularQueue ticks_buffer_;
   UnboundQueue<TickSampleEventRecord> ticks_from_vm_buffer_;
-  unsigned enqueue_order_;
+  unsigned last_code_event_id_;
+  unsigned last_processed_code_event_id_;
 };
 
 
@@ -248,6 +249,9 @@ class CpuProfiler {
     return &is_profiling_;
   }
 
+  ProfileGenerator* generator() const { return generator_; }
+  ProfilerEventsProcessor* processor() const { return processor_; }
+
  private:
   void StartProcessorIfNotStarted();
   void StopProcessorIfLastProfile(const char* title);

src/log.cc

@@ -1659,15 +1659,15 @@ void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
   Handle<String> func_name(shared->DebugName());
   if (shared->script()->IsScript()) {
     Handle<Script> script(Script::cast(shared->script()));
+    int line_num = GetScriptLineNumber(script, shared->start_position()) + 1;
     if (script->name()->IsString()) {
       Handle<String> script_name(String::cast(script->name()));
-      int line_num = GetScriptLineNumber(script, shared->start_position());
       if (line_num > 0) {
         PROFILE(isolate_,
                 CodeCreateEvent(
                     Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
                     *code, *shared, NULL,
-                    *script_name, line_num + 1));
+                    *script_name, line_num));
       } else {
         // Can't distinguish eval and script here, so always use Script.
         PROFILE(isolate_,
@@ -1679,7 +1679,8 @@ void Logger::LogExistingFunction(Handle<SharedFunctionInfo> shared,
       PROFILE(isolate_,
               CodeCreateEvent(
                   Logger::ToNativeByScript(Logger::LAZY_COMPILE_TAG, *script),
-                  *code, *shared, NULL, *func_name));
+                  *code, *shared, NULL,
+                  isolate_->heap()->empty_string(), line_num));
     }
   } else if (shared->IsApiFunction()) {
     // API function.

test/cctest/test-api.cc

@@ -12730,13 +12730,18 @@ static bool FunctionNameIs(const char* expected,
   const char* tail = event->name.str + kPreambleLen;
   size_t tail_len = event->name.len - kPreambleLen;
   size_t expected_len = strlen(expected);
-  if (tail_len == expected_len + 1) {
-    if (*tail == '*' || *tail == '~') {
-      --tail_len;
-      ++tail;
-    } else {
-      return false;
-    }
+  if (tail_len > 1 && (*tail == '*' || *tail == '~')) {
+    --tail_len;
+    ++tail;
+  }
+
+  // Check for tails like 'bar :1'.
+  if (tail_len > expected_len + 2 &&
+      tail[expected_len] == ' ' &&
+      tail[expected_len + 1] == ':' &&
+      tail[expected_len + 2] &&
+      !strncmp(tail, expected, expected_len)) {
+    return true;
   }
 
   if (tail_len != expected_len)

test/cctest/test-cpu-profiler.cc

@@ -52,7 +52,7 @@ TEST(StartStop) {
   ProfileGenerator generator(&profiles);
   ProfilerEventsProcessor processor(&generator);
   processor.Start();
-  processor.Stop();
+  processor.StopSynchronously();
   processor.Join();
 }
 
@@ -160,7 +160,7 @@ TEST(CodeEvents) {
   // Enqueue a tick event to enable code events processing.
   EnqueueTickSampleEvent(&processor, aaa_code->address());
 
-  processor.Stop();
+  processor.StopSynchronously();
   processor.Join();
 
   // Check the state of profile generator.
@@ -222,7 +222,7 @@ TEST(TickEvents) {
       frame2_code->instruction_end() - 1,
       frame1_code->instruction_end() - 1);
 
-  processor.Stop();
+  processor.StopSynchronously();
   processor.Join();
   CpuProfile* profile = profiles->StopProfiling("", 1);
   CHECK_NE(NULL, profile);
@@ -286,7 +286,7 @@ TEST(Issue1398) {
     sample->stack[i] = code->address();
   }
 
-  processor.Stop();
+  processor.StopSynchronously();
   processor.Join();
   CpuProfile* profile = profiles->StopProfiling("", 1);
   CHECK_NE(NULL, profile);

test/cctest/test-profile-generator.cc

@@ -826,3 +826,59 @@ TEST(ProfileNodeScriptId) {
 }
 
 
+
+
+static const char* line_number_test_source_existing_functions =
+"function foo_at_the_first_line() {\n"
+"}\n"
+"foo_at_the_first_line();\n"
+"function lazy_func_at_forth_line() {}\n";
+
+
+static const char* line_number_test_source_profile_time_functions =
+"// Empty first line\n"
+"function bar_at_the_second_line() {\n"
+"  foo_at_the_first_line();\n"
+"}\n"
+"bar_at_the_second_line();\n"
+"function lazy_func_at_6th_line() {}";
+
+int GetFunctionLineNumber(LocalContext* env, const char* name) {
+  CpuProfiler* profiler = i::Isolate::Current()->cpu_profiler();
+  CodeMap* code_map = profiler->generator()->code_map();
+  i::Handle<i::JSFunction> func = v8::Utils::OpenHandle(
+      *v8::Local<v8::Function>::Cast(
+          (*(*env))->Global()->Get(v8_str(name))));
+  CodeEntry* func_entry = code_map->FindEntry(func->code()->address());
+  if (!func_entry)
+    FATAL(name);
+  return func_entry->line_number();
+}
+
+
+TEST(LineNumber) {
+  i::FLAG_use_inlining = false;
+
+  CcTest::InitializeVM();
+  LocalContext env;
+  i::Isolate* isolate = i::Isolate::Current();
+  TestSetup test_setup;
+
+  i::HandleScope scope(isolate);
+
+  CompileRun(line_number_test_source_existing_functions);
+
+  CpuProfiler* profiler = isolate->cpu_profiler();
+  profiler->StartProfiling("LineNumber");
+
+  CompileRun(line_number_test_source_profile_time_functions);
+
+  profiler->processor()->StopSynchronously();
+
+  CHECK_EQ(1, GetFunctionLineNumber(&env, "foo_at_the_first_line"));
+  CHECK_EQ(0, GetFunctionLineNumber(&env, "lazy_func_at_forth_line"));
+  CHECK_EQ(2, GetFunctionLineNumber(&env, "bar_at_the_second_line"));
+  CHECK_EQ(0, GetFunctionLineNumber(&env, "lazy_func_at_6th_line"));
+
+  profiler->StopProfiling("LineNumber");
+}