Include more information in --prof log.

Main changes:
- include timestamps in profile ticks
- include code kind in code create events
- time execution in external code
- changed plot-timer-events.js to show the code kind being executed

R=jkummerow@chromium.org
BUG=

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

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

src/log.cc

@@ -716,6 +716,20 @@ void Logger::TimerEvent(const char* name, int64_t start, int64_t end) {
 }
 
 
+void Logger::ExternalSwitch(StateTag old_tag, StateTag new_tag) {
+  if (old_tag != EXTERNAL && new_tag == EXTERNAL) {
+    enter_external_ = OS::Ticks();
+  }
+  if (old_tag == EXTERNAL && new_tag != EXTERNAL && enter_external_ != 0) {
+    TimerEvent("V8.External", enter_external_, OS::Ticks());
+    enter_external_ = 0;
+  }
+}
+
+
+int64_t Logger::enter_external_ = 0;
+
+
 void Logger::TimerEventScope::LogTimerEvent() {
   LOG(isolate_, TimerEvent(name_, start_, OS::Ticks()));
 }
@@ -900,7 +914,7 @@ void Logger::CallbackEventInternal(const char* prefix, const char* name,
                                    Address entry_point) {
   if (!log_->IsEnabled() || !FLAG_log_code) return;
   LogMessageBuilder msg(this);
-  msg.Append("%s,%s,",
+  msg.Append("%s,%s,-3,",
              kLogEventsNames[CODE_CREATION_EVENT],
              kLogEventsNames[CALLBACK_TAG]);
   msg.AppendAddress(entry_point);
@@ -956,9 +970,10 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag,
   }
   if (!FLAG_log_code) return;
   LogMessageBuilder msg(this);
-  msg.Append("%s,%s,",
+  msg.Append("%s,%s,%d,",
              kLogEventsNames[CODE_CREATION_EVENT],
-             kLogEventsNames[tag]);
+             kLogEventsNames[tag],
+             code->kind());
   msg.AppendAddress(code->address());
   msg.Append(",%d,\"", code->ExecutableSize());
   for (const char* p = comment; *p != '\0'; p++) {
@@ -995,9 +1010,10 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag,
   }
   if (!FLAG_log_code) return;
   LogMessageBuilder msg(this);
-  msg.Append("%s,%s,",
+  msg.Append("%s,%s,%d,",
              kLogEventsNames[CODE_CREATION_EVENT],
-             kLogEventsNames[tag]);
+             kLogEventsNames[tag],
+             code->kind());
   msg.AppendAddress(code->address());
   msg.Append(",%d,\"", code->ExecutableSize());
   msg.AppendDetailed(name, false);
@@ -1047,9 +1063,10 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag,
   LogMessageBuilder msg(this);
   SmartArrayPointer<char> str =
       name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
-  msg.Append("%s,%s,",
+  msg.Append("%s,%s,%d,",
              kLogEventsNames[CODE_CREATION_EVENT],
-             kLogEventsNames[tag]);
+             kLogEventsNames[tag],
+             code->kind());
   msg.AppendAddress(code->address());
   msg.Append(",%d,\"%s\",", code->ExecutableSize(), *str);
   msg.AppendAddress(shared->address());
@@ -1094,9 +1111,10 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag,
       shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
   SmartArrayPointer<char> sourcestr =
       source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL);
-  msg.Append("%s,%s,",
+  msg.Append("%s,%s,%d,",
              kLogEventsNames[CODE_CREATION_EVENT],
-             kLogEventsNames[tag]);
+             kLogEventsNames[tag],
+             code->kind());
   msg.AppendAddress(code->address());
   msg.Append(",%d,\"%s %s:%d\",",
              code->ExecutableSize(),
@@ -1130,9 +1148,10 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) {
   }
   if (!FLAG_log_code) return;
   LogMessageBuilder msg(this);
-  msg.Append("%s,%s,",
+  msg.Append("%s,%s,%d,",
              kLogEventsNames[CODE_CREATION_EVENT],
-             kLogEventsNames[tag]);
+             kLogEventsNames[tag],
+             code->kind());
   msg.AppendAddress(code->address());
   msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count);
   msg.Append('\n');
@@ -1167,7 +1186,7 @@ void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
   }
   if (!FLAG_log_code) return;
   LogMessageBuilder msg(this);
-  msg.Append("%s,%s,",
+  msg.Append("%s,%s,-2,",
              kLogEventsNames[CODE_CREATION_EVENT],
              kLogEventsNames[REG_EXP_TAG]);
   msg.AppendAddress(code->address());
@@ -1347,6 +1366,8 @@ void Logger::TickEvent(TickSample* sample, bool overflow) {
   msg.AppendAddress(sample->pc);
   msg.Append(',');
   msg.AppendAddress(sample->sp);
+  msg.Append(",%ld",
+      FLAG_log_timer_events ? static_cast<int>(OS::Ticks() - epoch_) : 0);
   if (sample->has_external_callback) {
     msg.Append(",1,");
     msg.AppendAddress(sample->external_callback);

src/log.h

@@ -275,7 +275,10 @@ class Logger {
   void SharedLibraryEvent(const wchar_t* library_path,
                           uintptr_t start,
                           uintptr_t end);
+
+  // ==== Events logged by --log-timer-events. ====
   void TimerEvent(const char* name, int64_t start, int64_t end);
+  void ExternalSwitch(StateTag old_tag, StateTag new_tag);
 
   class TimerEventScope {
    public:
@@ -476,6 +479,7 @@ class Logger {
   Address prev_code_;
 
   int64_t epoch_;
+  static int64_t enter_external_;
 
   friend class CpuProfiler;
 };

src/vm-state-inl.h

@@ -67,6 +67,10 @@ VMState::VMState(Isolate* isolate, StateTag tag)
     LOG(isolate, UncheckedStringEvent("From", StateToString(previous_tag_)));
   }
 
+  if (FLAG_log_timer_events) {
+    LOG(isolate, ExternalSwitch(previous_tag_, tag));
+  }
+
   isolate_->SetCurrentVMState(tag);
 }
 
@@ -80,6 +84,10 @@ VMState::~VMState() {
         UncheckedStringEvent("To", StateToString(previous_tag_)));
   }
 
+  if (FLAG_log_timer_events) {
+    LOG(isolate_, ExternalSwitch(isolate_->current_vm_state(), previous_tag_));
+  }
+
   isolate_->SetCurrentVMState(previous_tag_);
 }
 

test/cctest/test-log.cc

@@ -392,7 +392,7 @@ TEST(LogCallbacks) {
 
   i::EmbeddedVector<char, 100> ref_data;
   i::OS::SNPrintF(ref_data,
-                  "code-creation,Callback,0x%" V8PRIxPTR ",1,\"method1\"\0",
+                  "code-creation,Callback,-3,0x%" V8PRIxPTR ",1,\"method1\"\0",
                   ObjMethod1);
 
   CHECK_NE(NULL, StrNStr(log.start(), ref_data.start(), log.length()));
@@ -435,21 +435,21 @@ TEST(LogAccessorCallbacks) {
 
   EmbeddedVector<char, 100> prop1_getter_record;
   i::OS::SNPrintF(prop1_getter_record,
-                  "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop1\"",
+                  "code-creation,Callback,-3,0x%" V8PRIxPTR ",1,\"get prop1\"",
                   Prop1Getter);
   CHECK_NE(NULL,
            StrNStr(log.start(), prop1_getter_record.start(), log.length()));
 
   EmbeddedVector<char, 100> prop1_setter_record;
   i::OS::SNPrintF(prop1_setter_record,
-                  "code-creation,Callback,0x%" V8PRIxPTR ",1,\"set prop1\"",
+                  "code-creation,Callback,-3,0x%" V8PRIxPTR ",1,\"set prop1\"",
                   Prop1Setter);
   CHECK_NE(NULL,
            StrNStr(log.start(), prop1_setter_record.start(), log.length()));
 
   EmbeddedVector<char, 100> prop2_getter_record;
   i::OS::SNPrintF(prop2_getter_record,
-                  "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop2\"",
+                  "code-creation,Callback,-3,0x%" V8PRIxPTR ",1,\"get prop2\"",
                   Prop2Getter);
   CHECK_NE(NULL,
            StrNStr(log.start(), prop2_getter_record.start(), log.length()));

test/mjsunit/tools/tickprocessor-test-func-info.log

@@ -2,10 +2,10 @@ shared-library,"shell",0x08048000,0x081ee000
 shared-library,"/lib32/libm-2.7.so",0xf7db6000,0xf7dd9000
 shared-library,"ffffe000-fffff000",0xffffe000,0xfffff000
 profiler,"begin",1
-code-creation,Stub,0x424260,348,"CompareStub_GE"
-code-creation,LazyCompile,0x2a8100,18535,"DrawQube 3d-cube.js:188",0xf43abcac,
-code-creation,LazyCompile,0x480100,3908,"DrawLine 3d-cube.js:17",0xf43abc50,
-tick,0x424284,0xbfffeea0,0,0x480600,0,0x2aaaa5
-tick,0x42429f,0xbfffed88,0,0x480600,0,0x2aacb4
-tick,0x48063d,0xbfffec7c,0,0x2d0f7c,0,0x2aaec6
+code-creation,Stub,0,0x424260,348,"CompareStub_GE"
+code-creation,LazyCompile,0,0x2a8100,18535,"DrawQube 3d-cube.js:188",0xf43abcac,
+code-creation,LazyCompile,0,0x480100,3908,"DrawLine 3d-cube.js:17",0xf43abc50,
+tick,0x424284,0xbfffeea0,0,0,0x480600,0,0x2aaaa5
+tick,0x42429f,0xbfffed88,0,0,0x480600,0,0x2aacb4
+tick,0x48063d,0xbfffec7c,0,0,0x2d0f7c,0,0x2aaec6
 profiler,"end"

test/mjsunit/tools/tickprocessor-test.log

@@ -2,24 +2,24 @@ shared-library,"shell",0x08048000,0x081ee000
 shared-library,"/lib32/libm-2.7.so",0xf7db6000,0xf7dd9000
 shared-library,"ffffe000-fffff000",0xffffe000,0xfffff000
 profiler,"begin",1
-code-creation,Stub,0xf540a100,474,"CEntryStub"
-code-creation,Script,0xf541cd80,736,"exp.js"
-code-creation,Stub,0xf541d0e0,47,"RuntimeStub_Math_exp"
-code-creation,LazyCompile,0xf541d120,145,"exp native math.js:41"
+code-creation,Stub,0,0xf540a100,474,"CEntryStub"
+code-creation,Script,0,0xf541cd80,736,"exp.js"
+code-creation,Stub,0,0xf541d0e0,47,"RuntimeStub_Math_exp"
+code-creation,LazyCompile,0,0xf541d120,145,"exp native math.js:41"
 function-creation,0xf441d280,0xf541d120
-code-creation,LoadIC,0xf541d280,117,"j"
-code-creation,LoadIC,0xf541d360,63,"i"
-tick,0x80f82d1,0xffdfe880,0,0,0,0xf541ce5c
-tick,0x80f89a1,0xffdfecf0,0,0,0,0xf541ce5c
-tick,0x8123b5c,0xffdff1a0,0,0,0,0xf541d1a1,0xf541ceea
-tick,0x8123b65,0xffdff1a0,0,0,0,0xf541d1a1,0xf541ceea
-tick,0xf541d2be,0xffdff1e4,0,0,0
-tick,0xf541d320,0xffdff1dc,0,0,0
-tick,0xf541d384,0xffdff1d8,0,0,0
-tick,0xf7db94da,0xffdff0ec,0,0,0,0xf541d1a1,0xf541ceea
-tick,0xf7db951c,0xffdff0f0,0,0,0,0xf541d1a1,0xf541ceea
-tick,0xf7dbc508,0xffdff14c,0,0,0,0xf541d1a1,0xf541ceea
-tick,0xf7dbff21,0xffdff198,0,0,0,0xf541d1a1,0xf541ceea
-tick,0xf7edec90,0xffdff0ec,0,0,0,0xf541d1a1,0xf541ceea
-tick,0xffffe402,0xffdff488,0,0,0
+code-creation,LoadIC,0,0xf541d280,117,"j"
+code-creation,LoadIC,0,0xf541d360,63,"i"
+tick,0x80f82d1,0xffdfe880,0,0,0,0,0xf541ce5c
+tick,0x80f89a1,0xffdfecf0,0,0,0,0,0xf541ce5c
+tick,0x8123b5c,0xffdff1a0,0,0,0,0,0xf541d1a1,0xf541ceea
+tick,0x8123b65,0xffdff1a0,0,0,0,0,0xf541d1a1,0xf541ceea
+tick,0xf541d2be,0xffdff1e4,0,0,0,0
+tick,0xf541d320,0xffdff1dc,0,0,0,0
+tick,0xf541d384,0xffdff1d8,0,0,0,0
+tick,0xf7db94da,0xffdff0ec,0,0,0,0,0xf541d1a1,0xf541ceea
+tick,0xf7db951c,0xffdff0f0,0,0,0,0,0xf541d1a1,0xf541ceea
+tick,0xf7dbc508,0xffdff14c,0,0,0,0,0xf541d1a1,0xf541ceea
+tick,0xf7dbff21,0xffdff198,0,0,0,0,0xf541d1a1,0xf541ceea
+tick,0xf7edec90,0xffdff0ec,0,0,0,0,0xf541d1a1,0xf541ceea
+tick,0xffffe402,0xffdff488,0,0,0,0
 profiler,"end"

tools/plot-timer-events

@@ -34,6 +34,7 @@ fi
 
 # nm spits out 'no symbols found' messages to stderr.
 cat $log_file | $d8_exec $tools_path/csvparser.js \
+    $tools_path/splaytree.js $tools_path/codemap.js \
     $tools_path/logreader.js $tools_path/plot-timer-events.js \
     2>/dev/null | gnuplot > timer-events.png
 

tools/tickprocessor.js

@@ -73,7 +73,7 @@ function parseState(s) {
 function SnapshotLogProcessor() {
   LogReader.call(this, {
       'code-creation': {
-          parsers: [null, parseInt, parseInt, null, 'var-args'],
+          parsers: [null, parseInt, parseInt, parseInt, null, 'var-args'],
           processor: this.processCodeCreation },
       'code-move': { parsers: [parseInt, parseInt],
           processor: this.processCodeMove },
@@ -107,7 +107,7 @@ inherits(SnapshotLogProcessor, LogReader);
 
 
 SnapshotLogProcessor.prototype.processCodeCreation = function(
-    type, start, size, name, maybe_func) {
+    type, kind, start, size, name, maybe_func) {
   if (maybe_func.length) {
     var funcAddr = parseInt(maybe_func[0]);
     var state = parseState(maybe_func[1]);
@@ -156,7 +156,7 @@ function TickProcessor(
       'shared-library': { parsers: [null, parseInt, parseInt],
           processor: this.processSharedLibrary },
       'code-creation': {
-          parsers: [null, parseInt, parseInt, null, 'var-args'],
+          parsers: [null, parseInt, parseInt, parseInt, null, 'var-args'],
           processor: this.processCodeCreation },
       'code-move': { parsers: [parseInt, parseInt],
           processor: this.processCodeMove },
@@ -167,7 +167,7 @@ function TickProcessor(
       'snapshot-pos': { parsers: [parseInt, parseInt],
           processor: this.processSnapshotPosition },
       'tick': {
-          parsers: [parseInt, parseInt, parseInt,
+          parsers: [parseInt, parseInt, parseInt, parseInt,
                     parseInt, parseInt, 'var-args'],
           processor: this.processTick },
       'heap-sample-begin': { parsers: [null, null, parseInt],
@@ -309,7 +309,7 @@ TickProcessor.prototype.processSharedLibrary = function(
 
 
 TickProcessor.prototype.processCodeCreation = function(
-    type, start, size, name, maybe_func) {
+    type, kind, start, size, name, maybe_func) {
   name = this.deserializedEntriesNames_[start] || name;
   if (maybe_func.length) {
     var funcAddr = parseInt(maybe_func[0]);
@@ -350,6 +350,7 @@ TickProcessor.prototype.includeTick = function(vmState) {
 
 TickProcessor.prototype.processTick = function(pc,
                                                sp,
+                                               ns_since_start,
                                                is_external_callback,
                                                tos_or_external_callback,
                                                vmState,