Initial pass at simple event tracing. I added a few traces to tcp_socket and test_shell to get an idea of what a simple trace might look like.

Here's a sample output line:
11:24:19.660604 0x1e278:0x1e24c BEGIN url.load [0x5 http://mail.google.com/mail/] <E:\src\cr\src\webkit\tools\test_shell\test_webview_delegate.cc:189>

format is:hh:mm:ss.us pid:tid TYPE NAME [id, extra] <file:line>


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

10 files changed, 348 insertions, 3 deletions

diff --git a/base/build/base.vcproj b/base/build/base.vcproj
index 9d2b459..b6fa837 100644
--- a/base/build/base.vcproj
+++ b/base/build/base.vcproj
@@ -514,11 +514,11 @@
 			>
 		</File>
 		<File
-			RelativePath="..\process_util_win.cc"
+			RelativePath="..\process_util.h"
 			>
 		</File>
 		<File
-			RelativePath="..\process_util.h"
+			RelativePath="..\process_util_win.cc"
 			>
 		</File>
 		<File
@@ -742,6 +742,14 @@
 			>
 		</File>
 		<File
+			RelativePath="..\trace_event.cc"
+			>
+		</File>
+		<File
+			RelativePath="..\trace_event.h"
+			>
+		</File>
+		<File
 			RelativePath="..\tracked.cc"
 			>
 		</File>
diff --git a/base/trace_event.cc b/base/trace_event.cc
new file mode 100644
index 0000000..3225830
--- /dev/null
+++ b/base/trace_event.cc
@@ -0,0 +1,161 @@
+// Copyright (c) 2006-2008 The Chromium 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 "base/trace_event.h"
+
+#include "base/file_util.h"
+#include "base/path_service.h"
+#include "base/platform_thread.h"
+#include "base/process_util.h"
+#include "base/string_util.h"
+#include "base/time.h"
+
+#define USE_UNRELIABLE_NOW
+
+namespace base {
+
+static const char* kEventTypeNames[] = {
+  "BEGIN",
+  "END",
+  "INSTANT"
+};
+
+static const wchar_t* kLogFileName = L"trace_%d.log";
+
+TraceLog::TraceLog() : enabled_(false), log_file_(NULL) {
+}
+
+TraceLog::~TraceLog() {
+  Stop();
+}
+
+// static
+bool TraceLog::IsTracing() {
+  TraceLog* trace = Singleton<TraceLog>::get();
+  return trace->enabled_;
+}
+
+// static
+bool TraceLog::StartTracing() {
+  TraceLog* trace = Singleton<TraceLog>::get();
+  return trace->Start();
+}
+
+bool TraceLog::Start() {
+  if (enabled_)
+    return true;
+  enabled_ = OpenLogFile();
+  if (enabled_)
+    trace_start_time_ = TimeTicks::Now();
+  return enabled_;
+}
+
+// static
+void TraceLog::StopTracing() {
+  TraceLog* trace = Singleton<TraceLog>::get();
+  return trace->Stop();
+}
+
+void TraceLog::Stop() {
+  if (enabled_) {
+    enabled_ = false;
+    CloseLogFile();
+  }
+}
+
+void TraceLog::CloseLogFile() {
+  if (log_file_) {
+#if defined(OS_WIN)
+    ::CloseHandle(log_file_);
+#elif defined(OS_POSIX)
+    fclose(log_file_);
+#endif
+  }
+}
+
+bool TraceLog::OpenLogFile() {
+  std::wstring pid_filename =
+    StringPrintf(kLogFileName, process_util::GetCurrentProcId());
+  std::wstring log_file_name;
+  PathService::Get(base::DIR_EXE, &log_file_name);
+  file_util::AppendToPath(&log_file_name, pid_filename);
+#if defined(OS_WIN)
+  log_file_ = ::CreateFile(log_file_name.c_str(), GENERIC_WRITE,
+                           FILE_SHARE_READ | FILE_SHARE_WRITE, NULL,
+                           OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL);
+  if (log_file_ == INVALID_HANDLE_VALUE || log_file_ == NULL) {
+    // try the current directory
+    log_file_ = ::CreateFile(pid_filename.c_str(), GENERIC_WRITE,
+                             FILE_SHARE_READ | FILE_SHARE_WRITE, NULL,
+                             OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, NULL);
+    if (log_file_ == INVALID_HANDLE_VALUE || log_file_ == NULL) {
+      log_file_ = NULL;
+      return false;
+    }
+  }
+  ::SetFilePointer(log_file_, 0, 0, FILE_END);
+#elif defined(OS_POSIX)
+  log_file_ = fopen(WideToUTF8(log_file_name).c_str(), "a");
+  if (log_file_ == NULL)
+    return false;
+#endif
+  return true;
+}
+
+void TraceLog::Trace(const std::string& name, 
+                     EventType type,
+                     void* id,
+                     const std::wstring& extra,
+                     const char* file, 
+                     int line) {
+  if (!enabled_)
+    return;
+  Trace(name, type, id, WideToUTF8(extra), file, line);
+}
+
+void TraceLog::Trace(const std::string& name, 
+                     EventType type,
+                     void* id,
+                     const std::string& extra,
+                     const char* file, 
+                     int line) {
+  if (!enabled_)
+    return;
+
+#ifdef USE_UNRELIABLE_NOW
+  TimeTicks tick = TimeTicks::UnreliableHighResNow();
+#else
+  TimeTicks tick = TimeTicks::Now();
+#endif
+  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,
+                 process_util::GetCurrentProcId(),
+                 PlatformThread::CurrentId(),
+                 kEventTypeNames[type],
+                 name.c_str(),
+                 id,
+                 extra.c_str(),
+                 file, 
+                 line);
+
+  Log(msg);
+}
+
+void TraceLog::Log(const std::string& msg) {
+  AutoLock lock(file_lock_);
+
+#if defined (OS_WIN)
+  SetFilePointer(log_file_, 0, 0, SEEK_END);
+  DWORD num;
+  WriteFile(log_file_, (void*)msg.c_str(), (DWORD)msg.length(), &num, NULL);
+#elif defined (OS_POSIX)
+  fprintf(log_file_, "%s", msg.c_str());
+#endif
+}
+
+} // namespace base
+
diff --git a/base/trace_event.h b/base/trace_event.h
new file mode 100644
index 0000000..b01a71e
--- /dev/null
+++ b/base/trace_event.h
@@ -0,0 +1,132 @@
+// Copyright (c) 2006-2008 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+// Trace events to track application performance.  Events consist of a name
+// a type (BEGIN, END or INSTANT), a tracking id and extra string data.
+// In addition, the current process id, thread id, a timestamp down to the
+// microsecond and a file and line number of the calling location.
+//
+// The current implementation logs these events into a log file of the form
+// trace_<pid>.log where it's designed to be post-processed to generate a
+// trace report.  In the future, it may use another mechansim to facilitate
+// real-time analysis.
+
+#ifndef BASE_TRACE_EVENT_H_
+#define BASE_TRACE_EVENT_H_
+
+#include "build/build_config.h"
+
+#if defined(OS_WIN)
+#include <windows.h>
+#endif
+
+#include <string>
+
+#include "base/lock.h"
+#include "base/singleton.h"
+#include "base/time.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:
+// TRACE_EVENT_BEGIN("v8.run", documentId, scriptLocation);
+// RunScript(script);
+// TRACE_EVENT_END("v8.run", documentId, scriptLocation);
+
+#if defined(OS_WIN)
+
+// Record that an event (of name, id) has begun.  All BEGIN events should have
+// corresponding END events with a matching (name, id).
+#define TRACE_EVENT_BEGIN(name, id, extra) \
+  Singleton<base::TraceLog>::get()->Trace(name, \
+                                          base::TraceLog::EVENT_BEGIN, \
+                                          reinterpret_cast<void*>(id), \
+                                          extra, \
+                                          __FILE__, \
+                                          __LINE__)
+
+// Record that an event (of name, id) has ended.  All END events should have
+// corresponding BEGIN events with a matching (name, id).
+#define TRACE_EVENT_END(name, id, extra) \
+  Singleton<base::TraceLog>::get()->Trace(name, \
+                                          base::TraceLog::EVENT_END, \
+                                          reinterpret_cast<void*>(id), \
+                                          extra, \
+                                          __FILE__, \
+                                          __LINE__)
+
+// Record that an event (of name, id) with no duration has happened.
+#define TRACE_EVENT_INSTANT(name, id, extra) \
+  Singleton<base::TraceLog>::get()->Trace(name, \
+                                          base::TraceLog::EVENT_INSTANT, \
+                                          reinterpret_cast<void*>(id), \
+                                          extra, \
+                                          __FILE__, \
+                                          __LINE__)
+#else
+// TODO(erikkay): temporarily disable the macros on other platforms
+// until I can add the files to the other platform build files.
+#define TRACE_EVENT_BEGIN(name, id, extra)
+#define TRACE_EVENT_END(name, id, extra)
+#define TRACE_EVENT_INSTANT(name, id, extra)
+#endif
+
+#if defined(OS_WIN)
+typedef HANDLE FileHandle;
+#else
+typedef FILE* FileHandle;
+#endif
+
+namespace base {
+
+class TraceLog {
+ public:
+  enum EventType {
+    EVENT_BEGIN,
+    EVENT_END,
+    EVENT_INSTANT
+  };
+
+  // Is tracing currently enabled.
+  static bool IsTracing();
+  // Start logging trace events.
+  static bool StartTracing();
+  // Stop logging trace events.
+  static void StopTracing();
+
+  // Log a trace event of (name, type, id) with the optional extra string.
+  void Trace(const std::string& name, 
+             EventType type,
+             void* id,
+             const std::wstring& extra,
+             const char* file, 
+             int line);
+  void Trace(const std::string& name, 
+             EventType type,
+             void* id,
+             const std::string& extra,
+             const char* file, 
+             int line);
+
+ private:
+  // This allows constructor and destructor to be private and usable only
+  // by the Singleton class.
+  friend struct DefaultSingletonTraits<TraceLog>;
+
+  TraceLog();
+  ~TraceLog();
+  bool OpenLogFile();
+  void CloseLogFile();
+  bool Start();
+  void Stop();
+  void Log(const std::string& msg);
+
+  bool enabled_;
+  FileHandle log_file_;
+  Lock file_lock_;
+  TimeTicks trace_start_time_;
+};
+
+} // namespace base
+
+#endif // BASE_TRACE_EVENT_H_
diff --git a/net/base/tcp_client_socket.cc b/net/base/tcp_client_socket.cc
index 9b6959e..fc65995 100644
--- a/net/base/tcp_client_socket.cc
+++ b/net/base/tcp_client_socket.cc
@@ -4,6 +4,8 @@
 
 #include "net/base/tcp_client_socket.h"
 
+#include "base/string_util.h"
+#include "base/trace_event.h"
 #include "net/base/net_errors.h"
 #include "net/base/winsock_init.h"
 
@@ -67,6 +69,7 @@ int TCPClientSocket::Connect(CompletionCallback* callback) {
   if (socket_ != INVALID_SOCKET)
     return OK;
 
+  TRACE_EVENT_BEGIN("socket.connect", this, "");
   const struct addrinfo* ai = current_ai_;
   DCHECK(ai);
 
@@ -80,6 +83,7 @@ int TCPClientSocket::Connect(CompletionCallback* callback) {
   WSAEventSelect(socket_, overlapped_.hEvent, FD_CONNECT);
 
   if (!connect(socket_, ai->ai_addr, static_cast<int>(ai->ai_addrlen))) {
+    TRACE_EVENT_END("socket.connect", this, "");
     // Connected without waiting!
     return OK;
   }
@@ -105,6 +109,8 @@ void TCPClientSocket::Disconnect() {
   if (socket_ == INVALID_SOCKET)
     return;
 
+  TRACE_EVENT_INSTANT("socket.disconnect", this, "");
+
   // Make sure the message loop is not watching this object anymore.
   watcher_.StopWatching();
 
@@ -224,6 +230,7 @@ void TCPClientSocket::DoCallback(int rv) {
 void TCPClientSocket::DidCompleteConnect() {
   int result;
 
+  TRACE_EVENT_END("socket.connect", this, "");
   wait_state_ = NOT_WAITING;
 
   WSANETWORKEVENTS events;
@@ -263,6 +270,13 @@ void TCPClientSocket::DidCompleteIO() {
   BOOL ok = WSAGetOverlappedResult(
       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));
+  } else {
+    TRACE_EVENT_INSTANT("socket.write", this, 
+                        StringPrintf("%d bytes", num_bytes));
+  }
   wait_state_ = NOT_WAITING;
   DoCallback(ok ? num_bytes : MapWinsockError(WSAGetLastError()));
 }
diff --git a/webkit/port/bindings/v8/v8_proxy.cpp b/webkit/port/bindings/v8/v8_proxy.cpp
index 5cfcd62..5ce4607 100644
--- a/webkit/port/bindings/v8/v8_proxy.cpp
+++ b/webkit/port/bindings/v8/v8_proxy.cpp
@@ -97,6 +97,7 @@
 #endif
 
 #include "base/stats_table.h"
+#include "base/trace_event.h"
 #include "webkit/glue/glue_util.h"
 #include "webkit/glue/webkit_glue.h"
 
@@ -960,12 +961,17 @@ v8::Local<v8::Value> V8Proxy::Evaluate(const String& fileName, int baseLine,
 
   // Compile the script.
   v8::Local<v8::String> code = v8ExternalString(str);
+  TRACE_EVENT_BEGIN("v8.compile", n, "");
   v8::Handle<v8::Script> script = CompileScript(code, fileName, baseLine);
+  TRACE_EVENT_END("v8.compile", n, "");
 
   // Set inlineCode to true for <a href="javascript:doSomething()">
   // and false for <script>doSomething</script>. For some reason, fileName
   // gives us this information.
-  return RunScript(script, fileName.isNull());
+  TRACE_EVENT_BEGIN("v8.run", n, "");
+  v8::Local<v8::Value> result = RunScript(script, fileName.isNull());
+  TRACE_EVENT_END("v8.run", n, "");
+  return result;
 }
 
 
diff --git a/webkit/tools/test_shell/test_shell.cc b/webkit/tools/test_shell/test_shell.cc
index fdd8e46..ec8b023 100644
--- a/webkit/tools/test_shell/test_shell.cc
+++ b/webkit/tools/test_shell/test_shell.cc
@@ -24,6 +24,7 @@
 #include "base/path_service.h"
 #include "base/stats_table.h"
 #include "base/string_util.h"
+#include "base/trace_event.h"
 #include "base/win_util.h"
 #include "googleurl/src/url_util.h"
 #include "net/base/mime_util.h"
@@ -816,6 +817,7 @@ void TestShell::LoadURLForFrame(const wchar_t* url,
     if (!url)
         return;
 
+    TRACE_EVENT_BEGIN("url.load", this, WideToUTF8(url));
     bool bIsSVGTest = wcsstr(url, L"W3C-SVG-1.1") > 0;
 
     if (bIsSVGTest) {
diff --git a/webkit/tools/test_shell/test_shell_main.cc b/webkit/tools/test_shell/test_shell_main.cc
index 6117cda..0383424 100644
--- a/webkit/tools/test_shell/test_shell_main.cc
+++ b/webkit/tools/test_shell/test_shell_main.cc
@@ -23,10 +23,12 @@
 #include "base/stack_container.h"
 #include "base/stats_table.h"
 #include "base/string_util.h"
+#include "base/trace_event.h"
 #include "breakpad/src/client/windows/handler/exception_handler.h"
 #include "net/base/cookie_monster.h"
 #include "net/base/net_module.h"
 #include "net/http/http_cache.h"
+#include "net/http/http_network_layer.h"
 #include "net/url_request/url_request_context.h"
 #include "webkit/glue/webkit_glue.h"
 #include "webkit/glue/window_open_disposition.h"
@@ -140,6 +142,14 @@ int main(int argc, char* argv[])
         _set_abort_behavior(0, _WRITE_ABORT_MSG);
     }
 
+    if (parsed_command_line.HasSwitch(test_shell::kEnableTracing))
+      base::TraceLog::StartTracing();
+
+    // Make the selection of network stacks early on before any consumers try to
+    // issue HTTP requests.
+    if (parsed_command_line.HasSwitch(test_shell::kUseNewHttp))
+      net::HttpNetworkLayer::UseWinHttp(false);
+
     bool layout_test_mode =
         parsed_command_line.HasSwitch(test_shell::kLayoutTests);
 
diff --git a/webkit/tools/test_shell/test_shell_switches.cc b/webkit/tools/test_shell/test_shell_switches.cc
index b39c9b7..540e8e6 100644
--- a/webkit/tools/test_shell/test_shell_switches.cc
+++ b/webkit/tools/test_shell/test_shell_switches.cc
@@ -48,5 +48,11 @@ const wchar_t kDebugMemoryInUse[] = L"debug-memory-in-use";
 // Enable cookies on the file:// scheme.  --layout-tests also enables this.
 const wchar_t kEnableFileCookies[] = L"enable-file-cookies";
 
+// Enable new HTTP stack.
+const wchar_t kUseNewHttp[] = L"new-http";
+
+// Enable tracing events (see base/trace_event.h)
+const wchar_t kEnableTracing[] = L"enable-tracing";
+
 }  // namespace test_shell
 
diff --git a/webkit/tools/test_shell/test_shell_switches.h b/webkit/tools/test_shell/test_shell_switches.h
index 9d057c0..7bb9157 100644
--- a/webkit/tools/test_shell/test_shell_switches.h
+++ b/webkit/tools/test_shell/test_shell_switches.h
@@ -24,6 +24,8 @@ extern const wchar_t kDumpStatsTable[];
 extern const wchar_t kCacheDir[];
 extern const wchar_t kDebugMemoryInUse[];
 extern const wchar_t kEnableFileCookies[];
+extern const wchar_t kUseNewHttp[];
+extern const wchar_t kEnableTracing[];
 
 }  // namespace test_shell
 
diff --git a/webkit/tools/test_shell/test_webview_delegate.cc b/webkit/tools/test_shell/test_webview_delegate.cc
index 55f9285..2737ed6 100644
--- a/webkit/tools/test_shell/test_webview_delegate.cc
+++ b/webkit/tools/test_shell/test_webview_delegate.cc
@@ -14,6 +14,7 @@
 #include "base/gfx/point.h"
 #include "base/message_loop.h"
 #include "base/string_util.h"
+#include "base/trace_event.h"
 #include "net/base/net_errors.h"
 #include "webkit/glue/webdatasource.h"
 #include "webkit/glue/webdropdata.h"
@@ -185,12 +186,14 @@ void TestWebViewDelegate::WillSendRequest(WebView* webview,
            request_url.c_str());
   }
 
+  TRACE_EVENT_BEGIN("url.load", identifier, request_url);
   // Set the new substituted URL.
   request->SetURL(GURL(TestShell::RewriteLocalUrl(request_url)));
 }
 
 void TestWebViewDelegate::DidFinishLoading(WebView* webview,
                                            uint32 identifier) {
+  TRACE_EVENT_END("url.load", identifier, "");
   if (shell_->ShouldDumpResourceLoadCallbacks()) {
     printf("%s - didFinishLoading\n",
            GetResourceDescription(identifier).c_str());
@@ -304,6 +307,7 @@ void TestWebViewDelegate::DidReceiveTitle(WebView* webview,
 
 void TestWebViewDelegate::DidFinishLoadForFrame(WebView* webview,
                                                 WebFrame* frame) {
+  TRACE_EVENT_END("frame.load", this, frame->GetURL().spec());
   if (shell_->ShouldDumpFrameLoadCallbacks()) {
     printf("%S - didFinishLoadForFrame\n",
            GetFrameDescription(frame).c_str());