Extend CPU profiler with mapping ticks to source lines

test/cctest/test-cpu-profiler.cc

 // Copyright 2010 the V8 project authors. All rights reserved.
 // Redistribution and use in source and binary forms, with or without
 // modification, are permitted provided that the following conditions are
 // met:
 //
 //     * Redistributions of source code must retain the above copyright
 //       notice, this list of conditions and the following disclaimer.
 //     * Redistributions in binary form must reproduce the above
 //       copyright notice, this list of conditions and the following
 //       disclaimer in the documentation and/or other materials provided
@@ skipping 1046 matching lines @@
   CheckChildrenNames(root, names);
 
   const v8::CpuProfileNode* startNode =
       GetChild(env->GetIsolate(), root, "start");
   GetChild(env->GetIsolate(), startNode, "foo");
 
   profile->Delete();
 }
 
 
+// This tests checks distribution of the samples through the source lines.
+TEST(TickLines) {
+  CcTest::InitializeVM();
+  LocalContext env;
+  i::Isolate* isolate = CcTest::i_isolate();
+  i::Factory* factory = isolate->factory();
+  i::HandleScope scope(isolate);
+
+  i::EmbeddedVector<char, 512> script;
+
+  const char* func_name = "func";
+  i::SNPrintF(script,
+      "function %s() {\n"
+      "  for (var i = 0; i < 10; ++i) {\n"
+      "    var n = 0;\n"
+      "    var m = 100*100;\n"
+      "    while (m > 1) {\n"
+      "      m--;\n"
+      "      n += m * m * m;\n"
+      "    }\n"
+      "  }\n"
+      "}\n"
+      "%s();\n", func_name, func_name);
+
+  CompileRun(script.start());
+
+  i::Handle<i::JSFunction> func = v8::Utils::OpenHandle(
+      *v8::Local<v8::Function>::Cast(
+      (*env)->Global()->Get(v8_str(func_name))));
+  CHECK_NE(NULL, func->shared());
+  CHECK_NE(NULL, func->code());
+  i::Address code_address = func->code()->address();
+  CHECK_NE(NULL, code_address);
+
+  CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate->heap());
+  profiles->StartProfiling("", false);
+  ProfileGenerator generator(profiles);
+  SmartPointer<ProfilerEventsProcessor> processor(new ProfilerEventsProcessor(
+      &generator, NULL, v8::base::TimeDelta::FromMicroseconds(100)));
+  processor->Start();
+  CpuProfiler profiler(isolate, profiles, &generator, processor.get());
+
+  // Enqueue code creation events.
+  i::Handle<i::String> str = factory->NewStringFromAsciiChecked(func_name);
+  int line = 1;
+  int column = 1;
+  profiler.CodeCreateEvent(i::Logger::FUNCTION_TAG,
+                           func->code(),
+                           func->shared(),
+                           NULL,
+                           *str,
+                           line,
+                           column);
+
+  // Enqueue a tick event to enable code events processing.
+  EnqueueTickSampleEvent(processor.get(), code_address);
+
+  processor->StopSynchronously();
+
+  CpuProfile* profile = profiles->StopProfiling("");
+  CHECK_NE(NULL, profile);
+
+  // Check the state of profile generator.
+  CodeEntry* func_entry = generator.code_map()->FindEntry(code_address);
+  CHECK_NE(NULL, func_entry);
+  CHECK_EQ(func_name, func_entry->name());
+  const i::JITLineInfoTable* line_info = func_entry->line_info();
+  CHECK_NE(NULL, line_info);

[alph, 2014/08/15 12:10:47]

I've got the test failing at this line for ia32 target because there's no
POSITION reloc infos for the code.

[Denis Pravdin, 2014/08/15 20:57:55]

Well, I found out what causes this test failure but I don’t understand a reason
of this behavior and I am not sure what the best way to fix it is:

In patch set 3, I iterate the heap to get a function object
(GetFunctionInfoFromHeap). The test passes all the time.

In patch set 4, I replace it with the lines below as you suggested (see a code
snippet below) and test failed.

i::Handle<i::JSFunction> func = v8::Utils::OpenHandle(
      *v8::Local<v8::Function>::Cast(
      (*env)->Global()->Get(v8_str(func_name))));

Looking into it, I decided to check what the difference between these two ways:
1. I added heap iteration back in addition to v8::Utils::OpenHandle
2. Then checked that reloc info for both objects of Code type include positions.

The test looks like:

  CompileRun(script.start());

  i::SharedFunctionInfo* shared = GetFunctionInfoFromHeap(isolate, func_name);
  int positions_ = 0;
  for (i::RelocIterator it(shared->code()); !it.done(); it.next()) {
    i::RelocInfo::Mode mode = it.rinfo()->rmode();
    if (i::RelocInfo::IsPosition(mode)) positions_++;
  }
  CHECK_GT(positions_, 0);  // THIS CHECK PASSED

  i::Handle<i::JSFunction> func = v8::Utils::OpenHandle(
      *v8::Local<v8::Function>::Cast(
      (*env)->Global()->Get(v8_str(func_name))));
  CHECK_NE(NULL, func->shared());
  CHECK_NE(NULL, func->code());
  int positions = 0;
  for (i::RelocIterator it(func->code()); !it.done(); it.next()) {
    i::RelocInfo::Mode mode = it.rinfo()->rmode();
    if (i::RelocInfo::IsPosition(mode)) positions++;
  }
  CHECK_GT(positions, 0);  // THIS CHECK DOES NOT PASS.

Do you have idea why for the first case I have POSITION reloc info, and never
have it for the second case?

It seems it's Linux specific issue. At least I don't see it on Windows.

[alph, 2014/08/19 14:23:35]

Could you please check the 'shared' and 'code' objects you get using these two
approaches are the same.

I think there are several versions on the code for the function, e.g. optimized
and non-optimized. One of them is missing relocations.

[Denis Pravdin, 2014/09/01 09:35:13]

Yes, you're right.
I debugged the test and found out:
1. There are two ways to get 'code' using JSFunction object (jsf is type of
JSFunction):
 (a) jsf->code()
 (b) jsf->shared()->code()
2. When optimized code is compiled that both JSFunction::ReplaceCode(Code*
code)and SharedFunctionInfo::ReplaceCode(Code* value) function are called. As
the result, the 'code' objects returned by (a) and (b) contains relocations.
3. Then, optimized version of code is generated and only
SFunction::ReplaceCode(Code* code) is called.
Note that I use func->code() instead of func->shared()->code():
 
   for (i::RelocIterator it(func->code()); !it.done(); it.next()) {
     i::RelocInfo::Mode mode = it.rinfo()->rmode();
     if (i::RelocInfo::IsPosition(mode)) positions++;
   }
 
 That's why my previous approach (GetFunctionInfoFromHeap) always works but new
one (OpenHandle) causes a test failure.
 
 Possible solutions:
 
 1) For testing purpose, always use unoptimized version of code (e.g.
 func->shared()->code())
    + allows to make the test more deterministic
    - optimized code is not tested
 
 2) Set FLAG_hydrogen_track_positions flag as true by default before CompileRun
for this test.
    I checked on Windows and see that number of positions is increased from 9 to
19 for 'func' function from the test.
 
 I think that the flag should be turned on always to achieve better mapping to
source lines for generated optimized code. We can add a runtime switch to turn
it on before profiling starts. It's a subject for a separate patch.

Can you suggest other ideas? If not that which of the above is the best?

+  CHECK_EQ(false, line_info->Empty());
+
+  // Check the hit source lines using V8 Public APIs.
+  const i::ProfileTree* tree = profile->top_down();
+  ProfileNode* root = tree->root();
+  CHECK_NE(NULL, root);
+  ProfileNode* func_node = root->FindChild(func_entry);
+  CHECK_NE(NULL, func_node);
+
+  // Add 10 faked ticks to source line #5.
+  int hit_line = 5;
+  int hit_count = 10;
+  for (int i = 0; i < hit_count; i++)
+    func_node->IncrementLineTicks(hit_line);
+
+  unsigned int line_count = func_node->GetHitLineCount();
+  CHECK_EQ(2, line_count);  // Expect two hit source lines - #1 and #5.
+  ScopedVector<v8::CpuProfileNode::LineTick> entries(line_count);
+  CHECK_EQ(true, func_node->GetLineTicks(&entries[0], line_count));
+  int value = 0;
+  for (int i = 0; i < entries.length(); i++)
+    if (entries[i].line == hit_line) {
+      value = entries[i].hit_count;
+      break;
+    }
+  CHECK_EQ(hit_count, value);
+}
+
+
 static const char* call_function_test_source = "function bar(iterations) {\n"
 "}\n"
 "function start(duration) {\n"
 "  var start = Date.now();\n"
 "  while (Date.now() - start < duration) {\n"
 "    try {\n"
 "      bar.call(this, 10 * 1000);\n"
 "    } catch(e) {}\n"
 "  }\n"
 "}";
@@ skipping 597 matching lines @@
   inner_profile = NULL;
   CHECK_EQ(0, iprofiler->GetProfilesCount());
 
   v8::CpuProfile* outer_profile = profiler->StopProfiling(outer);
   CHECK(outer_profile);
   CHECK_EQ(1, iprofiler->GetProfilesCount());
   outer_profile->Delete();
   outer_profile = NULL;
   CHECK_EQ(0, iprofiler->GetProfilesCount());
 }