Event tracing for sync events

chrome/browser/sync/engine/syncer.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/engine/syncer.h"
 
+#include "base/debug/trace_event.h"
 #include "base/location.h"
 #include "base/message_loop.h"
 #include "base/time.h"
 #include "chrome/browser/sync/engine/apply_updates_command.h"
 #include "chrome/browser/sync/engine/build_and_process_conflict_sets_command.h"
 #include "chrome/browser/sync/engine/build_commit_command.h"
 #include "chrome/browser/sync/engine/cleanup_disabled_types_command.h"
 #include "chrome/browser/sync/engine/clear_data_command.h"
 #include "chrome/browser/sync/engine/conflict_resolver.h"
 #include "chrome/browser/sync/engine/download_updates_command.h"
@@ skipping 30 matching lines @@
 using syncable::ScopedDirLookup;
 using syncable::WriteTransaction;
 
 namespace browser_sync {
 
 using sessions::ScopedSessionContextConflictResolver;
 using sessions::StatusController;
 using sessions::SyncSession;
 using sessions::ConflictProgress;
 
+#define ENUM_CASE(x) case x: return #x; break
+const char* SyncerStepToString(const SyncerStep step)
+{
+  switch (step) {
+    ENUM_CASE(SYNCER_BEGIN);
+    ENUM_CASE(CLEANUP_DISABLED_TYPES);
+    ENUM_CASE(DOWNLOAD_UPDATES);
+    ENUM_CASE(PROCESS_CLIENT_COMMAND);
+    ENUM_CASE(VERIFY_UPDATES);
+    ENUM_CASE(PROCESS_UPDATES);
+    ENUM_CASE(STORE_TIMESTAMPS);
+    ENUM_CASE(APPLY_UPDATES);
+    ENUM_CASE(BUILD_COMMIT_REQUEST);
+    ENUM_CASE(POST_COMMIT_MESSAGE);
+    ENUM_CASE(PROCESS_COMMIT_RESPONSE);
+    ENUM_CASE(BUILD_AND_PROCESS_CONFLICT_SETS);
+    ENUM_CASE(RESOLVE_CONFLICTS);
+    ENUM_CASE(APPLY_UPDATES_TO_RESOLVE_CONFLICTS);
+    ENUM_CASE(CLEAR_PRIVATE_DATA);
+    ENUM_CASE(SYNCER_END);
+  }
+}
+#undef ENUM_CASE
+
 Syncer::ScopedSyncStartStopTracker::ScopedSyncStartStopTracker(
     sessions::SyncSession* session) : session_(session) {
   session_->status_controller()->SetSyncInProgressAndUpdateStartTime(true);
 }
 
 Syncer::ScopedSyncStartStopTracker::~ScopedSyncStartStopTracker() {
   session_->status_controller()->SetSyncInProgressAndUpdateStartTime(false);
 }
 
 Syncer::Syncer()
@@ skipping 24 matching lines @@
   }
 
   ScopedSessionContextConflictResolver scoped(session->context(),
                                               &resolver_);
 
   ScopedSyncStartStopTracker start_stop_tracker(session);
   SyncerStep current_step = first_step;
 
   SyncerStep next_step = current_step;
   while (!ExitRequested()) {
+    TRACE_EVENT_BEGIN1("sync", "SyncerStateMachine",

[jbates, 2011/11/16 00:46:57]

If you change this to TRACE_EVENT1 instead of TRACE_EVENT_BEGIN1, it will
automatically end when the scope ends (and then you wouldn't need the
TRACE_EVENT_END1 below).

[rlarocque, 2011/11/16 01:03:40]

I had considered that, but decided against it.  I was worried that the fact that
the 'current_step' will have changed by the time we leave the scope could have
confused the system.  I thought the parameters for BEGIN and END were supposed
to match perfectly.  

I take it from you other comments that this is not the case.  I think I will use
scoped events here.  

+                       "state", SyncerStepToString(current_step));
+    VLOG(1) << "Syncer step:" << SyncerStepToString(current_step);
+
     switch (current_step) {
       case SYNCER_BEGIN:
-        VLOG(1) << "Syncer Begin";
         // This isn't perfect, as we can end up bundling extensions activity
         // intended for the next session into the current one.  We could do a
         // test-and-reset as with the source, but note that also falls short if
         // the commit request fails (e.g. due to lost connection), as we will
         // fall all the way back to the syncer thread main loop in that case,
         // creating a new session when a connection is established, losing the
         // records set here on the original attempt.  This should provide us
         // with the right data "most of the time", and we're only using this
         // for analysis purposes, so Law of Large Numbers FTW.
         session->context()->extensions_monitor()->GetAndClearRecords(
             session->mutable_extensions_activity());
         next_step = CLEANUP_DISABLED_TYPES;
         break;
       case CLEANUP_DISABLED_TYPES: {
-        VLOG(1) << "Cleaning up disabled types";
         CleanupDisabledTypesCommand cleanup;
         cleanup.Execute(session);
         next_step = DOWNLOAD_UPDATES;
         break;
       }
       case DOWNLOAD_UPDATES: {
-        VLOG(1) << "Downloading Updates";
         DownloadUpdatesCommand download_updates;
         download_updates.Execute(session);
         next_step = PROCESS_CLIENT_COMMAND;
         break;
       }
       case PROCESS_CLIENT_COMMAND: {
-        VLOG(1) << "Processing Client Command";
         ProcessClientCommand(session);
         next_step = VERIFY_UPDATES;
         break;
       }
       case VERIFY_UPDATES: {
-        VLOG(1) << "Verifying Updates";
         VerifyUpdatesCommand verify_updates;
         verify_updates.Execute(session);
         next_step = PROCESS_UPDATES;
         break;
       }
       case PROCESS_UPDATES: {
-        VLOG(1) << "Processing Updates";
         ProcessUpdatesCommand process_updates;
         process_updates.Execute(session);
         next_step = STORE_TIMESTAMPS;
         break;
       }
       case STORE_TIMESTAMPS: {
-        VLOG(1) << "Storing timestamps";
         StoreTimestampsCommand store_timestamps;
         store_timestamps.Execute(session);
         // We should download all of the updates before attempting to process
         // them.
         if (session->status_controller()->ServerSaysNothingMoreToDownload() ||
             !session->status_controller()->download_updates_succeeded()) {
           next_step = APPLY_UPDATES;
         } else {
           next_step = DOWNLOAD_UPDATES;
         }
         break;
       }
       case APPLY_UPDATES: {
-        VLOG(1) << "Applying Updates";
         ApplyUpdatesCommand apply_updates;
         apply_updates.Execute(session);
         if (last_step == APPLY_UPDATES) {
           // We're in configuration mode, but we still need to run the
           // SYNCER_END step.
           last_step = SYNCER_END;
           next_step = SYNCER_END;
         } else {
           next_step = BUILD_COMMIT_REQUEST;
         }
         break;
       }
       // These two steps are combined since they are executed within the same
       // write transaction.
       case BUILD_COMMIT_REQUEST: {
-        VLOG(1) << "Processing Commit Request";
         ScopedDirLookup dir(session->context()->directory_manager(),
                             session->context()->account_name());
         if (!dir.good()) {
           LOG(ERROR) << "Scoped dir lookup failed!";
           return;
         }
         WriteTransaction trans(FROM_HERE, SYNCER, dir);
         sessions::ScopedSetSessionWriteTransaction set_trans(session, &trans);
 
         VLOG(1) << "Getting the Commit IDs";
         GetCommitIdsCommand get_commit_ids_command(
             session->context()->max_commit_batch_size());
         get_commit_ids_command.Execute(session);
 
         if (!session->status_controller()->commit_ids().empty()) {
           VLOG(1) << "Building a commit message";
           BuildCommitCommand build_commit_command;
           build_commit_command.Execute(session);
 
           next_step = POST_COMMIT_MESSAGE;
         } else {
           next_step = BUILD_AND_PROCESS_CONFLICT_SETS;
         }
 
         break;
       }
       case POST_COMMIT_MESSAGE: {
-        VLOG(1) << "Posting a commit request";
         PostCommitMessageCommand post_commit_command;
         post_commit_command.Execute(session);
         next_step = PROCESS_COMMIT_RESPONSE;
         break;
       }
       case PROCESS_COMMIT_RESPONSE: {
-        VLOG(1) << "Processing the commit response";
         session->status_controller()->reset_num_conflicting_commits();
         ProcessCommitResponseCommand process_response_command;
         process_response_command.Execute(session);
         next_step = BUILD_AND_PROCESS_CONFLICT_SETS;
         break;
       }
       case BUILD_AND_PROCESS_CONFLICT_SETS: {
-        VLOG(1) << "Building and Processing Conflict Sets";
         BuildAndProcessConflictSetsCommand build_process_conflict_sets;
         build_process_conflict_sets.Execute(session);
         if (session->status_controller()->conflict_sets_built())
           next_step = SYNCER_END;
         else
           next_step = RESOLVE_CONFLICTS;
         break;
       }
       case RESOLVE_CONFLICTS: {
-        VLOG(1) << "Resolving Conflicts";
 
         // Trigger the pre_conflict_resolution_closure_, which is a testing
         // hook for the unit tests, if it is non-NULL.
         if (pre_conflict_resolution_closure_) {
           pre_conflict_resolution_closure_->Run();
         }
 
         StatusController* status = session->status_controller();
         status->reset_conflicts_resolved();
         ResolveConflictsCommand resolve_conflicts_command;
@@ skipping 22 matching lines @@
             status->TotalNumBlockingConflictingItems();
         status->update_conflicts_resolved(before_blocking_conflicting_updates >
                                           after_blocking_conflicting_updates);
         if (status->conflicts_resolved())
           next_step = RESOLVE_CONFLICTS;
         else
           next_step = SYNCER_END;
         break;
       }
       case CLEAR_PRIVATE_DATA: {
-        VLOG(1) << "Clear Private Data";
         ClearDataCommand clear_data_command;
         clear_data_command.Execute(session);
         next_step = SYNCER_END;
         break;
       }
       case SYNCER_END: {
-        VLOG(1) << "Syncer End";
         SyncerEndCommand syncer_end_command;
         syncer_end_command.Execute(session);
         next_step = SYNCER_END;
         break;
       }
       default:
         LOG(ERROR) << "Unknown command: " << current_step;
     }
-    VLOG(2) << "last step: " << last_step << ", current step: "
-            << current_step << ", next step: "
-            << next_step << ", snapshot: "
-            << session->TakeSnapshot().ToString();
+    VLOG(2) << "last step: " << SyncerStepToString(last_step) << ", "
+        << "current step: " << SyncerStepToString(current_step) << ", "
+        << "next step: " << SyncerStepToString(next_step) << ", "
+        << "snapshot: " << session->TakeSnapshot().ToString();
+    TRACE_EVENT_END1("sync", "SyncerStateMachine",

[jbates, 2011/11/16 00:46:57]

Could remove this as mentioned above.

+                     "state", SyncerStepToString(current_step));
     if (last_step == current_step)
       break;
     current_step = next_step;
   }
 }
 
 void Syncer::ProcessClientCommand(sessions::SyncSession* session) {
   const ClientToServerResponse& response =
       session->status_controller()->updates_response();
   if (!response.has_client_command())
@@ skipping 40 matching lines @@
   entry->Put(SERVER_CTIME, Time());
   entry->Put(SERVER_VERSION, 0);
   entry->Put(SERVER_IS_DIR, false);
   entry->Put(SERVER_IS_DEL, false);
   entry->Put(IS_UNAPPLIED_UPDATE, false);
   entry->Put(SERVER_SPECIFICS, sync_pb::EntitySpecifics::default_instance());
   entry->Put(SERVER_POSITION_IN_PARENT, 0);
 }
 
 }  // namespace browser_sync