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

3 files changed, 303 insertions, 2 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_