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..3c325a8a5633832053c8fcbaee8f9d447730d271
--- /dev/null
+++ b/remoting/test/connection_time_observer.cc
@@ -0,0 +1,114 @@
+// 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"
+
+namespace remoting {
+namespace test {
+
+std::string GetStateAsString(const protocol::ConnectionToHost::State& state) {

[joedow, 2015/07/24 13:38:28]

no need for const ref on the state param.

[tonychun, 2015/07/27 16:03:37]

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() {
+}
+
+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) {
+  transition_times_map_.insert(std::make_pair(state, base::TimeTicks::Now()));

[joedow, 2015/07/24 13:38:28]

Seems like you would want to protect against adding the same state twice (in
case of a future product or test bug).  Perhaps a LOG(ERROR) and early return
would make sense.  

[tonychun, 2015/07/27 16:03:37]

Done.

+  current_connection_state_ = state;
+}
+
+void ConnectionTimeObserver::DisplayConnectionStats() {
+  protocol::ConnectionToHost::State initializing =
+      protocol::ConnectionToHost::State::INITIALIZING;
+  protocol::ConnectionToHost::State current_state = initializing;
+
+  const char kStateChangeTitleFormatString[] = "%-20s%-15s%-15s";
+  LOG(INFO) << base::StringPrintf(kStateChangeTitleFormatString,
+      "State", "Total Time", "Delta Time");
+  LOG(INFO) << base::StringPrintf(kStateChangeTitleFormatString,
+      "-----", "----------", "----------");
+
+  std::vector<protocol::ConnectionToHost::State> list_of_states;
+  list_of_states.push_back(initializing);
+  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);
+  list_of_states.push_back(protocol::ConnectionToHost::State::CLOSED);
+
+  const char kStateChangeFormatString[] = "%-20s%-7ld%-8s%-7ld%-8s";
+  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(state).c_str(),
+          GetStateTransitionDelay(initializing, state).InMilliseconds(), "ms",
+          GetStateTransitionDelay(current_state, state).InMilliseconds(), "ms");

[joedow, 2015/07/24 13:38:28]

This loop prints the difference between initializing and each state, I was
thinking of something a little different:
1.) Print total connection duration (either initializing to connected or
initializing to error (if one occurred)
2.) Print total connection time (initializing to closed/failed)
3.) Print duration for each transition segment (initializing to connecting,
connecting to authenticated, etc)

WIth these stats it will be clear where the most time is being spent and how it
rolls up to the total, with the method above you are making the reader of the
output do more work.

[tonychun, 2015/07/27 16:03:37]

I have added these suggestions. However, I don't think that #2 will serve much
use because we are only really concerned with authentication time and
authenticated to connected time.

+      current_state = state;
+    }
+  }
+}
+
+base::TimeDelta ConnectionTimeObserver::GetStateTransitionDelay(
+    const protocol::ConnectionToHost::State& start_state,
+    const 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. Did you switch the states?";

[joedow, 2015/07/24 13:38:28]

nit: 'Did you switch the states?' is a little strongly worded, I'd suggest
something like 'check the state ordering: start iter_start->second, end
iter_end->second' so that the debug output shows the states passed in so from
the debug log the reader can determine if it is a calling error or a product
error.

[tonychun, 2015/07/27 16:03:37]

Done.

+    return base::TimeDelta::Max();
+  }
+
+  return delta;
+}
+
+}  // namespace test
+}  // namespace remoting