sync: Improve ModelAssociation event tracing

chrome/browser/sync/glue/model_association_manager.cc

 // Copyright (c) 2012 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/glue/model_association_manager.h"
 
 #include <algorithm>
 #include <functional>
 
 #include "base/debug/trace_event.h"
@@ skipping 222 matching lines @@
   if (state_ == CONFIGURING) {
     DVLOG(1) << "ModelAssociationManager: In the middle of configuration while"
              << " stopping";
     state_ = ABORTED;
     DCHECK(currently_associating_ != NULL ||
            needs_start_.size() > 0 ||
            pending_model_load_.size() > 0 ||
            waiting_to_associate_.size() > 0);
 
     if (currently_associating_) {
-      TRACE_EVENT_END0("sync", "ModelAssociation");
+      TRACE_EVENT_ASYNC_END1("sync", "ModelAssociation",
+                             "DataType",
+                             ModelTypeToString(currently_associating_->type()),
+                             currently_associating_);
       DVLOG(1) << "ModelAssociationManager: stopping "
                << currently_associating_->name();
       currently_associating_->Stop();
     } else {
       // DTCs in other lists would be stopped below.
       state_ = IDLE;
     }
 
     DCHECK_EQ(IDLE, state_);
 
@@ skipping 63 matching lines @@
   UMA_HISTOGRAM_ENUMERATION("Sync.ConfigureFailed",
                             ModelTypeToHistogramInt(error.model_type()),
                             syncer::MODEL_TYPE_COUNT);
 }
 
 void ModelAssociationManager::TypeStartCallback(
     DataTypeController::StartResult start_result,
     const syncer::SyncMergeResult& local_merge_result,
     const syncer::SyncMergeResult& syncer_merge_result) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
-  TRACE_EVENT_END0("sync", "ModelAssociation");
+  TRACE_EVENT_ASYNC_END1("sync", "ModelAssociation",
+                         "DataType",
+                         ModelTypeToString(currently_associating_->type()),
+                         currently_associating_);
 
   DVLOG(1) << "ModelAssociationManager: TypeStartCallback";
   if (state_ == ABORTED) {
     // Now that we have finished with the current type we can stop
     // if abort was called.
     DVLOG(1) << "ModelAssociationManager: Doing an early return"
              << " because of abort";
     state_ = IDLE;
     return;
   }
@@ skipping 168 matching lines @@
 }
 
 void ModelAssociationManager::StartAssociatingNextType() {
   DCHECK_EQ(state_, CONFIGURING);
   DCHECK_EQ(currently_associating_, static_cast<DataTypeController*>(NULL));
 
   DVLOG(1) << "ModelAssociationManager: StartAssociatingNextType";
   if (!waiting_to_associate_.empty()) {
     DVLOG(1) << "ModelAssociationManager: Starting "
             << waiting_to_associate_[0]->name();
-    TRACE_EVENT_BEGIN1("sync", "ModelAssociation",
-                       "DataType",
-                       ModelTypeToString(waiting_to_associate_[0]->type()));
     DataTypeController* dtc = waiting_to_associate_[0];
     waiting_to_associate_.erase(waiting_to_associate_.begin());
     currently_associating_ = dtc;
     current_type_association_start_time_ = base::Time::Now();
+    TRACE_EVENT_ASYNC_BEGIN1("sync", "ModelAssociation",
+                             "DataType",
+                             ModelTypeToString(currently_associating_->type()),
+                             currently_associating_);

[Raghu Simha, 2013/09/07 00:20:18]

I think the order of arguments in these calls is incorrect.

When TRACE_EVENT_BEGIN1 was being called, "DataType" corresponded to the
"arg1_name" parameter, and the model type string to "arg1_val".

In the new version where TRACE_EVENT_ASYNC_BEGIN1 is being called, "DataType"
now corresponds to the "id" parameter, the model type string to "arg1_name", and
the DTC pointer to "arg1_value".

I think |currently_associating_| ought to be the third argument in all three
calls.

     dtc->StartAssociating(base::Bind(
         &ModelAssociationManager::TypeStartCallback,
         weak_ptr_factory_.GetWeakPtr()));
     return;
   }
 
   // We are done with this cycle of association. Stop any failed types now.
   needs_stop_.clear();
   for (DataTypeController::TypeMap::const_iterator it = controllers_->begin();
        it != controllers_->end(); ++it) {
@@ skipping 39 matching lines @@
   }
   return result;
 }
 
 base::OneShotTimer<ModelAssociationManager>*
     ModelAssociationManager::GetTimerForTesting() {
   return &timer_;
 }
 
 }  // namespace browser_sync