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_);
 }
 
 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",

[akalin, 2011/11/17 03:27:21]

What about adding the trace events to BaseTransaction/~BaseTransaction instead?

We already pass in a name to BaseTransaction.  If you change the passed-in names
to "ReadTransaction"/"WriteTransaction", you can then do:

BaseTransaction::BaseTransaction(...) : ... {
  TRACE_EVENT_BEGIN2("sync", name_, "src_file", ...);
  ...
}

and similarly in the destructor.

[rlarocque, 2011/11/17 19:37:53]

I originally wanted to do it that way, but couldn't.  The TRACE_EVENT macros
only handle two arguments.  I think there's a cost associated with supporting
more arguments, so it's probably not a simple matter to add more.  

That being said, I'm pretty happy with how it turned out.  It's nice to see the
type of transaction displayed prominently in the UI.  

[akalin, 2011/11/17 22:17:45]

I'm not sure what you mean; my suggestion doesn't involve adding extra
arguments, but simply replacing the 'name' parameter to the macro with the name
parameter passed into BaseTransaction's constructor.

+                     "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_END0("sync", "ReadTransaction");
 }
 
 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_END0("sync", "WriteTransaction");
 }
 
 ///////////////////////////////////////////////////////////////////////////
 // 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