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..a9fcf5c9c6aeacf0e0a06ab7c5d511ea41e5532f
--- /dev/null
+++ b/remoting/test/connection_time_observer.cc
@@ -0,0 +1,137 @@
+// 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"
+#include "remoting/test/test_chromoting_client.h"

[joedow, 2015/07/27 21:45:44]

I don't think this class should know about the TestChromotingClient since the
only thing it uses is a helper method.  May we can put the helper method in the
same file that defines the connection states, that way any code which uses those
states can print nice error messages.

[tonychun, 2015/07/28 17:53:44]

Moved helper method to ConnectionToHostImpl.

+
+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::Initialize() {
+  if (!transition_times_map_.empty()) {
+    LOG(ERROR) << "INITIALIZING state is already initialized";

[joedow, 2015/07/27 21:45:44]

nit: s/is already initialized/has already been set.

[tonychun, 2015/07/28 17:53:44]

Done.

+    return;
+  }
+  transition_times_map_.insert(std::make_pair(
+          protocol::ConnectionToHost::State::INITIALIZING,

[joedow, 2015/07/27 21:45:44]

why not call just call ConectionStateChanged() with initializing and ok from
here.  That way you get the error checking (to prevent double initializing) and
the insert willl be done for you.  This is a good wrapper method but you may as
well call the existing method to do the work for you.

[tonychun, 2015/07/28 17:53:44]

Done.

+          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) << TestChromotingClient::ConnectionStateToFriendlyString(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) {
+  transition_times_map_.insert(
+      std::make_pair(protocol::ConnectionToHost::State::CLOSED,
+                     base::TimeTicks::Now()));

[joedow, 2015/07/27 21:45:44]

What if 'ready' is true?  Then you will still log connection state as 'closed'.

[tonychun, 2015/07/28 17:53:45]

For right now, since I don't have the helper class implemented, I will remove
this and have the helper class cleanly close the connection.

+}
+
+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;

[joedow, 2015/07/27 21:45:44]

if you don't include 'closed' here, this should probably be called
'connected_states'.  You don't need to say 'list_of' since the type is apparent.

[tonychun, 2015/07/28 17:53:45]

Done.

+  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);

[joedow, 2015/07/27 21:45:44]

nit: a comment that the order of the list is important (i.e. that it mimics the
expected order when a connection is made) would be good here.

[tonychun, 2015/07/28 17:53:44]

Done.

+
+  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,
+          TestChromotingClient::ConnectionStateToFriendlyString(current_state),
+          TestChromotingClient::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 "
+            << TestChromotingClient::ConnectionStateToFriendlyString(
+                   current_state) << "): "
+            << GetStateTransitionTime(initializing,
+                                      current_state).InMilliseconds()
+            << " ms";
+  LOG(INFO) << "Total Connection Time (INITIALIZING to CLOSED): "
+            << GetStateTransitionTime(
+                   initializing,
+                   protocol::ConnectionToHost::State::CLOSED).InMilliseconds()
+            << " ms";

[joedow, 2015/07/27 21:45:44]

Do you want to make sure there is a closed state before logging this?  If a
connection was never created then the state may never be added.

[tonychun, 2015/07/28 17:53:45]

Removed. I will implement closing with the helper class, then re-add in the LOG
that I removed.

+}
+
+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 "

[joedow, 2015/07/27 21:45:44]

nit: I like to add a colon (or similar) to the end of the static text so I know
when the dynamic text (error string/state) starts.

[tonychun, 2015/07/28 17:53:45]

Done.

+               << TestChromotingClient::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 "
+               << TestChromotingClient::ConnectionStateToFriendlyString(
+                      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 "
+               << TestChromotingClient::ConnectionStateToFriendlyString(
+                      start_state) << ", end "
+               << TestChromotingClient::ConnectionStateToFriendlyString(
+                      end_state);
+    return base::TimeDelta::Max();
+  }
+
+  return delta;
+}
+
+}  // namespace test
+}  // namespace remoting