Added ConnectionTimeObserver to calculate the times to authenticate and connect.

remoting/test/connection_time_observer.cc

Index: remoting/test/connection_time_observer.cc
diff --git a/remoting/test/connection_time_observer.cc b/remoting/test/connection_time_observer.cc
new file mode 100644
index 0000000000000000000000000000000000000000..aae3be8f7b5f0cdded29354e8eac6816999946b1
--- /dev/null
+++ b/remoting/test/connection_time_observer.cc
@@ -0,0 +1,117 @@
+// Copyright 2015 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 "remoting/test/connection_time_observer.h"
+
+#include <utility>
+
+#include "base/strings/stringprintf.h"
+#include "base/time/time.h"
+#include "base/timer/timer.h"
+
+namespace remoting {
+namespace test {
+
+ConnectionTimeObserver::ConnectionTimeObserver() {
+}
+
+ConnectionTimeObserver::~ConnectionTimeObserver() {
+}
+
+void ConnectionTimeObserver::SetTransitionTimesMapForTest(
+    const std::map<protocol::ConnectionToHost::State, base::TimeTicks>& map) {
+  transition_times_map_ = map;
+}
+
+void ConnectionTimeObserver::ConnectionStateChanged(
+    protocol::ConnectionToHost::State state,
+    protocol::ErrorCode error_code) {
+  if (transition_times_map_.find(state) != transition_times_map_.end()) {
+    LOG(ERROR) << protocol::ConnectionToHost::ConnectionStateToFriendlyString(
+                      state) << " state has already been set";

[joedow, 2015/07/29 17:07:02]

Can you fix the indentation here.  Alternatively you could save this state into
a string and just clean up this statement.

[tonychun, 2015/07/29 18:30:33]

Done.

+    return;
+  }
+  transition_times_map_.insert(std::make_pair(state, base::TimeTicks::Now()));
+  current_connection_state_ = state;
+}
+
+void ConnectionTimeObserver::DisplayConnectionStats() const {
+  protocol::ConnectionToHost::State initializing =
+      protocol::ConnectionToHost::State::INITIALIZING;
+  protocol::ConnectionToHost::State current_state = initializing;
+
+  const char kStateChangeTitleFormatString[] = "%-35s%-15s";
+  LOG(INFO) << base::StringPrintf(kStateChangeTitleFormatString,
+      "State to State", "Delta Time");
+  LOG(INFO) << base::StringPrintf(kStateChangeTitleFormatString,
+      "--------------", "----------");
+
+  // Note: the order of |connected_states| mimics the expected order of when a
+  // connection is made.
+  std::vector<protocol::ConnectionToHost::State> connected_states;
+  connected_states.push_back(protocol::ConnectionToHost::State::CONNECTING);
+  connected_states.push_back(protocol::ConnectionToHost::State::AUTHENTICATED);
+  connected_states.push_back(protocol::ConnectionToHost::State::CONNECTED);
+  connected_states.push_back(protocol::ConnectionToHost::State::FAILED);
+
+  const char kStateChangeFormatString[] = "%-13s to %-18s%-7dms";
+  auto iter_end = transition_times_map_.end();
+  for (protocol::ConnectionToHost::State state : connected_states) {
+    auto iter_state = transition_times_map_.find(state);
+    if (iter_state != iter_end) {
+      LOG(INFO) << base::StringPrintf(kStateChangeFormatString,
+          protocol::ConnectionToHost::ConnectionStateToFriendlyString(
+              current_state),
+          protocol::ConnectionToHost::ConnectionStateToFriendlyString(state),
+          static_cast<int>(GetStateTransitionTime(current_state,
+                                                  state).InMilliseconds()));
+      current_state = state;
+    }
+  }
+
+  // |current state| will either be FAILED or CONNECTED.
+  LOG(INFO) << "Total Connection Duration (INITIALIZING to "
+            << protocol::ConnectionToHost::ConnectionStateToFriendlyString(
+                   current_state) << "): "
+            << GetStateTransitionTime(initializing,
+                                      current_state).InMilliseconds() << " ms";

[joedow, 2015/07/29 17:07:02]

The indentation is kind of distracting here, can you clean it up?

[tonychun, 2015/07/29 18:30:33]

Done.

+}
+
+base::TimeDelta ConnectionTimeObserver::GetStateTransitionTime(
+    protocol::ConnectionToHost::State start_state,
+    protocol::ConnectionToHost::State end_state) const {
+  auto iter_end = transition_times_map_.end();
+
+  auto iter_start_state = transition_times_map_.find(start_state);
+  if (iter_start_state == iter_end) {
+    LOG(ERROR) << "No time found for state: "
+               << protocol::ConnectionToHost::ConnectionStateToFriendlyString(
+                      start_state);
+    return base::TimeDelta::Max();
+  }
+
+  auto iter_end_state = transition_times_map_.find(end_state);
+  if (iter_end_state == iter_end) {
+    LOG(ERROR) << "No time found for state: "
+               << protocol::ConnectionToHost::ConnectionStateToFriendlyString(

[joedow, 2015/07/29 17:07:02]

Using a static method on ConnectionToHost to generate the string is really
causing readability issues for me.  We should consider either getting the string
before the log message, moving the helper method out of 'ConnectionToHost' and
into the namespace, or perhaps shortening the method name.

[tonychun, 2015/07/29 18:30:33]

Done.

+                      end_state);
+    return base::TimeDelta::Max();
+  }
+
+  base::TimeDelta delta = iter_end_state->second - iter_start_state->second;
+  if (delta.InMilliseconds() < 0) {
+    LOG(ERROR) << "Transition delay is negative. Check the state ordering: "
+               << "[start: "
+               << protocol::ConnectionToHost::ConnectionStateToFriendlyString(
+                      start_state) << ", end: "
+               << protocol::ConnectionToHost::ConnectionStateToFriendlyString(
+                      end_state) << "]";
+    return base::TimeDelta::Max();
+  }
+
+  return delta;
+}
+
+}  // namespace test
+}  // namespace remoting