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..779c8ab200e2ca49524be04c8973c4a5372b35c6
--- /dev/null
+++ b/remoting/test/connection_time_observer.cc
@@ -0,0 +1,153 @@
+// 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 {
+
+std::string GetStateAsString(protocol::ConnectionToHost::State state) {

[anandc, 2015/07/27 18:22:29]

ConnectionStateToFriendlyString, as defined here:
https://code.google.com/p/chromium/codesearch#chromium/src/remoting/test/test...
?

[tonychun, 2015/07/27 21:20:42]

Done.

+  switch (state) {
+    case protocol::ConnectionToHost::State::INITIALIZING:
+      return "INITIALIZING";
+    case protocol::ConnectionToHost::State::CONNECTING:
+      return "CONNECTING";
+    case protocol::ConnectionToHost::State::AUTHENTICATED:
+      return "AUTHENTICATED";
+    case protocol::ConnectionToHost::State::CONNECTED:
+      return "CONNECTED";
+    case protocol::ConnectionToHost::State::FAILED:
+      return "FAILED";
+    case protocol::ConnectionToHost::State::CLOSED:
+      return "CLOSED";
+    default:
+      LOG(ERROR) << "Unknown state: " << state;
+      NOTREACHED();
+      return std::string();
+  }
+}
+
+ConnectionTimeObserver::ConnectionTimeObserver(base::Timer* timer)
+    : timer_(timer) {
+}
+
+ConnectionTimeObserver::~ConnectionTimeObserver() {
+}
+
+void ConnectionTimeObserver::SetTransitionTimesMapForTest(
+    const std::map<protocol::ConnectionToHost::State, base::TimeTicks>& map) {
+  transition_times_map_ = map;
+}
+
+void ConnectionTimeObserver::SetInitializingState() {
+  if (!transition_times_map_.empty()) {
+    LOG(ERROR) << "INITIALIZING state is already initialized";
+    return;
+  }
+  transition_times_map_.insert(std::make_pair(
+          protocol::ConnectionToHost::State::INITIALIZING,
+          base::TimeTicks::Now()));
+}
+
+void ConnectionTimeObserver::ConnectionStateChanged(
+    protocol::ConnectionToHost::State state,
+    protocol::ErrorCode error_code) {
+  if (transition_times_map_.find(state) != transition_times_map_.end()) {
+    LOG(ERROR) << GetStateAsString(state) << " state is already initialized";
+    return;
+  }
+  transition_times_map_.insert(std::make_pair(state, base::TimeTicks::Now()));
+  current_connection_state_ = state;
+}
+
+void ConnectionTimeObserver::ConnectionReady(bool ready) {
+  // TODO(TonyChun): Currently, this performance check does not have any tests
+  // to run, so I will save the CLOSED state here. Normally, the CLOSED state
+  // will be saved when a test completes a chromoting connection to a host.

[anandc, 2015/07/27 18:22:29]

Do you mean "when a test terminates a Chromoting connection"?

[tonychun, 2015/07/27 21:20:42]

Done.

+  transition_times_map_.insert(
+      std::make_pair(protocol::ConnectionToHost::State::CLOSED,
+                     base::TimeTicks::Now()));
+  timer_->user_task().Run();

[joedow, 2015/07/27 16:25:39]

If you are trying to get to the QuitClosure() to signal the connection is ready,
then I think you should just use that type.  Passing the timer around is a lot
of overhead for little benefit.  Also, this class is should handle gathering and
reporting performance metrics, it shouldn't be signaling connection state
changes.

[tonychun, 2015/07/27 21:20:42]

I will remove this and create a helper class to handle signaling connection
state changes.

+}
+
+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,
+      "--------------", "----------");
+
+  std::vector<protocol::ConnectionToHost::State> list_of_states;
+  list_of_states.push_back(protocol::ConnectionToHost::State::CONNECTING);
+  list_of_states.push_back(protocol::ConnectionToHost::State::AUTHENTICATED);
+  list_of_states.push_back(protocol::ConnectionToHost::State::CONNECTED);
+  list_of_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 : list_of_states) {
+    auto iter_state = transition_times_map_.find(state);
+    if (iter_state != iter_end) {
+      LOG(INFO) << base::StringPrintf(kStateChangeFormatString,
+          GetStateAsString(current_state).c_str(),
+          GetStateAsString(state).c_str(),
+          static_cast<int>(GetStateTransitionDelayTimeDelta(current_state,
+                                                 state).InMilliseconds()));
+      current_state = state;
+    }
+  }
+
+  // |current state| will either be FAILED or CONNECTED.
+  LOG(INFO) << "Total Connection Duration (INITIALIZING to "
+            << GetStateAsString(current_state) << "): "
+            << GetStateTransitionDelayTimeDelta(initializing,
+                                                current_state).InMilliseconds()
+            << " ms";
+  LOG(INFO) << "Total Connection Time (INITIALIZING to CLOSED): "
+            << GetStateTransitionDelayTimeDelta(
+                   initializing,
+                   protocol::ConnectionToHost::State::CLOSED).InMilliseconds()
+            << " ms";
+}
+
+base::TimeDelta ConnectionTimeObserver::GetStateTransitionDelayTimeDelta(
+    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 " << GetStateAsString(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 " << GetStateAsString(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 " << GetStateAsString(start_state)
+               << ", end " << GetStateAsString(end_state);
+    return base::TimeDelta::Max();
+  }
+
+  return delta;
+}
+
+}  // namespace test
+}  // namespace remoting