Added ConnectionTimeObserver to provide a way to calculate times betw…

…een the different stages.

The ConnectionTimeObserver saves the state of the client and the time when the client state changes. The delta times can be accessed through GetStateTransitionDelay and a start and end state.

BUG=

Review URL: https://codereview.chromium.org/1238343002

Cr-Commit-Position: refs/heads/master@{#341232}

remoting/client/plugin/chromoting_instance.cc

@@ -98,27 +98,6 @@ const int kBandwidthHistogramBuckets = 100;
 const int kRandomSeedSize = 1024;
 #endif  // defined(USE_OPENSSL)
 
-std::string ConnectionStateToString(protocol::ConnectionToHost::State state) {
-  // Values returned by this function must match the
-  // remoting.ClientSession.State enum in JS code.
-  switch (state) {
-    case protocol::ConnectionToHost::INITIALIZING:
-      return "INITIALIZING";
-    case protocol::ConnectionToHost::CONNECTING:
-      return "CONNECTING";
-    case protocol::ConnectionToHost::AUTHENTICATED:
-      return "AUTHENTICATED";
-    case protocol::ConnectionToHost::CONNECTED:
-      return "CONNECTED";
-    case protocol::ConnectionToHost::CLOSED:
-      return "CLOSED";
-    case protocol::ConnectionToHost::FAILED:
-      return "FAILED";
-  }
-  NOTREACHED();
-  return std::string();
-}
-
 // TODO(sergeyu): Ideally we should just pass ErrorCode to the webapp
 // and let it handle it, but it would be hard to fix it now because
 // client plugin and webapp versions may not be in sync. It should be
@@ -486,7 +465,7 @@ void ChromotingInstance::OnConnectionState(
     protocol::ConnectionToHost::State state,
     protocol::ErrorCode error) {
   scoped_ptr<base::DictionaryValue> data(new base::DictionaryValue());
-  data->SetString("state", ConnectionStateToString(state));
+  data->SetString("state", protocol::ConnectionToHost::StateToString(state));
   data->SetString("error", ConnectionErrorToString(error));
   PostLegacyJsonMessage("onConnectionStatus", data.Pass());
 }

remoting/protocol/connection_to_host.h

@@ -46,6 +46,9 @@ class ConnectionToHost {
     CLOSED,
   };
 
+  // Returns the literal string of |state|.
+  static const char* StateToString(State state);
+
   class HostEventCallback {
    public:
     virtual ~HostEventCallback() {}

remoting/protocol/connection_to_host_impl.cc

@@ -48,6 +48,23 @@ ConnectionToHostImpl::~ConnectionToHostImpl() {
     signal_strategy_->RemoveListener(this);
 }
 
+#define RETURN_STRING_LITERAL(x) \
+case x: \
+return #x;
+
+const char* ConnectionToHost::StateToString(State state) {
+  switch (state) {
+    RETURN_STRING_LITERAL(INITIALIZING);
+    RETURN_STRING_LITERAL(CONNECTING);
+    RETURN_STRING_LITERAL(AUTHENTICATED);
+    RETURN_STRING_LITERAL(CONNECTED);
+    RETURN_STRING_LITERAL(CLOSED);
+    RETURN_STRING_LITERAL(FAILED);
+  }
+  NOTREACHED();
+  return nullptr;
+}
+
 void ConnectionToHostImpl::Connect(
     SignalStrategy* signal_strategy,
     scoped_ptr<TransportFactory> transport_factory,

remoting/protocol/errors.cc

@@ -0,0 +1,34 @@
+// 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/protocol/errors.h"
+
+#include "base/logging.h"
+
+namespace remoting {
+namespace protocol {
+
+#define RETURN_STRING_LITERAL(x) \
+case x: \
+return #x;
+
+const char* ErrorCodeToString(ErrorCode error) {
+  switch (error) {
+    RETURN_STRING_LITERAL(OK);
+    RETURN_STRING_LITERAL(PEER_IS_OFFLINE);
+    RETURN_STRING_LITERAL(SESSION_REJECTED);
+    RETURN_STRING_LITERAL(INCOMPATIBLE_PROTOCOL);
+    RETURN_STRING_LITERAL(AUTHENTICATION_FAILED);
+    RETURN_STRING_LITERAL(CHANNEL_CONNECTION_ERROR);
+    RETURN_STRING_LITERAL(SIGNALING_ERROR);
+    RETURN_STRING_LITERAL(SIGNALING_TIMEOUT);
+    RETURN_STRING_LITERAL(HOST_OVERLOAD);
+    RETURN_STRING_LITERAL(UNKNOWN_ERROR);
+  }
+  NOTREACHED();
+  return nullptr;
+}
+
+}  // namespace protocol
+}  // namespace remoting

remoting/protocol/errors.h

@@ -25,6 +25,9 @@ enum ErrorCode {
   UNKNOWN_ERROR,
 };
 
+// Returns the literal string of |error|.
+const char* ErrorCodeToString(ErrorCode error);
+
 }  // namespace protocol
 }  // namespace remoting
 

remoting/remoting_srcs.gypi

@@ -118,6 +118,7 @@
       'protocol/content_description.cc',
       'protocol/content_description.h',
       'protocol/datagram_channel_factory.h',
+      'protocol/errors.cc',
       'protocol/errors.h',
       'protocol/host_control_dispatcher.cc',
       'protocol/host_control_dispatcher.h',

remoting/remoting_test.gypi

@@ -60,6 +60,8 @@
         'test/chromoting_test_driver_environment.h',
         'test/connection_setup_info.cc',
         'test/connection_setup_info.h',
+        'test/connection_time_observer.cc',
+        'test/connection_time_observer.h',
         'test/fake_access_token_fetcher.cc',
         'test/fake_access_token_fetcher.h',
         'test/fake_app_remoting_report_issue_request.cc',
@@ -330,6 +332,7 @@
         'test/access_token_fetcher_unittest.cc',
         'test/app_remoting_report_issue_request_unittest.cc',
         'test/chromoting_test_driver_environment_unittest.cc',
+        'test/connection_time_observer_unittest.cc',
         'test/host_list_fetcher_unittest.cc',
         'test/remote_host_info_fetcher_unittest.cc',
         'test/test_chromoting_client_unittest.cc',

remoting/test/BUILD.gn

@@ -16,6 +16,8 @@ source_set("test_support") {
     "chromoting_test_driver_environment.h",
     "connection_setup_info.cc",
     "connection_setup_info.h",
+    "connection_time_observer.cc",
+    "connection_time_observer.h",
     "fake_access_token_fetcher.cc",
     "fake_access_token_fetcher.h",
     "fake_app_remoting_report_issue_request.cc",
@@ -134,6 +136,7 @@ source_set("unit_tests") {
     "access_token_fetcher_unittest.cc",
     "app_remoting_report_issue_request_unittest.cc",
     "chromoting_test_driver_environment_unittest.cc",
+    "connection_time_observer_unittest.cc",
     "host_list_fetcher_unittest.cc",
     "remote_host_info_fetcher_unittest.cc",
     "test_chromoting_client_unittest.cc",

remoting/test/chromoting_test_driver.cc

@@ -183,7 +183,7 @@ int main(int argc, char* argv[]) {
       argc, argv, base::Bind(&NoAtExitBaseTestSuite::RunTestSuite, argc, argv));
   }
 
-  // Update the logging verbosity level is user specified one.
+  // Update the logging verbosity level if user specified one.
   std::string verbosity_level(
       command_line->GetSwitchValueASCII(switches::kLoggingLevelSwitchName));
   if (!verbosity_level.empty()) {

remoting/test/connection_time_observer.cc

@@ -0,0 +1,113 @@
+// 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()) {
+    std::string connection_state =
+        protocol::ConnectionToHost::StateToString(state);
+    LOG(ERROR) << connection_state << " state has already been set";
+    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) {
+      int state_transition_time =
+          GetStateTransitionTime(current_state, state).InMilliseconds();
+      LOG(INFO) << base::StringPrintf(kStateChangeFormatString,
+          protocol::ConnectionToHost::StateToString(current_state),
+          protocol::ConnectionToHost::StateToString(state),
+          state_transition_time);
+      current_state = state;
+    }
+  }
+
+  int connected_time =
+      GetStateTransitionTime(initializing, current_state).InMilliseconds();
+
+  // |current state| will either be FAILED or CONNECTED.
+  LOG(INFO) << "Total Connection Duration (INITIALIZING to "
+            << protocol::ConnectionToHost::StateToString(current_state) << "): "
+            << connected_time << " ms";
+}
+
+base::TimeDelta ConnectionTimeObserver::GetStateTransitionTime(
+    protocol::ConnectionToHost::State start,
+    protocol::ConnectionToHost::State end) const {
+  auto iter_end = transition_times_map_.end();
+
+  auto iter_start_state = transition_times_map_.find(start);
+  std::string start_state = protocol::ConnectionToHost::StateToString(start);
+  if (iter_start_state == iter_end) {
+    LOG(ERROR) << "No time found for state: " << start_state;
+    return base::TimeDelta::Max();
+  }
+
+  auto iter_end_state = transition_times_map_.find(end);
+  std::string end_state = protocol::ConnectionToHost::StateToString(end);
+  if (iter_end_state == iter_end) {
+    LOG(ERROR) << "No time found for state: " << 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: " << start_state << ", end: " << end_state << "]";
+    return base::TimeDelta::Max();
+  }
+
+  return delta;
+}
+
+}  // namespace test
+}  // namespace remoting

remoting/test/connection_time_observer.h

@@ -0,0 +1,61 @@
+// 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.
+
+#ifndef REMOTING_TEST_CONNECTION_TIME_OBSERVER_H_
+#define REMOTING_TEST_CONNECTION_TIME_OBSERVER_H_
+
+#include <map>
+
+#include "remoting/test/remote_connection_observer.h"
+
+namespace base {
+class TimeDelta;
+class Timer;
+}
+
+namespace remoting {
+namespace test {
+
+// Observes and saves the times when a chromoting client changes its state. It
+// allows for tests to access latency times between the different states the
+// client transitioned through.
+class ConnectionTimeObserver
+    : public RemoteConnectionObserver {
+ public:
+  ConnectionTimeObserver();
+  ~ConnectionTimeObserver() override;
+
+  // RemoteConnectionObserver interface.
+  void ConnectionStateChanged(protocol::ConnectionToHost::State state,
+                              protocol::ErrorCode error_code) override;
+
+  // Prints out connection performance stats to STDOUT.
+  void DisplayConnectionStats() const;
+
+  // Returns the time delta in milliseconds between |start_state| and
+  // |end_state| stored in |transition_times_map_|.
+  base::TimeDelta GetStateTransitionTime(
+      protocol::ConnectionToHost::State start,
+      protocol::ConnectionToHost::State end) const;
+
+  // Used to set fake state transition times for ConnectionTimeObserver tests.
+  void SetTransitionTimesMapForTest(
+      const std::map<protocol::ConnectionToHost::State, base::TimeTicks>& map);
+
+ private:
+  // Saves the current connection state of client to host.
+  protocol::ConnectionToHost::State current_connection_state_ =
+      protocol::ConnectionToHost::State::INITIALIZING;
+
+  // The TimeTicks to get to a state from the previous state.
+  std::map<protocol::ConnectionToHost::State, base::TimeTicks>
+      transition_times_map_;
+
+  DISALLOW_COPY_AND_ASSIGN(ConnectionTimeObserver);
+};
+
+}  // namespace test
+}  // namespace remoting
+
+#endif  // REMOTING_TEST_CONNECTION_TIME_OBSERVER_H_