[profiler] Web UI: add summary of opts/deopts.

src/log.cc

 // Copyright 2011 the V8 project authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "src/log.h"
 
 #include <cstdarg>
 #include <memory>
 #include <sstream>
 
@@ skipping 825 matching lines @@
                                 uintptr_t start, uintptr_t end,
                                 intptr_t aslr_slide) {
   if (!log_->IsEnabled() || !FLAG_prof_cpp) return;
   Log::MessageBuilder msg(log_);
   msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR
              ",%" V8PRIdPTR,
              library_path.c_str(), start, end, aslr_slide);
   msg.WriteToLogFile();
 }
 
-
-void Logger::CodeDeoptEvent(Code* code, Address pc, int fp_to_sp_delta) {
-  if (!log_->IsEnabled() || !FLAG_log_internal_timer_events) return;
+void Logger::CodeDeoptEvent(DeoptKind kind, Code* code, Address pc,
+                            int fp_to_sp_delta) {
+  if (!log_->IsEnabled()) return;
+  Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(code, pc);
   Log::MessageBuilder msg(log_);
   int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
-  msg.Append("code-deopt,%d,%d", since_epoch, code->CodeSize());
+  msg.Append("code-deopt,%d,%d,", since_epoch, code->CodeSize());
+  msg.AppendAddress(code->address());
+
+  // Deoptimization position.
+  std::ostringstream deopt_location;
+  int inlining_id = -1;
+  int script_offset = -1;
+  if (info.position.IsKnown()) {
+    info.position.Print(deopt_location, code);
+    inlining_id = info.position.InliningId();
+    script_offset = info.position.ScriptOffset();
+  } else {
+    deopt_location << "<unknown>";
+  }
+  msg.Append(",%d,%d,", inlining_id, script_offset);
+  switch (kind) {
+    case kLazy:
+      msg.Append("\"lazy\",");
+      break;
+    case kSoft:
+      msg.Append("\"soft\",");
+      break;
+    case kEager:
+      msg.Append("\"eager\",");
+      break;
+  }
+  msg.AppendDoubleQuotedString(deopt_location.str().c_str());
+  msg.Append(",");
+  msg.AppendDoubleQuotedString(DeoptimizeReasonToString(info.deopt_reason));
   msg.WriteToLogFile();
 }
 
 
 void Logger::CurrentTimeEvent() {
   if (!log_->IsEnabled()) return;
   DCHECK(FLAG_log_timer_events || FLAG_prof_cpp);
   Log::MessageBuilder msg(log_);
   int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds());
   msg.Append("current-time,%d", since_epoch);
@@ skipping 103 matching lines @@
 }
 
 
 void Logger::CallbackEventInternal(const char* prefix, Name* name,
                                    Address entry_point) {
   if (!FLAG_log_code || !log_->IsEnabled()) return;
   Log::MessageBuilder msg(log_);
   msg.Append("%s,%s,-2,",
              kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT],
              kLogEventsNames[CodeEventListener::CALLBACK_TAG]);
+  if (timer_.IsStarted()) {
+    msg.Append("%d,", static_cast<int>(timer_.Elapsed().InMicroseconds()));
+  } else {
+    msg.Append("-1,");
+  }
   msg.AppendAddress(entry_point);
   if (name->IsString()) {
     std::unique_ptr<char[]> str =
         String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
     msg.Append(",1,\"%s%s\"", prefix, str.get());
   } else {
     Symbol* symbol = Symbol::cast(name);
     if (symbol->name()->IsUndefined(symbol->GetIsolate())) {
       msg.Append(",1,symbol(hash %x)", symbol->Hash());
     } else {
@@ skipping 15 matching lines @@
 
 void Logger::GetterCallbackEvent(Name* name, Address entry_point) {
   CallbackEventInternal("get ", name, entry_point);
 }
 
 
 void Logger::SetterCallbackEvent(Name* name, Address entry_point) {
   CallbackEventInternal("set ", name, entry_point);
 }
 
-static void AppendCodeCreateHeader(Log::MessageBuilder* msg,
-                                   CodeEventListener::LogEventsAndTags tag,
-                                   AbstractCode* code) {
+namespace {
+
+void AppendCodeCreateHeader(Log::MessageBuilder* msg,
+                            CodeEventListener::LogEventsAndTags tag,
+                            AbstractCode* code, base::ElapsedTimer* timer) {
   DCHECK(msg);
   msg->Append("%s,%s,%d,",
               kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT],
               kLogEventsNames[tag], code->kind());
+  int timestamp = timer->IsStarted()

[Leszek Swirski, 2017/03/21 14:28:39]

nit: inconsistent use of if blocks vs. ternary operator -- either is fine with
me

+                      ? static_cast<int>(timer->Elapsed().InMicroseconds())
+                      : -1;
+  msg->Append("%d,", timestamp);
   msg->AppendAddress(code->address());
   msg->Append(",%d,", code->ExecutableSize());
 }
 
+}  // namespace
+
 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                              AbstractCode* code, const char* comment) {
   if (!is_logging_code_events()) return;
   if (!FLAG_log_code || !log_->IsEnabled()) return;
   Log::MessageBuilder msg(log_);
-  AppendCodeCreateHeader(&msg, tag, code);
+  AppendCodeCreateHeader(&msg, tag, code, &timer_);
   msg.AppendDoubleQuotedString(comment);
   msg.WriteToLogFile();
 }
 
 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                              AbstractCode* code, Name* name) {
   if (!is_logging_code_events()) return;
   if (!FLAG_log_code || !log_->IsEnabled()) return;
   Log::MessageBuilder msg(log_);
-  AppendCodeCreateHeader(&msg, tag, code);
+  AppendCodeCreateHeader(&msg, tag, code, &timer_);
   if (name->IsString()) {
     msg.Append('"');
     msg.AppendDetailed(String::cast(name), false);
     msg.Append('"');
   } else {
     msg.AppendSymbolName(Symbol::cast(name));
   }
   msg.WriteToLogFile();
 }
 
 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                              AbstractCode* code, SharedFunctionInfo* shared,
                              Name* name) {
   if (!is_logging_code_events()) return;
   if (!FLAG_log_code || !log_->IsEnabled()) return;
   if (code == AbstractCode::cast(
                   isolate_->builtins()->builtin(Builtins::kCompileLazy))) {
     return;
   }
 
   Log::MessageBuilder msg(log_);
-  AppendCodeCreateHeader(&msg, tag, code);
+  AppendCodeCreateHeader(&msg, tag, code, &timer_);
   if (name->IsString()) {
     std::unique_ptr<char[]> str =
         String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
     msg.Append("\"%s\"", str.get());
   } else {
     msg.AppendSymbolName(Symbol::cast(name));
   }
   msg.Append(',');
   msg.AppendAddress(shared->address());
   msg.Append(",%s", ComputeMarker(shared, code));
   msg.WriteToLogFile();
 }
 
 
 // Although, it is possible to extract source and line from
 // the SharedFunctionInfo object, we left it to caller
 // to leave logging functions free from heap allocations.
 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                              AbstractCode* code, SharedFunctionInfo* shared,
                              Name* source, int line, int column) {
   if (!is_logging_code_events()) return;
   if (!FLAG_log_code || !log_->IsEnabled()) return;
   Log::MessageBuilder msg(log_);
-  AppendCodeCreateHeader(&msg, tag, code);
+  AppendCodeCreateHeader(&msg, tag, code, &timer_);
   std::unique_ptr<char[]> name =
       shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
   msg.Append("\"%s ", name.get());
   if (source->IsString()) {
     std::unique_ptr<char[]> sourcestr = String::cast(source)->ToCString(
         DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
     msg.Append("%s", sourcestr.get());
   } else {
     msg.AppendSymbolName(Symbol::cast(source));
   }
   msg.Append(":%d:%d\",", line, column);
   msg.AppendAddress(shared->address());
   msg.Append(",%s", ComputeMarker(shared, code));
   msg.WriteToLogFile();
 }
 
 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                              AbstractCode* code, int args_count) {
   if (!is_logging_code_events()) return;
   if (!FLAG_log_code || !log_->IsEnabled()) return;
   Log::MessageBuilder msg(log_);
-  AppendCodeCreateHeader(&msg, tag, code);
+  AppendCodeCreateHeader(&msg, tag, code, &timer_);
   msg.Append("\"args_count: %d\"", args_count);
   msg.WriteToLogFile();
 }
 
 void Logger::CodeDisableOptEvent(AbstractCode* code,
                                  SharedFunctionInfo* shared) {
   if (!is_logging_code_events()) return;
   if (!FLAG_log_code || !log_->IsEnabled()) return;
   Log::MessageBuilder msg(log_);
   msg.Append("%s,", kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT]);
   std::unique_ptr<char[]> name =
       shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
   msg.Append("\"%s\",", name.get());
   msg.Append("\"%s\"", GetBailoutReason(shared->disable_optimization_reason()));
   msg.WriteToLogFile();
 }
 
 
 void Logger::CodeMovingGCEvent() {
   if (!is_logging_code_events()) return;
   if (!log_->IsEnabled() || !FLAG_ll_prof) return;
   base::OS::SignalCodeMovingGC();
 }
 
 void Logger::RegExpCodeCreateEvent(AbstractCode* code, String* source) {
   if (!is_logging_code_events()) return;
   if (!FLAG_log_code || !log_->IsEnabled()) return;
   Log::MessageBuilder msg(log_);
-  AppendCodeCreateHeader(&msg, CodeEventListener::REG_EXP_TAG, code);
+  AppendCodeCreateHeader(&msg, CodeEventListener::REG_EXP_TAG, code, &timer_);
   msg.Append('"');
   msg.AppendDetailed(source, false);
   msg.Append('"');
   msg.WriteToLogFile();
 }
 
 void Logger::CodeMoveEvent(AbstractCode* from, Address to) {
   if (!is_logging_code_events()) return;
   MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from->address(), to);
 }
@@ skipping 712 matching lines @@
 
   if (profiler_listener_.get() != nullptr) {
     removeCodeEventListener(profiler_listener_.get());
   }
 
   return log_->Close();
 }
 
 }  // namespace internal
 }  // namespace v8