Add parallel recompilation time to histogram and plot execution pause times.

BUG=

Review URL: https://chromiumcodereview.appspot.com/11412125

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

src/api.cc

@@ -1681,6 +1681,8 @@ Local<Value> Script::Run() {
   ON_BAILOUT(isolate, "v8::Script::Run()", return Local<Value>());
   LOG_API(isolate, "Script::Run");
   ENTER_V8(isolate);
+  i::Logger::TimerEventScope timer_scope(
+      isolate->logger(), i::Logger::TimerEventScope::v8_execute);
   i::Object* raw_result = NULL;
   {
     i::HandleScope scope(isolate);

src/compiler.cc

@@ -396,7 +396,10 @@ static bool GenerateCode(CompilationInfo* info) {
   bool is_optimizing = V8::UseCrankshaft() &&
                        !info->IsCompilingForDebugging() &&
                        info->IsOptimizing();
+  Logger* logger = info->isolate()->logger();
   if (is_optimizing) {
+    Logger::TimerEventScope timer(
+        logger, Logger::TimerEventScope::v8_recompile_synchronous);
     return MakeCrankshaftCode(info);
   } else {
     if (info->IsOptimizing()) {
@@ -404,6 +407,8 @@ static bool GenerateCode(CompilationInfo* info) {
       // BASE or NONOPT.
       info->DisableOptimization();
     }
+    Logger::TimerEventScope timer(
+        logger, Logger::TimerEventScope::v8_compile_full_code);
     return FullCodeGenerator::MakeCode(info);
   }
 }
@@ -852,6 +857,11 @@ void Compiler::RecompileParallel(Handle<JSFunction> closure) {
   ASSERT(closure->IsMarkedForParallelRecompilation());
 
   Isolate* isolate = closure->GetIsolate();
+  // Here we prepare compile data for the parallel recompilation thread, but
+  // this still happens synchronously and interrupts execution.
+  Logger::TimerEventScope timer(
+      isolate->logger(), Logger::TimerEventScope::v8_recompile_synchronous);
+
   if (!isolate->optimizing_compiler_thread()->IsQueueAvailable()) {
     if (FLAG_trace_parallel_recompilation) {
       PrintF("  ** Compilation queue, will retry opting on next run.\n");
@@ -860,7 +870,7 @@ void Compiler::RecompileParallel(Handle<JSFunction> closure) {
   }
 
   SmartPointer<CompilationInfo> info(new CompilationInfoWithZone(closure));
-  VMState state(isolate, PARALLEL_COMPILER_PROLOGUE);
+  VMState state(isolate, PARALLEL_COMPILER);
   PostponeInterruptsScope postpone(isolate);
 
   Handle<SharedFunctionInfo> shared = info->shared_info();
@@ -908,6 +918,10 @@ void Compiler::RecompileParallel(Handle<JSFunction> closure) {
 
 void Compiler::InstallOptimizedCode(OptimizingCompiler* optimizing_compiler) {
   SmartPointer<CompilationInfo> info(optimizing_compiler->info());
+  Isolate* isolate = info->isolate();
+  VMState state(isolate, PARALLEL_COMPILER);
+  Logger::TimerEventScope timer(
+      isolate->logger(), Logger::TimerEventScope::v8_recompile_synchronous);
   // If crankshaft succeeded, install the optimized code else install
   // the unoptimized code.
   OptimizingCompiler::Status status = optimizing_compiler->last_status();

src/counters.cc

@@ -77,7 +77,7 @@ void* Histogram::CreateHistogram() const {
 
 // Start the timer.
 void HistogramTimer::Start() {
-  if (histogram_.Enabled()) {
+  if (histogram_.Enabled() || FLAG_log_timer_events) {
     stop_time_ = 0;
     start_time_ = OS::Ticks();
   }
@@ -87,11 +87,15 @@ void HistogramTimer::Start() {
 void HistogramTimer::Stop() {
   if (histogram_.Enabled()) {
     stop_time_ = OS::Ticks();
-
     // Compute the delta between start and stop, in milliseconds.
     int milliseconds = static_cast<int>(stop_time_ - start_time_) / 1000;
     histogram_.AddSample(milliseconds);
   }
+  if (FLAG_log_timer_events) {
+    stop_time_ = OS::Ticks();
+    Isolate::Current()->logger()->TimerEvent(
+        histogram_.name_, start_time_, stop_time_);
+  }
 }
 
 } }  // namespace v8::internal

src/flag-definitions.h

@@ -667,6 +667,7 @@ DEFINE_string(logfile, "v8.log", "Specify the name of the log file.")
 DEFINE_bool(ll_prof, false, "Enable low-level linux profiler.")
 DEFINE_string(gc_fake_mmap, "/tmp/__v8_gc__",
               "Specify the name of the file for fake gc mmap used in ll_prof")
+DEFINE_bool(log_timer_events, false, "Log histogram timer events.")
 
 //
 // Disassembler only flags

src/heap.cc

@@ -644,13 +644,13 @@ bool Heap::CollectGarbage(AllocationSpace space,
     // Tell the tracer which collector we've selected.
     tracer.set_collector(collector);
 
-    HistogramTimer* rate = (collector == SCAVENGER)
-        ? isolate_->counters()->gc_scavenger()
-        : isolate_->counters()->gc_compactor();
-    rate->Start();
-    next_gc_likely_to_collect_more =
-        PerformGarbageCollection(collector, &tracer);
-    rate->Stop();
+    {
+      HistogramTimerScope histogram_timer_scope(
+          (collector == SCAVENGER) ? isolate_->counters()->gc_scavenger()
+                                   : isolate_->counters()->gc_compactor());
+      next_gc_likely_to_collect_more =
+          PerformGarbageCollection(collector, &tracer);
+    }
 
     ASSERT(collector == SCAVENGER || incremental_marking()->IsStopped());
 

src/log-utils.cc

@@ -80,7 +80,8 @@ void Log::Initialize() {
 
   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_ll_prof;
+      || FLAG_log_regexp || FLAG_log_state_changes || FLAG_ll_prof
+      || FLAG_log_timer_events;
 
   // If we're logging anything, we need to open the log file.
   if (open_log_file) {

src/log.cc

@@ -531,7 +531,8 @@ Logger::Logger()
     prev_sp_(NULL),
     prev_function_(NULL),
     prev_to_(NULL),
-    prev_code_(NULL) {
+    prev_code_(NULL),
+    epoch_(0) {
 }
 
 
@@ -704,6 +705,25 @@ void Logger::SharedLibraryEvent(const wchar_t* library_path,
 }
 
 
+void Logger::TimerEvent(const char* name, int64_t start, int64_t end) {
+  ASSERT(FLAG_log_timer_events);
+  LogMessageBuilder msg(this);
+  int since_epoch = static_cast<int>(start - epoch_);
+  int pause_time = static_cast<int>(end - start);
+  msg.Append("timer-event,\"%s\",%ld,%ld\n", name, since_epoch, pause_time);
+  msg.WriteToLogFile();
+}
+
+
+const char* Logger::TimerEventScope::v8_recompile_synchronous =
+    "V8.RecompileSynchronous";
+const char* Logger::TimerEventScope::v8_recompile_parallel =
+    "V8.RecompileParallel";
+const char* Logger::TimerEventScope::v8_compile_full_code =
+    "V8.CompileFullCode";
+const char* Logger::TimerEventScope::v8_execute = "V8.Execute";
+
+
 void Logger::LogRegExpSource(Handle<JSRegExp> regexp) {
   // Prints "/" + re.source + "/" +
   //      (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"")
@@ -1727,7 +1747,8 @@ bool Logger::SetUp() {
 
   bool start_logging = 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_ll_prof;
+    || FLAG_log_regexp || FLAG_log_state_changes || FLAG_ll_prof
+    || FLAG_log_timer_events;
 
   if (start_logging) {
     logging_nesting_ = 1;
@@ -1745,6 +1766,8 @@ bool Logger::SetUp() {
     }
   }
 
+  if (FLAG_log_timer_events) epoch_ = OS::Ticks();
+
   return true;
 }
 

src/log.h

@@ -274,6 +274,31 @@ class Logger {
   void SharedLibraryEvent(const wchar_t* library_path,
                           uintptr_t start,
                           uintptr_t end);
+  void TimerEvent(const char* name, int64_t start, int64_t end);
+
+  class TimerEventScope {
+   public:
+    TimerEventScope(Logger* logger, const char* name)
+        : logger_(logger), name_(name), start_(0) {
+      if (FLAG_log_timer_events) start_ = OS::Ticks();
+    }
+
+    ~TimerEventScope() {
+      if (FLAG_log_timer_events) {
+        logger_->TimerEvent(name_, start_, OS::Ticks());
+      }
+    }
+
+    static const char* v8_recompile_synchronous;
+    static const char* v8_recompile_parallel;
+    static const char* v8_compile_full_code;
+    static const char* v8_execute;
+
+   private:
+    Logger* logger_;
+    const char* name_;
+    int64_t start_;
+  };
 
   // ==== Events logged by --log-regexp ====
   // Regexp compilation and execution events.
@@ -449,6 +474,8 @@ class Logger {
   //  Logger::FunctionCreateEvent(...)
   Address prev_code_;
 
+  int64_t epoch_;
+
   friend class CpuProfiler;
 };
 

src/optimizing-compiler-thread.cc

@@ -48,6 +48,8 @@ void OptimizingCompilerThread::Run() {
 
   while (true) {
     input_queue_semaphore_->Wait();
+    Logger::TimerEventScope timer(
+        isolate_->logger(), Logger::TimerEventScope::v8_recompile_parallel);
     if (Acquire_Load(&stop_thread_)) {
       stop_semaphore_->Signal();
       if (FLAG_trace_parallel_recompilation) {

src/profile-generator-inl.h

@@ -84,7 +84,7 @@ CodeEntry* ProfileGenerator::EntryForVMState(StateTag tag) {
       return gc_entry_;
     case JS:
     case COMPILER:
-    case PARALLEL_COMPILER_PROLOGUE:
+    case PARALLEL_COMPILER:
     // DOM events handlers are reported as OTHER / EXTERNAL entries.
     // To avoid confusing people, let's put all these entries into
     // one bucket.

src/v8-counters.h

@@ -50,7 +50,6 @@ namespace internal {
   HT(compile_eval, V8.CompileEval)                                    \
   HT(compile_lazy, V8.CompileLazy)
 
-
 #define HISTOGRAM_PERCENTAGE_LIST(HP)                                 \
   HP(external_fragmentation_total,                                    \
      V8.MemoryExternalFragmentationTotal)                             \

src/v8globals.h

@@ -355,7 +355,7 @@ struct AccessorDescriptor {
   V(JS)                                         \
   V(GC)                                         \
   V(COMPILER)                                   \
-  V(PARALLEL_COMPILER_PROLOGUE)                 \
+  V(PARALLEL_COMPILER)                          \
   V(OTHER)                                      \
   V(EXTERNAL)
 

src/vm-state-inl.h

@@ -47,8 +47,8 @@ inline const char* StateToString(StateTag state) {
       return "GC";
     case COMPILER:
       return "COMPILER";
-    case PARALLEL_COMPILER_PROLOGUE:
-      return "PARALLEL_COMPILER_PROLOGUE";
+    case PARALLEL_COMPILER:
+      return "PARALLEL_COMPILER";
     case OTHER:
       return "OTHER";
     case EXTERNAL:

tools/plot-timer-events

+#!/bin/sh
+
+# find the name of the log file to process, it must not start with a dash.
+log_file="v8.log"
+for arg in "$@"
+do
+  if ! expr "X${arg}" : "^X-" > /dev/null; then
+    log_file=${arg}
+  fi
+done
+
+tools_path=`cd $(dirname "$0");pwd`
+if [ ! "$D8_PATH" ]; then
+  d8_public=`which d8`
+  if [ -x "$d8_public" ]; then D8_PATH=$(dirname "$d8_public"); fi
+fi
+[ -n "$D8_PATH" ] || D8_PATH=$tools_path/..
+d8_exec=$D8_PATH/d8
+
+if [ ! -x "$d8_exec" ]; then
+  D8_PATH=`pwd`/out/native
+  d8_exec=$D8_PATH/d8
+fi
+
+if [ ! -x "$d8_exec" ]; then
+  d8_exec=`grep -m 1 -o '".*/d8"' $log_file | sed 's/"//g'`
+fi
+
+if [ ! -x "$d8_exec" ]; then
+  echo "d8 shell not found in $D8_PATH"
+  echo "To build, execute 'make native' from the V8 directory"
+  exit 1
+fi
+
+# nm spits out 'no symbols found' messages to stderr.
+cat $log_file | $d8_exec $tools_path/csvparser.js \
+    $tools_path/logreader.js $tools_path/plot-timer-events.js \
+    2>/dev/null | gnuplot > timer-events.png
+

tools/tickprocessor.js

@@ -231,7 +231,7 @@ TickProcessor.VmStates = {
   JS: 0,
   GC: 1,
   COMPILER: 2,
-  PARALLEL_COMPILER_PROLOGUE: 3,
+  PARALLEL_COMPILER: 3,
   OTHER: 4,
   EXTERNAL: 5
 };