Event tracing for sync events

chrome/browser/sync/syncable/syncable.cc

Index: chrome/browser/sync/syncable/syncable.cc
diff --git a/chrome/browser/sync/syncable/syncable.cc b/chrome/browser/sync/syncable/syncable.cc
index efeecaf94440d8411742f63c28016e9bca6a3ec6..aa49815e7cbd653bb7b870fa070ef47a203a8342 100644
--- a/chrome/browser/sync/syncable/syncable.cc
+++ b/chrome/browser/sync/syncable/syncable.cc
@@ -13,6 +13,7 @@
 #include <set>
 #include <string>
 
+#include "base/debug/trace_event.h"
 #include "base/compiler_specific.h"
 #include "base/file_util.h"
 #include "base/hash_tables.h"
@@ -1128,23 +1129,15 @@ ScopedKernelLock::ScopedKernelLock(const Directory* dir)
 // Transactions
 
 void BaseTransaction::Lock() {
-  base::TimeTicks start_time = base::TimeTicks::Now();
+  TRACE_EVENT2("sync_lock_contention", "AcquireLock",
+               "src_file", from_here_.file_name(),
+               "src_func", from_here_.function_name());
 
   dirkernel_->transaction_mutex.Acquire();
-
-  time_acquired_ = base::TimeTicks::Now();
-  const base::TimeDelta elapsed = time_acquired_ - start_time;
-  VLOG_LOC(from_here_, 2)
-      << name_ << " transaction waited "
-      << elapsed.InSecondsF() << " seconds.";
 }
 
 void BaseTransaction::Unlock() {
   dirkernel_->transaction_mutex.Release();
-  const base::TimeDelta elapsed = base::TimeTicks::Now() - time_acquired_;
-  VLOG_LOC(from_here_, 2)
-        << name_ << " transaction completed in " << elapsed.InSecondsF()
-        << " seconds.";
 }
 
 BaseTransaction::BaseTransaction(const tracked_objects::Location& from_here,
@@ -1165,22 +1158,34 @@ BaseTransaction::~BaseTransaction() {
 ReadTransaction::ReadTransaction(const tracked_objects::Location& location,
                                  Directory* directory)
     : BaseTransaction(location, "Read", INVALID, directory) {
+  TRACE_EVENT_BEGIN2("sync", "ReadTransaction",
+                     "src_file", from_here_.file_name(),
+                     "src_func", from_here_.function_name());
   Lock();
 }
 
 ReadTransaction::ReadTransaction(const tracked_objects::Location& location,
                                  const ScopedDirLookup& scoped_dir)
     : BaseTransaction(location, "Read", INVALID, scoped_dir.operator->()) {
+  TRACE_EVENT_BEGIN2("sync", "ReadTransaction",
+                     "src_file", from_here_.file_name(),
+                     "src_func", from_here_.function_name());
   Lock();
 }
 
 ReadTransaction::~ReadTransaction() {
   Unlock();
+  TRACE_EVENT_END2("sync", "ReadTransaction",
+                   "src_file", from_here_.file_name(),
+                   "src_func", from_here_.function_name());
 }
 
 WriteTransaction::WriteTransaction(const tracked_objects::Location& location,
                                    WriterTag writer, Directory* directory)
     : BaseTransaction(location, "Write", writer, directory) {
+  TRACE_EVENT_BEGIN2("sync", "WriteTransaction",
+                     "src_file", from_here_.file_name(),
+                     "src_func", from_here_.function_name());
   Lock();
 }
 
@@ -1188,6 +1193,9 @@ WriteTransaction::WriteTransaction(const tracked_objects::Location& location,
                                    WriterTag writer,
                                    const ScopedDirLookup& scoped_dir)
     : BaseTransaction(location, "Write", writer, scoped_dir.operator->()) {
+  TRACE_EVENT_BEGIN2("sync", "WriteTransaction",
+                     "src_file", from_here_.file_name(),
+                     "src_func", from_here_.function_name());
   Lock();
 }
 
@@ -1291,6 +1299,9 @@ WriteTransaction::~WriteTransaction() {
   }
 
   UnlockAndNotify(mutations);
+  TRACE_EVENT_END2("sync", "WriteTransaction",
+                   "src_file", from_here_.file_name(),
+                   "src_func", from_here_.function_name());
 }
 
 ///////////////////////////////////////////////////////////////////////////