* Change output of trace_event log to JSON to enable easier integration with visualization UI.

* Simple (manual) trace visualizer with some sample data.
* a few more trace events
* add process_util function for current process handle

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

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@2381 0039d316-1c4b-4281-b951-d872f2087c98

base/process_util.h

@@ -32,6 +32,9 @@ namespace process_util {
 // Returns the id of the current process.
 int GetCurrentProcId();
 
+// Returns the ProcessHandle of the current process.
+ProcessHandle GetCurrentProcessHandle();
+
 // Returns the unique ID for the specified process.  This is functionally the
 // same as Windows' GetProcessId(), but works on versions of Windows before
 // Win XP SP1 as well.

base/process_util_posix.cc

@@ -15,6 +15,10 @@ int GetCurrentProcId() {
   return getpid();
 }
 
+ProcessHandle GetCurrentProcessHandle() {
+  return GetCurrentProcId();
+}
+
 int GetProcId(ProcessHandle process) {
   return process;
 }

base/process_util_win.cc

@@ -28,6 +28,10 @@ int GetCurrentProcId() {
   return ::GetCurrentProcessId();
 }
 
+ProcessHandle GetCurrentProcessHandle() {
+  return ::GetCurrentProcess();
+}
+
 // Helper for GetProcId()
 bool GetProcIdViaGetProcessId(ProcessHandle process, DWORD* id) {
   // Dynamically get a pointer to GetProcessId().

base/trace_event.cc

@@ -24,6 +24,8 @@ static const char* kEventTypeNames[] = {
 static const wchar_t* kLogFileName = L"trace_%d.log";
 
 TraceLog::TraceLog() : enabled_(false), log_file_(NULL) {
+  ProcessHandle proc = process_util::GetCurrentProcessHandle();
+  process_metrics_.reset(process_util::ProcessMetrics::CreateProcessMetrics(proc));
 }
 
 TraceLog::~TraceLog() {
@@ -46,8 +48,11 @@ bool TraceLog::Start() {
   if (enabled_)
     return true;
   enabled_ = OpenLogFile();
-  if (enabled_)
+  if (enabled_) {
+    Log("var raw_trace_events = [\r\n");
     trace_start_time_ = TimeTicks::Now();
+    timer_.Start(TimeDelta::FromMilliseconds(250), this, &TraceLog::Heartbeat);
+  }
   return enabled_;
 }
 
@@ -60,10 +65,17 @@ void TraceLog::StopTracing() {
 void TraceLog::Stop() {
   if (enabled_) {
     enabled_ = false;
+    Log("];\r\n");
     CloseLogFile();
+    timer_.Stop();
   }
 }
 
+void TraceLog::Heartbeat() {
+  std::string cpu = StringPrintf("%d", process_metrics_->GetCPUUsage());
+  TRACE_EVENT_INSTANT("heartbeat.cpu", 0, cpu);
+}
+
 void TraceLog::CloseLogFile() {
   if (log_file_) {
 #if defined(OS_WIN)
@@ -105,7 +117,7 @@ bool TraceLog::OpenLogFile() {
 
 void TraceLog::Trace(const std::string& name, 
                      EventType type,
-                     void* id,
+                     const void* id,
                      const std::wstring& extra,
                      const char* file, 
                      int line) {
@@ -116,7 +128,7 @@ void TraceLog::Trace(const std::string& name,
 
 void TraceLog::Trace(const std::string& name, 
                      EventType type,
-                     void* id,
+                     const void* id,
                      const std::string& extra,
                      const char* file, 
                      int line) {
@@ -131,8 +143,9 @@ void TraceLog::Trace(const std::string& name,
   TimeDelta delta = tick - trace_start_time_;
   int64 usec = delta.InMicroseconds();
   std::string msg = 
-    StringPrintf("%I64d 0x%lx:0x%lx %s %s [0x%lx %s] <%s:%d>\r\n",
-                 usec,
+    StringPrintf("{'pid':'0x%lx', 'tid':'0x%lx', 'type':'%s', "
+                 "'name':'%s', 'id':'0x%lx', 'extra':'%s', 'file':'%s', "
+                 "'line_number':'%d', 'usec_begin': %I64d},\r\n", 
                  process_util::GetCurrentProcId(),
                  PlatformThread::CurrentId(),
                  kEventTypeNames[type],
@@ -140,7 +153,8 @@ void TraceLog::Trace(const std::string& name,
                  id,
                  extra.c_str(),
                  file, 
-                 line);
+                 line,
+                 usec);
 
   Log(msg);
 }

base/trace_event.h

@@ -24,8 +24,10 @@
 #include <string>
 
 #include "base/lock.h"
+#include "base/scoped_ptr.h"
 #include "base/singleton.h"
 #include "base/time.h"
+#include "base/timer.h"
 
 // Use the following macros rather than using the TraceLog class directly as the
 // underlying implementation may change in the future.  Here's a sample usage:
@@ -40,7 +42,7 @@
 #define TRACE_EVENT_BEGIN(name, id, extra) \
   Singleton<base::TraceLog>::get()->Trace(name, \
                                           base::TraceLog::EVENT_BEGIN, \
-                                          reinterpret_cast<void*>(id), \
+                                          reinterpret_cast<const void*>(id), \
                                           extra, \
                                           __FILE__, \
                                           __LINE__)
@@ -50,7 +52,7 @@
 #define TRACE_EVENT_END(name, id, extra) \
   Singleton<base::TraceLog>::get()->Trace(name, \
                                           base::TraceLog::EVENT_END, \
-                                          reinterpret_cast<void*>(id), \
+                                          reinterpret_cast<const void*>(id), \
                                           extra, \
                                           __FILE__, \
                                           __LINE__)
@@ -59,7 +61,7 @@
 #define TRACE_EVENT_INSTANT(name, id, extra) \
   Singleton<base::TraceLog>::get()->Trace(name, \
                                           base::TraceLog::EVENT_INSTANT, \
-                                          reinterpret_cast<void*>(id), \
+                                          reinterpret_cast<const void*>(id), \
                                           extra, \
                                           __FILE__, \
                                           __LINE__)
@@ -77,6 +79,10 @@ typedef HANDLE FileHandle;
 typedef FILE* FileHandle;
 #endif
 
+namespace process_util {
+class ProcessMetrics;
+}
+
 namespace base {
 
 class TraceLog {
@@ -97,13 +103,13 @@ class TraceLog {
   // Log a trace event of (name, type, id) with the optional extra string.
   void Trace(const std::string& name, 
              EventType type,
-             void* id,
+             const void* id,
              const std::wstring& extra,
              const char* file, 
              int line);
   void Trace(const std::string& name, 
              EventType type,
-             void* id,
+             const void* id,
              const std::string& extra,
              const char* file, 
              int line);
@@ -119,12 +125,15 @@ class TraceLog {
   void CloseLogFile();
   bool Start();
   void Stop();
+  void Heartbeat();
   void Log(const std::string& msg);
 
   bool enabled_;
   FileHandle log_file_;
   Lock file_lock_;
   TimeTicks trace_start_time_;
+  scoped_ptr<process_util::ProcessMetrics> process_metrics_;
+  RepeatingTimer<TraceLog> timer_;
 };
 
 } // namespace base

net/base/tcp_client_socket.cc

@@ -157,6 +157,7 @@ int TCPClientSocket::Read(char* buf,
   buffer_.len = buf_len;
   buffer_.buf = buf;
 
+  TRACE_EVENT_BEGIN("socket.read", this, "");
   // TODO(wtc): Remove the CHECKs after enough testing.
   CHECK(WaitForSingleObject(overlapped_.hEvent, 0) == WAIT_TIMEOUT);
   DWORD num, flags = 0;
@@ -165,6 +166,7 @@ int TCPClientSocket::Read(char* buf,
     CHECK(WaitForSingleObject(overlapped_.hEvent, 0) == WAIT_OBJECT_0);
     BOOL ok = WSAResetEvent(overlapped_.hEvent);
     CHECK(ok);
+    TRACE_EVENT_END("socket.read", this, StringPrintf("%d bytes", num));
     return static_cast<int>(num);
   }
   int err = WSAGetLastError();
@@ -187,6 +189,7 @@ int TCPClientSocket::Write(const char* buf,
   buffer_.len = buf_len;
   buffer_.buf = const_cast<char*>(buf);
 
+  TRACE_EVENT_BEGIN("socket.write", this, "");
   // TODO(wtc): Remove the CHECKs after enough testing.
   CHECK(WaitForSingleObject(overlapped_.hEvent, 0) == WAIT_TIMEOUT);
   DWORD num;
@@ -195,6 +198,7 @@ int TCPClientSocket::Write(const char* buf,
     CHECK(WaitForSingleObject(overlapped_.hEvent, 0) == WAIT_OBJECT_0);
     BOOL ok = WSAResetEvent(overlapped_.hEvent);
     CHECK(ok);
+    TRACE_EVENT_END("socket.write", this, StringPrintf("%d bytes", num));
     return static_cast<int>(num);
   }
   int err = WSAGetLastError();
@@ -272,11 +276,9 @@ void TCPClientSocket::DidCompleteIO() {
       socket_, &overlapped_, &num_bytes, FALSE, &flags);
   WSAResetEvent(overlapped_.hEvent);
   if (wait_state_ == WAITING_READ) {
-    TRACE_EVENT_INSTANT("socket.read", this, 
-                        StringPrintf("%d bytes", num_bytes));
+    TRACE_EVENT_END("socket.read", this, StringPrintf("%d bytes", num_bytes));
   } else {
-    TRACE_EVENT_INSTANT("socket.write", this, 
-                        StringPrintf("%d bytes", num_bytes));
+    TRACE_EVENT_END("socket.write", this, StringPrintf("%d bytes", num_bytes));
   }
   wait_state_ = NOT_WAITING;
   DoCallback(ok ? num_bytes : MapWinsockError(WSAGetLastError()));

net/http/http_network_transaction.cc

@@ -5,6 +5,7 @@
 #include "net/http/http_network_transaction.h"
 
 #include "base/string_util.h"
+#include "base/trace_event.h"
 #include "net/base/client_socket_factory.h"
 #include "net/base/host_resolver.h"
 #include "net/base/load_flags.h"
@@ -254,66 +255,84 @@ int HttpNetworkTransaction::DoLoop(int result) {
     switch (state) {
       case STATE_RESOLVE_PROXY:
         DCHECK(rv == OK);
+        TRACE_EVENT_BEGIN("http.resolve_proxy", request_, request_->url.spec());
         rv = DoResolveProxy();
         break;
       case STATE_RESOLVE_PROXY_COMPLETE:
         rv = DoResolveProxyComplete(rv);
+        TRACE_EVENT_END("http.resolve_proxy", request_, request_->url.spec());
         break;
       case STATE_INIT_CONNECTION:
         DCHECK(rv == OK);
+        TRACE_EVENT_BEGIN("http.init_conn", request_, request_->url.spec());
         rv = DoInitConnection();
         break;
       case STATE_INIT_CONNECTION_COMPLETE:
         rv = DoInitConnectionComplete(rv);
+        TRACE_EVENT_END("http.init_conn", request_, request_->url.spec());
         break;
       case STATE_RESOLVE_HOST:
         DCHECK(rv == OK);
+        TRACE_EVENT_BEGIN("http.resolve_host", request_, request_->url.spec());
         rv = DoResolveHost();
         break;
       case STATE_RESOLVE_HOST_COMPLETE:
         rv = DoResolveHostComplete(rv);
+        TRACE_EVENT_END("http.resolve_host", request_, request_->url.spec());
         break;
       case STATE_CONNECT:
         DCHECK(rv == OK);
+        TRACE_EVENT_BEGIN("http.connect", request_, request_->url.spec());
         rv = DoConnect();
         break;
       case STATE_CONNECT_COMPLETE:
         rv = DoConnectComplete(rv);
+        TRACE_EVENT_END("http.connect", request_, request_->url.spec());
         break;
       case STATE_SSL_CONNECT_OVER_TUNNEL:
         DCHECK(rv == OK);
+        TRACE_EVENT_BEGIN("http.ssl_tunnel", request_, request_->url.spec());
         rv = DoSSLConnectOverTunnel();
         break;
       case STATE_SSL_CONNECT_OVER_TUNNEL_COMPLETE:
         rv = DoSSLConnectOverTunnelComplete(rv);
+        TRACE_EVENT_END("http.ssl_tunnel", request_, request_->url.spec());
         break;
       case STATE_WRITE_HEADERS:
         DCHECK(rv == OK);
+        TRACE_EVENT_BEGIN("http.write_headers", request_, request_->url.spec());
         rv = DoWriteHeaders();
         break;
       case STATE_WRITE_HEADERS_COMPLETE:
         rv = DoWriteHeadersComplete(rv);
+        TRACE_EVENT_END("http.write_headers", request_, request_->url.spec());
         break;
       case STATE_WRITE_BODY:
         DCHECK(rv == OK);
+        TRACE_EVENT_BEGIN("http.write_body", request_, request_->url.spec());
         rv = DoWriteBody();
         break;
       case STATE_WRITE_BODY_COMPLETE:
         rv = DoWriteBodyComplete(rv);
+        TRACE_EVENT_END("http.write_body", request_, request_->url.spec());
         break;
       case STATE_READ_HEADERS:
         DCHECK(rv == OK);
+        TRACE_EVENT_BEGIN("http.read_headers", request_, request_->url.spec());
         rv = DoReadHeaders();
         break;
       case STATE_READ_HEADERS_COMPLETE:
         rv = DoReadHeadersComplete(rv);
+        TRACE_EVENT_END("http.read_headers", request_, request_->url.spec());
         break;
       case STATE_READ_BODY:
         DCHECK(rv == OK);
+        TRACE_EVENT_BEGIN("http.read_body", request_, request_->url.spec());
         rv = DoReadBody();
         break;
       case STATE_READ_BODY_COMPLETE:
         rv = DoReadBodyComplete(rv);
+        TRACE_EVENT_END("http.read_body", request_, request_->url.spec());
         break;
       default:
         NOTREACHED() << "bad state";

tools/trace/trace.html

@@ -0,0 +1,287 @@
+<html>
+<head>
+<title>
+Trace Events
+</title>
+<style>
+body {
+  font-family: "Courier New";
+  font-size: 9pt;
+}
+
+#header {
+  position: absolute;
+  top: 0px;
+  left: 0px;
+  border-bottom: 1px dashed black;
+  background-color: #F0F0F0;
+  z-index: 3;
+}
+
+#outer {
+  position: relative;
+  height: 200px;
+}
+
+#time_scale {
+  height: 15px;
+  width: 100%;
+}
+
+#tooltip {
+  position: absolute;
+  background-color: #FFFFCC;
+  display: none;
+  font-family: "Courier New";
+  font-size: 9pt;
+  padding: 5px;
+  border: 1px solid #CCCC88;
+  z-index: 3;
+}
+
+#legend {
+  position: fixed;
+  left: 10px;
+  bottom: 10px;
+  padding: 5px;
+  border: 1px solid silver;
+  z-index: 10;
+  background-color: #f0f0f0;
+}
+
+h2 {
+  margin: 5px;
+}
+
+#instructions {
+  position: absolute;
+  top: 
+  float: right;
+  display: none;
+}
+
+li.time_tick {
+  background-color: #FFFFCC;
+  height: 15px;
+}
+
+li {
+  background: pink;
+  position: absolute;
+  height: 10px;
+  list-style: none;
+  margin: 0px;
+  padding: 0px;
+  z-index: 2;
+}
+
+li:hover {
+  border: 1px solid red;
+}
+
+.url {
+  background-color: green;
+}
+
+.http {
+  background-color: blue;
+}
+
+.socket {
+  background-color: black;
+}
+
+.v8 {
+  background-color: orange; 
+}
+
+</style>
+
+<script src='trace_data.js'></script>
+<script>
+var scale = 100000;
+var row_height = 15;
+var trace_initial_time = 0;
+var trace_threads = {};
+var heartbeats = [];
+var trace_total_time = 0;
+
+function process_raw_events() {
+  trace_initial_time = raw_trace_events[0].usec_begin;
+  var stack = [];
+  var e;
+  for (var i in raw_trace_events) {
+    e = raw_trace_events[i];
+    var trace_events = trace_threads["e.tid"];
+    if (!trace_events) {
+      trace_events = [];
+      trace_threads["e.tid"] = trace_events;
+    }
+    if (e.name.indexOf("heartbeat.") == 0) {
+      heartbeats.push(e);
+    } else if (e.type == "BEGIN") {
+      trace_events.push(e);
+      stack.unshift(e);
+    } else if (e.type == "END") {
+      for (var s in stack) {
+        var begin = stack[s];
+        if ((begin.id == e.id) && (begin.name == e.name) &&
+            (begin.pid == e.pid) && (begin.tid == e.tid)) {
+          begin.usec_end = e.usec_begin;
+          begin.duration = begin.usec_end - begin.usec_begin;
+          stack.splice(s, 1);
+          break;
+        } 
+      }
+    } else if (e.type == "INSTANT") {
+      trace_events.push(e);
+      e.duration = 0;
+    }
+  }
+  if (e.usec_end)
+    trace_total_time = e.usec_end - trace_initial_time;
+  else
+    trace_total_time = e.usec_begin - trace_initial_time;
+}
+
+function compute_scale() {
+  var outer = document.getElementById("outer");
+  scale = Math.floor(trace_total_time / (outer.offsetWidth - (row_height * 2)));
+};
+
+function show_details(tid, i, event) {
+  var trace_events = trace_threads["e.tid"];
+  var inner = trace_events[i].name + " " +
+              trace_events[i].duration / 1000 + "ms<br />" + 
+              trace_events[i].id  + "<br />" + 
+              trace_events[i].extra  + "<br />";
+  var tooltip = document.getElementById("tooltip");
+  tooltip.innerHTML = inner;
+  if (window.event)
+    event = window.event;
+  tooltip.style.top = event.pageY + 3;
+  tooltip.style.left = event.pageX + 3;
+  tooltip.style.display = "block";
+};
+
+function generate_time_scale() {
+  var view_size = window.clientWidth;
+  var body_size = document.body.scrollWidth;
+  var inner = "";
+  
+  var step_ms = Math.floor(scale / 10); // ms per 100px
+  var pow10 = Math.pow(10, Math.floor(Math.log(step_ms) / Math.log(10)));
+  var round = .5 * pow10;
+  step_ms = round * (Math.floor(step_ms / round)); // round to a multiple of round
+  for (var i = step_ms; i < trace_total_time / 1000; i += step_ms) {
+    var x = Math.floor(i * 1000 / scale);
+    inner += "<li class='time_tick' style='left: " + x + "px'>" + i + "</li>";
+  }
+  var time_scale = document.getElementById("time_scale");
+  time_scale.innerHTML = inner;
+  time_scale.style.width = document.body.scrollWidth;
+}
+
+function generate_subchart(trace_events, top) {
+  var inner = "";
+  var last_max_time = 0;
+  var last_max_x = 0;
+  for (var i in trace_events) {
+    var e = trace_events[i];
+    var start_time = e.usec_begin - trace_initial_time;
+    var left = row_height + Math.floor(start_time / scale);
+    var width = Math.floor(e.duration / scale);
+    if (width == 0)
+      width = 1;
+    if (start_time < last_max_time)
+      top += row_height;
+    var style = "top: " + top + "px; left: " + left + "px; width: " + width + "px;";
+    var js = 'javascript:show_details("' + e.tid + '", ' + i + ', event);';
+    var cls = e.name.split('.')[0];
+    inner += "<li class='" + cls + "' onmouseover='" + js + "' id='li-" + i + "' style='" + style + "'></li>\n";
+    last_max_time = start_time + e.duration;
+    last_max_x = left + width;
+  }
+  var subchart = document.createElement('div');
+  subchart.setAttribute("class", "subchart");
+  subchart.setAttribute("id", trace_events[0].tid);
+  subchart.innerHTML = inner;
+  subchart.style.height = top + row_height;
+  subchart.style.width = row_height + last_max_x;
+  var chart = document.getElementById("chart");
+  chart.appendChild(subchart);
+  
+  return top;
+};
+
+function generate_chart() {
+  var chart = document.getElementById("chart");
+  chart.innerHTML = "";
+  var top = 60;
+  for (var t in trace_threads) {
+    top = generate_subchart(trace_threads[t], top);
+  }
+  generate_time_scale();
+}
+
+function change_scale(event) {
+  if (!event)
+    event = window.event;
+  if (!event.shiftKey)
+    return;
+  var delta = 0;
+  if (event.wheelDelta) {
+    delta = event.wheelDelta / 120;
+  } else if (event.detail) {
+    delta = - event.detail / 3;
+  }
+  if (delta) {
+    var tooltip = document.getElementById("tooltip");
+    tooltip.style.display = "none";
+    var factor = 1.1;
+    if (delta < 0)
+      scale = Math.floor(scale * factor);
+    else
+      scale = Math.floor(scale / factor);
+    if (scale > 300000)
+      scale = 300000;
+    generate_chart();
+    if (event.preventDefault)
+      event.preventDefault();
+  }
+  event.returnValue = false;
+};
+
+function initial_load() {
+  if (window.addEventListener)
+    window.addEventListener('DOMMouseScroll', change_scale, false);
+  window.onmousewheel = document.onmousewheel = change_scale;
+
+  process_raw_events();
+  compute_scale();
+  generate_chart();
+};
+
+</script>
+</head>
+<body onload='initial_load();'>
+<div id="header">
+<h2>Trace Events</h2>
+<div id="instructions">
+Use shift+mouse-wheel to zoom in and out.
+</div>
+<div id="time_scale"></div>
+</div>
+<div id="legend">
+<span class="url">&nbsp;</span> URL<br />
+<span class="http">&nbsp;</span> HTTP<br />
+<span class="socket">&nbsp;</span> Socket<br />
+<span class="v8">&nbsp;</span> V8<br />
+</div>
+<div id="chart">
+<div id="outer">
+</div>
+</div>
+<div id="tooltip" ondblclick="this.style.display = 'none';"></div>
+</body>
+</html>