Event tracing for sync events

chrome/browser/sync/syncable/syncable.cc

 // Copyright (c) 2011 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 "chrome/browser/sync/syncable/syncable.h"
 
 #include <algorithm>
 #include <cstring>
 #include <functional>
 #include <iomanip>
 #include <iterator>
 #include <limits>
 #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"
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/perftimer.h"
 #include "base/stl_util.h"
 #include "base/string_number_conversions.h"
 #include "base/string_util.h"
@@ skipping 1095 matching lines @@
 // ScopedKernelLock
 
 ScopedKernelLock::ScopedKernelLock(const Directory* dir)
   :  scoped_lock_(dir->kernel_->mutex), dir_(const_cast<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,
                                  const char* name,
                                  WriterTag writer,
                                  Directory* directory)
     : from_here_(from_here), name_(name), writer_(writer),
       directory_(directory), dirkernel_(directory->kernel_) {
   dirkernel_->observers->Notify(
       &TransactionObserver::OnTransactionStart, from_here_, writer_);

[rlarocque, 2011/11/15 19:45:07]

I'm tempted to remove the OnTransactionStart and OnTransactionEnd events.  These
events are somewhat expensive and impossible to disable.  The trace events will
collect the same information at lower cost and lower latency (we don't need to
wait for the sync thread to be free to get the results).

Are there any objections to removing them?

 }
 
 BaseTransaction::~BaseTransaction() {
   dirkernel_->observers->Notify(
       &TransactionObserver::OnTransactionEnd, from_here_, writer_);
 }
 
 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();
 }
 
 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();
 }
 
 void WriteTransaction::SaveOriginal(const EntryKernel* entry) {
   if (!entry) {
     return;
   }
   // Insert only if it's not already there.
   const int64 handle = entry->ref(META_HANDLE);
   EntryKernelMutationMap::iterator it = mutations_.lower_bound(handle);
@@ skipping 83 matching lines @@
 
   if (OFF != kInvariantCheckLevel) {
     const bool full_scan = (FULL_DB_VERIFICATION == kInvariantCheckLevel);
     if (full_scan)
       directory()->CheckTreeInvariants(this, full_scan);
     else
       directory()->CheckTreeInvariants(this, mutations.Get());
   }
 
   UnlockAndNotify(mutations);
+  TRACE_EVENT_END2("sync", "WriteTransaction",
+                   "src_file", from_here_.file_name(),
+                   "src_func", from_here_.function_name());
 }
 
 ///////////////////////////////////////////////////////////////////////////
 // Entry
 
 Entry::Entry(BaseTransaction* trans, GetById, const Id& id)
     : basetrans_(trans) {
   kernel_ = trans->directory()->GetEntryById(id);
 }
 
@@ skipping 715 matching lines @@
     if (entry->ref(NEXT_ID).IsRoot() ||
         entry->ref(NEXT_ID) != entry->ref(PREV_ID)) {
       return entry;
     }
   }
   // There were no children in the linked list.
   return NULL;
 }
 
 }  // namespace syncable