Implement resource-saving ("lazy") mode of Profiler.
authormikhail.naganov@gmail.com <mikhail.naganov@gmail.com@ce2b1a6d-e550-0410-aec6-3dcde31c8c00>
Mon, 25 May 2009 08:25:36 +0000 (08:25 +0000)
committermikhail.naganov@gmail.com <mikhail.naganov@gmail.com@ce2b1a6d-e550-0410-aec6-3dcde31c8c00>
Mon, 25 May 2009 08:25:36 +0000 (08:25 +0000)
This is intended to be used with Chromium. When in resource-saving mode, profiler doesn't consume any resources (sampler and logging is off) until resumed. Then again, when profiler is paused, sampling and logging are turned off.

Tested under Linux and Windows. Also have done preliminary testing with Chromium.

Review URL: http://codereview.chromium.org/113762

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

src/flag-definitions.h
src/log.cc
src/log.h
src/platform.h
test/cctest/test-log.cc

index 5a4a3c86d1b4bc8f2416ee3c510e0b53d794c307..13e41e34fefaa3e87bec136daa759c1cdd93743d 100644 (file)
@@ -336,6 +336,9 @@ DEFINE_bool(prof, false,
             "Log statistical profiling information (implies --log-code).")
 DEFINE_bool(prof_auto, true,
             "Used with --prof, starts profiling automatically")
+DEFINE_bool(prof_lazy, false,
+            "Used with --prof, only does sampling and logging"
+            " when profiler is active (implies --noprof_auto).")
 DEFINE_bool(log_regexp, false, "Log regular expression execution.")
 DEFINE_bool(sliding_state_window, false,
             "Update sliding state window counters.")
index 3d3cd2d262b9604502283bf10eee1db34026e977..d5701f5c61ccd12d711623cb9c1fb1fcbbd659c3 100644 (file)
@@ -188,7 +188,7 @@ class Ticker: public Sampler {
 
   void SetProfiler(Profiler* profiler) {
     profiler_ = profiler;
-    if (!IsActive()) Start();
+    if (!FLAG_prof_lazy && !IsActive()) Start();
   }
 
   void ClearProfiler() {
@@ -267,6 +267,8 @@ void Profiler::Disengage() {
   // the thread to terminate.
   running_ = false;
   TickSample sample;
+  // Reset 'paused_' flag, otherwise semaphore may not be signalled.
+  resume();
   Insert(&sample);
   Join();
 
@@ -1096,14 +1098,30 @@ bool Logger::IsProfilerPaused() {
 
 void Logger::PauseProfiler() {
   profiler_->pause();
+  if (FLAG_prof_lazy) {
+    if (!FLAG_sliding_state_window) ticker_->Stop();
+    FLAG_log_code = false;
+    LOG(UncheckedStringEvent("profiler", "pause"));
+  }
 }
 
 
 void Logger::ResumeProfiler() {
+  if (FLAG_prof_lazy) {
+    LOG(UncheckedStringEvent("profiler", "resume"));
+    FLAG_log_code = true;
+    LogCompiledFunctions();
+    if (!FLAG_sliding_state_window) ticker_->Start();
+  }
   profiler_->resume();
 }
 
 
+bool Logger::IsProfilerSamplerActive() {
+  return ticker_->IsActive();
+}
+
+
 int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
   return Log::GetLogLines(from_pos, dest_buf, max_size);
 }
@@ -1190,9 +1208,15 @@ bool Logger::Setup() {
   // --prof implies --log-code.
   if (FLAG_prof) FLAG_log_code = true;
 
+  // --prof_lazy controls --log-code, implies --noprof_auto.
+  if (FLAG_prof_lazy) {
+    FLAG_log_code = false;
+    FLAG_prof_auto = false;
+  }
+
   bool open_log_file = FLAG_log || FLAG_log_runtime || FLAG_log_api
       || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
-      || FLAG_log_regexp || FLAG_log_state_changes;
+      || FLAG_log_regexp || FLAG_log_state_changes || FLAG_prof_lazy;
 
   // If we're logging anything, we need to open the log file.
   if (open_log_file) {
@@ -1277,8 +1301,10 @@ void Logger::TearDown() {
   }
 
   delete sliding_state_window_;
+  sliding_state_window_ = NULL;
 
   delete ticker_;
+  ticker_ = NULL;
 
   Log::Close();
 #endif
index 6e5fb5bb7aa0a6d77598d3c8a85483118f0b6522..fc0b9f9a308e1237d8e955e644de3013688b4023 100644 (file)
--- a/src/log.h
+++ b/src/log.h
@@ -230,6 +230,9 @@ class Logger {
   // Logs a StringEvent regardless of whether FLAG_log is true.
   static void UncheckedStringEvent(const char* name, const char* value);
 
+  // Returns whether profiler's sampler is active.
+  static bool IsProfilerSamplerActive();
+
   // The sampler used by the profiler and the sliding state window.
   static Ticker* ticker_;
 
@@ -255,6 +258,8 @@ class Logger {
   friend class Profiler;
   friend class SlidingStateWindow;
   friend class VMState;
+
+  friend class LoggerTestHelper;
 #else
   static bool is_enabled() { return false; }
 #endif
index e23abfc375de08380991ea1dee918b45298f3bf2..3c2318f64e7f1d61316e1f702c24074426ab6ad7 100644 (file)
@@ -518,10 +518,11 @@ class Sampler {
   // Is the sampler used for profiling.
   inline bool IsProfiling() { return profiling_; }
 
-  class PlatformData;
- protected:
+  // Whether the sampler is running (that is, consumes resources).
   inline bool IsActive() { return active_; }
 
+  class PlatformData;
+
  private:
   int interval_;
   bool profiling_;
index d65a995a0d9abee580ce544b433d74d2ef516401..3d5d5ae8903524486b0212998a0dc2e81ba1afb0 100644 (file)
@@ -10,6 +10,7 @@
 #include "cctest.h"
 
 using v8::internal::Address;
+using v8::internal::EmbeddedVector;
 using v8::internal::Logger;
 
 namespace i = v8::internal;
@@ -84,6 +85,11 @@ TEST(GetMessages) {
 }
 
 
+static int GetLogLines(int start_pos, i::Vector<char>* buffer) {
+  return Logger::GetLogLines(start_pos, buffer->start(), buffer->length());
+}
+
+
 TEST(BeyondWritePosition) {
   SetUp();
   Logger::StringEvent("aaa", "bbb");
@@ -91,14 +97,16 @@ TEST(BeyondWritePosition) {
   // See Logger::StringEvent.
   const char* all_lines = "aaa,\"bbb\"\ncccc,\"dddd\"\n";
   const int all_lines_len = strlen(all_lines);
-  CHECK_EQ(0, Logger::GetLogLines(all_lines_len, NULL, 1));
-  CHECK_EQ(0, Logger::GetLogLines(all_lines_len, NULL, 100));
-  CHECK_EQ(0, Logger::GetLogLines(all_lines_len + 1, NULL, 1));
-  CHECK_EQ(0, Logger::GetLogLines(all_lines_len + 1, NULL, 100));
-  CHECK_EQ(0, Logger::GetLogLines(all_lines_len + 100, NULL, 1));
-  CHECK_EQ(0, Logger::GetLogLines(all_lines_len + 100, NULL, 100));
-  CHECK_EQ(0, Logger::GetLogLines(10 * 1024 * 1024, NULL, 1));
-  CHECK_EQ(0, Logger::GetLogLines(10 * 1024 * 1024, NULL, 100));
+  EmbeddedVector<char, 100> buffer;
+  const int beyond_write_pos = all_lines_len;
+  CHECK_EQ(0, Logger::GetLogLines(beyond_write_pos, buffer.start(), 1));
+  CHECK_EQ(0, GetLogLines(beyond_write_pos, &buffer));
+  CHECK_EQ(0, Logger::GetLogLines(beyond_write_pos + 1, buffer.start(), 1));
+  CHECK_EQ(0, GetLogLines(beyond_write_pos + 1, &buffer));
+  CHECK_EQ(0, Logger::GetLogLines(beyond_write_pos + 100, buffer.start(), 1));
+  CHECK_EQ(0, GetLogLines(beyond_write_pos + 100, &buffer));
+  CHECK_EQ(0, Logger::GetLogLines(10 * 1024 * 1024, buffer.start(), 1));
+  CHECK_EQ(0, GetLogLines(10 * 1024 * 1024, &buffer));
   TearDown();
 }
 
@@ -116,6 +124,121 @@ TEST(MemoryLoggingTurnedOff) {
 }
 
 
+static void CompileAndRunScript(const char *src) {
+  v8::Script::Compile(v8::String::New(src))->Run();
+}
+
+
+namespace v8 {
+namespace internal {
+
+class LoggerTestHelper : public AllStatic {
+ public:
+  static bool IsSamplerActive() { return Logger::IsProfilerSamplerActive(); }
+};
+
+}  // namespace v8::internal
+}  // namespace v8
+
+using v8::internal::LoggerTestHelper;
+
+
+static int CheckThatProfilerWorks(int log_pos) {
+  Logger::ResumeProfiler();
+  CHECK(LoggerTestHelper::IsSamplerActive());
+
+  // Verify that the current map of compiled functions has been logged.
+  EmbeddedVector<char, 102400> buffer;
+  int map_log_size = GetLogLines(log_pos, &buffer);
+  printf("map_log_size: %d\n", map_log_size);
+  CHECK_GT(map_log_size, 0);
+  CHECK_GT(buffer.length(), map_log_size);
+  log_pos += map_log_size;
+  // Check buffer contents.
+  buffer[map_log_size] = '\0';
+  const char* code_creation = "\ncode-creation,";  // eq. to /^code-creation,/
+  CHECK_NE(NULL, strstr(buffer.start(), code_creation));
+
+  // Force compiler to generate new code by parametrizing source.
+  EmbeddedVector<char, 100> script_src;
+  i::OS::SNPrintF(script_src,
+                  "for (var i = 0; i < 1000; ++i) { "
+                  "(function(x) { return %d * x; })(i); }",
+                  log_pos);
+  // Run code for 100 msecs to get some ticks.
+  const int64_t started_us = i::OS::Ticks();
+  while (i::OS::Ticks() - started_us < 100 * 1000) {
+    CompileAndRunScript(script_src.start());
+  }
+
+  Logger::PauseProfiler();
+  CHECK(!LoggerTestHelper::IsSamplerActive());
+
+  // Now we must have compiler and tick records.
+  int log_size = GetLogLines(log_pos, &buffer);
+  printf("log_size: %d\n", log_size);
+  CHECK_GT(log_size, 0);
+  CHECK_GT(buffer.length(), log_size);
+  log_pos += log_size;
+  // Check buffer contents.
+  buffer[log_size] = '\0';
+  const char* tick = "\ntick,";
+  CHECK_NE(NULL, strstr(buffer.start(), code_creation));
+  CHECK_NE(NULL, strstr(buffer.start(), tick));
+
+  return log_pos;
+}
+
+
+TEST(ProfLazyMode) {
+  const bool saved_prof_lazy = i::FLAG_prof_lazy;
+  const bool saved_prof = i::FLAG_prof;
+  const bool saved_prof_auto = i::FLAG_prof_auto;
+  i::FLAG_prof = true;
+  i::FLAG_prof_lazy = true;
+  i::FLAG_prof_auto = false;
+  i::FLAG_logfile = "*";
+
+  // If tests are being run manually, V8 will be already initialized
+  // by the test below.
+  const bool need_to_set_up_logger = i::V8::HasBeenSetup();
+  v8::HandleScope scope;
+  v8::Handle<v8::Context> env = v8::Context::New();
+  if (need_to_set_up_logger) Logger::Setup();
+  env->Enter();
+
+  // No sampling should happen prior to resuming profiler.
+  CHECK(!LoggerTestHelper::IsSamplerActive());
+
+  // Read initial logged data (static libs map).
+  EmbeddedVector<char, 102400> buffer;
+  int log_pos = GetLogLines(0, &buffer);
+  CHECK_GT(log_pos, 0);
+  CHECK_GT(buffer.length(), log_pos);
+
+  CompileAndRunScript("var a = (function(x) { return x + 1; })(10);");
+
+  // Nothing must be logged while profiling is suspended.
+  CHECK_EQ(0, GetLogLines(log_pos, &buffer));
+
+  log_pos = CheckThatProfilerWorks(log_pos);
+
+  CompileAndRunScript("var a = (function(x) { return x + 1; })(10);");
+
+  // No new data beyond last retrieved position.
+  CHECK_EQ(0, GetLogLines(log_pos, &buffer));
+
+  // Check that profiling can be resumed again.
+  CheckThatProfilerWorks(log_pos);
+
+  env->Exit();
+  Logger::TearDown();
+  i::FLAG_prof_lazy = saved_prof_lazy;
+  i::FLAG_prof = saved_prof;
+  i::FLAG_prof_auto = saved_prof_auto;
+}
+
+
 static inline bool IsStringEqualTo(const char* r, const char* s) {
   return strncmp(r, s, strlen(r)) == 0;
 }
@@ -487,6 +610,15 @@ static bool AreEntitiesEqual(CodeEntityInfo ref_e, CodeEntityInfo new_e) {
 // Test that logging of code create / move / delete events
 // is equivalent to traversal of a resulting heap.
 TEST(EquivalenceOfLoggingAndTraversal) {
+  // This test needs to be run on a "clean" V8 to ensure that snapshot log
+  // is loaded. This is always true when running using tools/test.py because
+  // it launches a new cctest instance for every test. To be sure that launching
+  // cctest manually also works, please be sure that no tests below
+  // are using V8.
+  //
+  // P.S. No, V8 can't be re-initialized after disposal, see include/v8.h.
+  CHECK(!i::V8::HasBeenSetup());
+
   i::FLAG_logfile = "*";
   i::FLAG_log = true;
   i::FLAG_log_code = true;
@@ -499,20 +631,19 @@ TEST(EquivalenceOfLoggingAndTraversal) {
 
   v8::HandleScope scope;
   v8::Handle<v8::Value> global_object = v8::Handle<v8::Value>();
-  v8::Persistent<v8::Context> env = v8::Context::New(
+  v8::Handle<v8::Context> env = v8::Context::New(
       0, v8::Handle<v8::ObjectTemplate>(), global_object);
   env->Enter();
 
   // Compile and run a function that creates other functions.
-  v8::Local<v8::Script> script = v8::Script::Compile(v8::String::New(
+  CompileAndRunScript(
       "(function f(obj) {\n"
       "  obj.test =\n"
       "    (function a(j) { return function b() { return j; } })(100);\n"
-      "})(this);"));
-  script->Run();
+      "})(this);");
   i::Heap::CollectAllGarbage();
 
-  i::EmbeddedVector<char, 204800> buffer;
+  EmbeddedVector<char, 204800> buffer;
   int log_size;
   ParseLogResult ref_result;
 
@@ -521,7 +652,7 @@ TEST(EquivalenceOfLoggingAndTraversal) {
     // Make sure that no GCs occur prior to LogCompiledFunctions call.
     i::AssertNoAllocation no_alloc;
 
-    log_size = Logger::GetLogLines(0, buffer.start(), buffer.length());
+    log_size = GetLogLines(0, &buffer);
     CHECK_GT(log_size, 0);
     CHECK_GT(buffer.length(), log_size);
 
@@ -566,7 +697,7 @@ TEST(EquivalenceOfLoggingAndTraversal) {
   CHECK(results_equal);
 
   env->Exit();
-  v8::V8::Dispose();
+  Logger::TearDown();
   i::FLAG_always_compact = saved_always_compact;
 }