Fixed numerous issues that were causing errors in profiler log processing

on a real web application loaded in the test shell.

Also implemented output of JSON-encoded call stacks for profiler
prototype.

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

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

src/log.cc

@@ -299,6 +299,7 @@ class LogMessageBuilder BASE_EMBEDDED {
   void AppendDetailed(String* str, bool show_impl_info);
 
   void WriteToLogFile();
+  void WriteCStringToLogFile(const char* str);
 
  private:
   ScopedLock sl;
@@ -395,6 +396,14 @@ void LogMessageBuilder::WriteToLogFile() {
   ASSERT(rv == static_cast<size_t>(pos_));
   USE(rv);
 }
+
+// Write a null-terminated string to to the log file currently opened.
+void LogMessageBuilder::WriteCStringToLogFile(const char* str) {
+  size_t len = strlen(str);
+  size_t rv = fwrite(str, 1, len, Logger::logfile_);
+  ASSERT(rv == len);
+  USE(rv);
+}
 #endif
 
 
@@ -417,8 +426,7 @@ void Logger::Preamble(const char* content) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_code) return;
   LogMessageBuilder msg;
-  msg.Append("%s", content);
-  msg.WriteToLogFile();
+  msg.WriteCStringToLogFile(content);
 #endif
 }
 
@@ -758,6 +766,20 @@ void Logger::CodeCreateEvent(const char* tag, Code* code, int args_count) {
 }
 
 
+void Logger::RegExpCodeCreateEvent(Code* code, String* source) {
+#ifdef ENABLE_LOGGING_AND_PROFILING
+  if (logfile_ == NULL || !FLAG_log_code) return;
+  LogMessageBuilder msg;
+  msg.Append("code-creation,%s,0x%x,%d,\"", "RegExp",
+             reinterpret_cast<unsigned int>(code->address()),
+             code->ExecutableSize());
+  msg.AppendDetailed(source, false);
+  msg.Append("\"\n");
+  msg.WriteToLogFile();
+#endif
+}
+
+
 void Logger::CodeAllocateEvent(Code* code, Assembler* assem) {
 #ifdef ENABLE_LOGGING_AND_PROFILING
   if (logfile_ == NULL || !FLAG_log_code) return;
@@ -1010,9 +1032,9 @@ bool Logger::Setup() {
         }
       }
       SmartPointer<const char> expanded = stream.ToCString();
-      logfile_ = OS::FOpen(*expanded, "w");
+      logfile_ = OS::FOpen(*expanded, OS::LogFileOpenMode);
     } else {
-      logfile_ = OS::FOpen(FLAG_logfile, "w");
+      logfile_ = OS::FOpen(FLAG_logfile, OS::LogFileOpenMode);
     }
     message_buffer_ = NewArray<char>(kMessageBufferSize);
     mutex_ = OS::CreateMutex();

src/log.h

@@ -167,6 +167,8 @@ class Logger {
   static void CodeCreateEvent(const char* tag, Code* code, String* name,
                               String* source, int line);
   static void CodeCreateEvent(const char* tag, Code* code, int args_count);
+  // Emits a code create event for a RegExp.
+  static void RegExpCodeCreateEvent(Code* code, String* source);
   static void CodeAllocateEvent(Code* code, Assembler* assem);
   // Emits a code move event.
   static void CodeMoveEvent(Address from, Address to);
@@ -227,7 +229,7 @@ class Logger {
   static void UncheckedStringEvent(const char* name, const char* value);
 
   // Size of buffer used for formatting log messages.
-  static const int kMessageBufferSize = 256;
+  static const int kMessageBufferSize = 2048;
 
   // Buffer used for formatting log messages. This is a singleton buffer and
   // mutex_ should be acquired before using it.

src/platform-posix.cc

@@ -113,6 +113,9 @@ FILE* OS::FOpen(const char* path, const char* mode) {
 }
 
 
+const char* OS::LogFileOpenMode = "w";
+
+
 void OS::Print(const char* format, ...) {
   va_list args;
   va_start(args, format);

src/platform-win32.cc

@@ -683,6 +683,10 @@ FILE* OS::FOpen(const char* path, const char* mode) {
 }
 
 
+// Open log file in binary mode to avoid /n -> /r/n conversion.
+const char* OS::LogFileOpenMode = "wb";
+
+
 // Print (debug) message to console.
 void OS::Print(const char* format, ...) {
   va_list args;

src/platform.h

@@ -151,6 +151,9 @@ class OS {
 
   static FILE* FOpen(const char* path, const char* mode);
 
+  // Log file open mode is platform-dependent due to line ends issues.
+  static const char* LogFileOpenMode;
+
   // Print output to console. This is mostly used for debugging output.
   // On platforms that has standard terminal output, the output
   // should go to stdout.
@@ -484,7 +487,7 @@ class TickSample {
   unsigned int sp;  // Stack pointer.
   unsigned int fp;  // Frame pointer.
   StateTag state;   // The state of the VM.
-  static const int kMaxFramesCount = 5;
+  static const int kMaxFramesCount = 100;
   EmbeddedVector<Address, kMaxFramesCount> stack;  // Call stack.
   int frames_count;  // Number of captured frames.
 };

src/regexp-macro-assembler-ia32.cc

@@ -825,7 +825,7 @@ Handle<Object> RegExpMacroAssemblerIA32::GetCode(Handle<String> source) {
                                        NULL,
                                        Code::ComputeFlags(Code::REGEXP),
                                        masm_->CodeObject());
-  LOG(CodeCreateEvent("RegExp", *code, *(source->ToCString())));
+  LOG(RegExpCodeCreateEvent(*code, *source));
   return Handle<Object>::cast(code);
 }
 

tools/tickprocessor.py

@@ -147,6 +147,27 @@ class Assembler(object):
     self.regions = []
 
 
+class FunctionEnumerator(object):
+
+  def __init__(self):
+    self.known_funcs = {}
+    self.next_func_id = 0
+
+  def GetFunctionId(self, name):
+    if not self.known_funcs.has_key(name):
+      self.known_funcs[name] = self.next_func_id
+      self.next_func_id += 1
+    return self.known_funcs[name]
+
+  def GetKnownFunctions(self):
+    known_funcs_items = self.known_funcs.items();
+    known_funcs_items.sort(key = itemgetter(1))
+    result = []
+    for func, id_not_used in known_funcs_items:
+      result.append(func)
+    return result
+
+
 VMStates = { 'JS': 0, 'GC': 1, 'COMPILER': 2, 'OTHER': 3, 'EXTERNAL' : 4 }
 
 
@@ -170,20 +191,26 @@ class TickProcessor(object):
     self.number_of_gc_ticks = 0
     # Flag indicating whether to ignore unaccounted ticks in the report
     self.ignore_unknown = False
+    self.func_enum = FunctionEnumerator()
+    self.packed_stacks = []
 
-  def ProcessLogfile(self, filename, included_state = None, ignore_unknown = False, separate_ic = False):
+  def ProcessLogfile(self, filename, included_state = None, ignore_unknown = False, separate_ic = False, call_graph_json = False):
     self.log_file = filename
     self.included_state = included_state
     self.ignore_unknown = ignore_unknown
     self.separate_ic = separate_ic
+    self.call_graph_json = call_graph_json
 
     try:
       logfile = open(filename, 'rb')
     except IOError:
       sys.exit("Could not open logfile: " + filename)
+    try:
       try:
         logreader = csv.reader(logfile)
+        row_num = 1
         for row in logreader:
+          row_num += 1
           if row[0] == 'tick':
             self.ProcessTick(int(row[1], 16), int(row[2], 16), int(row[3]), self.PreprocessStack(row[4:]))
           elif row[0] == 'code-creation':
@@ -201,6 +228,9 @@ class TickProcessor(object):
             self.ProcessEndCodeRegion(int(row[1], 16), int(row[2], 16), int(row[3], 16))
           elif row[0] == 'code-allocate':
             self.ProcessCodeAllocate(int(row[1], 16), int(row[2], 16))
+      except csv.Error:
+        print("parse error in line " + str(row_num))
+        raise
     finally:
       logfile.close()
 
@@ -312,8 +342,25 @@ class TickProcessor(object):
         self.unaccounted_number_of_ticks += 1
     else:
       entry.Tick(pc, self.ProcessStack(stack))
+      if self.call_graph_json:
+        self.AddToPackedStacks(pc, stack)
+
+  def AddToPackedStacks(self, pc, stack):
+    full_stack = stack
+    full_stack.insert(0, pc)
+    func_names = self.ProcessStack(full_stack)
+    func_ids = []
+    for func in func_names:
+      func_ids.append(self.func_enum.GetFunctionId(func))
+    self.packed_stacks.append(func_ids)
 
   def PrintResults(self):
+    if not self.call_graph_json:
+      self.PrintStatistics()
+    else:
+      self.PrintCallGraphJSON()
+
+  def PrintStatistics(self):
     print('Statistical profiling result from %s, (%d ticks, %d unaccounted, %d excluded).' %
           (self.log_file,
            self.total_number_of_ticks,
@@ -412,6 +459,16 @@ class TickProcessor(object):
         'call_path' : stack[0] + '  <-  ' + stack[1]
       })
 
+  def PrintCallGraphJSON(self):
+    print('\nvar __profile_funcs = ["' +
+          '",\n"'.join(self.func_enum.GetKnownFunctions()) +
+          '"];')
+    print('var __profile_ticks = [')
+    str_packed_stacks = []
+    for stack in self.packed_stacks:
+      str_packed_stacks.append('[' + ','.join(map(str, stack)) + ']')
+    print(',\n'.join(str_packed_stacks))
+    print('];')
 
 class CmdLineProcessor(object):
 
@@ -422,12 +479,14 @@ class CmdLineProcessor(object):
                     "other",
                     "external",
                     "ignore-unknown",
-                    "separate-ic"]
+                    "separate-ic",
+                    "call-graph-json"]
     # default values
     self.state = None
     self.ignore_unknown = False
     self.log_file = None
     self.separate_ic = False
+    self.call_graph_json = False
 
   def ProcessArguments(self):
     try:
@@ -449,6 +508,8 @@ class CmdLineProcessor(object):
         self.ignore_unknown = True
       if key in ("--separate-ic"):
         self.separate_ic = True
+      if key in ("--call-graph-json"):
+        self.call_graph_json = True
     self.ProcessRequiredArgs(args)
 
   def ProcessRequiredArgs(self, args):
@@ -466,7 +527,8 @@ class CmdLineProcessor(object):
     sys.exit(2)
 
   def RunLogfileProcessing(self, tick_processor):
-    tick_processor.ProcessLogfile(self.log_file, self.state, self.ignore_unknown, self.separate_ic)
+    tick_processor.ProcessLogfile(self.log_file, self.state, self.ignore_unknown,
+                                  self.separate_ic, self.call_graph_json)
 
 
 if __name__ == '__main__':