sync: Improve ModelAssociation event tracing

chrome/browser/sync/glue/model_association_manager.cc

Index: chrome/browser/sync/glue/model_association_manager.cc
diff --git a/chrome/browser/sync/glue/model_association_manager.cc b/chrome/browser/sync/glue/model_association_manager.cc
index f37fd63390c6566e8ecc727bc3b1f42bee661a20..995c943213729116c60eae65525a0df119ce5da8 100644
--- a/chrome/browser/sync/glue/model_association_manager.cc
+++ b/chrome/browser/sync/glue/model_association_manager.cc
@@ -240,7 +240,10 @@ void ModelAssociationManager::Stop() {
            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();
@@ -324,7 +327,10 @@ void ModelAssociationManager::TypeStartCallback(
     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) {
@@ -513,13 +519,14 @@ void 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()));