Report video and network stats averaged over 1s, and create corresponding UMA metrics.

remoting/client/plugin/chromoting_instance.cc

 // Copyright (c) 2012 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/client/plugin/chromoting_instance.h"
 
 #include <string>
 #include <vector>
 
 #if defined(OS_NACL)
@@ skipping 14 matching lines @@
 #include "base/threading/thread.h"
 #include "base/values.h"
 #include "crypto/random.h"
 #include "jingle/glue/thread_wrapper.h"
 #include "media/base/yuv_convert.h"
 #include "net/socket/ssl_server_socket.h"
 #include "ppapi/cpp/completion_callback.h"
 #include "ppapi/cpp/dev/url_util_dev.h"
 #include "ppapi/cpp/image_data.h"
 #include "ppapi/cpp/input_event.h"
+#include "ppapi/cpp/private/uma_private.h"
 #include "ppapi/cpp/rect.h"
 #include "ppapi/cpp/var_array_buffer.h"
 #include "ppapi/cpp/var_dictionary.h"
 #include "remoting/base/constants.h"
 #include "remoting/base/util.h"
 #include "remoting/client/chromoting_client.h"
 #include "remoting/client/plugin/delegating_signal_strategy.h"
 #include "remoting/client/plugin/normalizing_input_filter_cros.h"
 #include "remoting/client/plugin/normalizing_input_filter_mac.h"
 #include "remoting/client/plugin/pepper_audio_player.h"
@@ skipping 15 matching lines @@
 #undef PostMessage
 #endif
 
 namespace remoting {
 
 namespace {
 
 // Default DPI to assume for old clients that use notifyClientResolution.
 const int kDefaultDPI = 96;
 
-// Interval at which to sample performance statistics.
-const int kPerfStatsIntervalMs = 1000;
-
 // URL scheme used by Chrome apps and extensions.
 const char kChromeExtensionUrlScheme[] = "chrome-extension";
 
+// The boundary value for the FPS histogram: we don't expect video frame-rate to
+// be greater than 40fps.

[Wez, 2015/07/08 23:42:29]

Why not? Where does the 40fps come from? What happens if a load of frames get
stuck in-transit and we receive them in a sudden burst?

Also, doesn't this mean things will break if we e.g. upgrade to 60fps hosts?

[anandc, 2015/07/09 19:17:10]

The 40fps came from our expected happy-path scenario. To handle the scenario you
point out, and leave some room for growth, updated this to 60.
Values above the max end up in the right-most bucket of the histograms.

+// Histograms expect samples to be less than the boundary value, so set to 41.
+const int kMaxFrameRate = 41;

[Wez, 2015/07/08 23:42:29]

nit: Blank line after this.

[anandc, 2015/07/09 19:17:10]

Done.

+// For bandwidth, we'll use a histogram ranging from 0 to 1MB/s, spread across

[Wez, 2015/07/08 23:42:29]

Why is 1MB/s the maximum?

[anandc, 2015/07/09 19:17:10]

Added clarification.

+// 1000 buckets.
+// Histograms are log-scaled by default. This results in fine-grained buckets at
+// lower values and wider-ranged buckets closer to the maximum.
+// Values above the maximum defined here end up in the right-most bucket.
+// See $/src/base/metrics/histogram.h for more details.
+const int kBandwidthHistogramMin = 1;
+const int kBandwidthHistogramMax = 1024000;
+const int kBandwidthHistogramNumBuckets = 1000;
+
+// For the latency metrics, we'll set the max histogram value to 20,000ms, split
+// over 1000 buckets.

[Wez, 2015/07/08 23:42:29]

Again, explain why these numbers were chosen?

[anandc, 2015/07/09 19:17:10]

Removed from this CL.

+const int kLatencyHistogramMin = 1;
+const int kLatencyHistogramMax = 20000;
+const int kLatencyHistogramNumBuckets = 1000;
+
 #if defined(USE_OPENSSL)
 // Size of the random seed blob used to initialize RNG in libjingle. Libjingle
 // uses the seed only for OpenSSL builds. OpenSSL needs at least 32 bytes of
 // entropy (see http://wiki.openssl.org/index.php/Random_Numbers), but stores
 // 1039 bytes of state, so we initialize it with 1k or random data.
 const int kRandomSeedSize = 1024;
 #endif  // defined(USE_OPENSSL)
 
 std::string ConnectionStateToString(protocol::ConnectionToHost::State state) {
   // Values returned by this function must match the
@@ skipping 635 matching lines @@
           host_public_key));
   scoped_ptr<protocol::Authenticator> authenticator(
       new protocol::NegotiatingClientAuthenticator(
           client_pairing_id, client_paired_secret, authentication_tag,
           fetch_secret_callback, token_fetcher.Pass(), auth_methods));
 
   // Kick off the connection.
   client_->Start(signal_strategy_.get(), authenticator.Pass(),
                  transport_factory.Pass(), host_jid, capabilities);
 
-  // Start timer that periodically sends perf stats.
+  // Start timers that periodically send perf stats, for display and for UMA.
   plugin_task_runner_->PostDelayedTask(
-      FROM_HERE, base::Bind(&ChromotingInstance::SendPerfStats,
+      FROM_HERE, base::Bind(&ChromotingInstance::SendDisplayPerfStats,
                             weak_factory_.GetWeakPtr()),
-      base::TimeDelta::FromMilliseconds(kPerfStatsIntervalMs));
+      base::TimeDelta::FromSeconds(
+        video_renderer_->GetStats()->kDisplayStatsUpdateWindowInSeconds));

[Wez, 2015/07/08 23:42:29]

This is a constant, not a member, so you can just write
ChromotingStats::kDisplayStatsUpdateWindowInSeconds

[anandc, 2015/07/09 19:17:10]

Done.

+  plugin_task_runner_->PostDelayedTask(
+      FROM_HERE, base::Bind(&ChromotingInstance::SendUMAPerfStats,
+                            weak_factory_.GetWeakPtr()),
+      base::TimeDelta::FromSeconds(
+        video_renderer_->GetStats()->kUMAStatsTimeWindowInSeconds));
 }
 
 void ChromotingInstance::HandleDisconnect(const base::DictionaryValue& data) {
   DCHECK(plugin_task_runner_->BelongsToCurrentThread());
   Disconnect();
 }
 
 void ChromotingInstance::HandleOnIncomingIq(const base::DictionaryValue& data) {
   std::string iq;
   if (!data.GetString("iq", &iq)) {
@@ skipping 291 matching lines @@
   data->SetBoolean("pressed", pressed);
   PostLegacyJsonMessage("trappedKeyEvent", data.Pass());
 }
 
 void ChromotingInstance::SendOutgoingIq(const std::string& iq) {
   scoped_ptr<base::DictionaryValue> data(new base::DictionaryValue());
   data->SetString("iq", iq);
   PostLegacyJsonMessage("sendOutgoingIq", data.Pass());
 }
 
-void ChromotingInstance::SendPerfStats() {
+void ChromotingInstance::SendDisplayPerfStats() {
   if (!video_renderer_.get()) {
     return;
   }
 
   plugin_task_runner_->PostDelayedTask(
-      FROM_HERE, base::Bind(&ChromotingInstance::SendPerfStats,
+      FROM_HERE, base::Bind(&ChromotingInstance::SendDisplayPerfStats,
                             weak_factory_.GetWeakPtr()),
-      base::TimeDelta::FromMilliseconds(kPerfStatsIntervalMs));
+      base::TimeDelta::FromSeconds(
+        ChromotingStats::kDisplayStatsUpdateWindowInSeconds));
 
+  // Update performance stats, averaged over the past few seconds.
+  // These are eventually upstreamed to the client and available for display to
+  // the user.

[Wez, 2015/07/08 23:42:29]

This is very vague... why "eventually", and what does "upstreamed" mean?

I'd suggest something like "Supply the app with performance stats averaged over
several seconds, suitable for display to the user."

[anandc, 2015/07/09 19:17:10]

Thanks. PTAL at latest comment.

   scoped_ptr<base::DictionaryValue> data(new base::DictionaryValue());
   ChromotingStats* stats = video_renderer_->GetStats();
-  data->SetDouble("videoBandwidth", stats->video_bandwidth()->Rate());
-  data->SetDouble("videoFrameRate", stats->video_frame_rate()->Rate());
+  data->SetDouble("videoBandwidth", stats->video_bandwidth_display()->Rate());
+  data->SetDouble("videoFrameRate", stats->video_frame_rate_display()->Rate());
   data->SetDouble("captureLatency", stats->video_capture_ms()->Average());
   data->SetDouble("encodeLatency", stats->video_encode_ms()->Average());
   data->SetDouble("decodeLatency", stats->video_decode_ms()->Average());
   data->SetDouble("renderLatency", stats->video_paint_ms()->Average());
   data->SetDouble("roundtripLatency", stats->round_trip_ms()->Average());
   PostLegacyJsonMessage("onPerfStats", data.Pass());
 }
 
+void ChromotingInstance::SendUMAPerfStats() {
+  if (!video_renderer_.get()) {
+    return;
+  }
+
+  plugin_task_runner_->PostDelayedTask(
+      FROM_HERE, base::Bind(&ChromotingInstance::SendUMAPerfStats,
+                            weak_factory_.GetWeakPtr()),
+      base::TimeDelta::FromSeconds(
+        ChromotingStats::kUMAStatsTimeWindowInSeconds));
+
+  // Update UMA histograms for video frame-rate, bandwidth and latencies.
+  // These metrics will be averaged over the last second.

[Wez, 2015/07/08 23:42:29]

Will be averaged by whom...? The UMA APIs average them? Aren't we already
averaging them before we even reach here?

[anandc, 2015/07/09 19:17:09]

Yes, we are averaging them. Clarified.

+  ChromotingStats* stats = video_renderer_->GetStats();
+  pp::UMAPrivate uma(this);
+  uma.HistogramEnumeration("Chromoting.Video.FrameRate",
+    stats->video_frame_rate_uma()->Rate(), kMaxFrameRate);
+  uma.HistogramEnumeration("Chromoting.Video.PacketRate",
+    stats->video_packet_rate_uma()->Rate(), kMaxFrameRate);
+  uma.HistogramCustomCounts("Chromoting.Video.Bandwidth",
+    stats->video_bandwidth_uma()->Rate(), kBandwidthHistogramMin,
+    kBandwidthHistogramMax, kBandwidthHistogramNumBuckets);
+  uma.HistogramCustomTimes("Chromoting.Video.CaptureLatency",

[Wez, 2015/07/08 23:42:29]

nit: This isn't a latency, it's the time taken to capture; suggest CaptureMs for
the name, and similarly for the other values below.

Also, the values you're logging here are already averaged over the past 10s,
which means that any averaging that UMA APIs do will mess things up, surely? 
Don't you need special UMA-friendly 1s-averaged versions of these?

Should we instead be logging these stats for every frame, and letting UMA do all
the averaging, and then doing separate averaging for the display stats?

[anandc, 2015/07/09 19:17:09]

You are correct. The latency metrics, if uploaded to UMA in this manner, won't
be accurate, as you point out. Going to do the accurate calculation and upload
in a separate CL. 
Tracked by https://code.google.com/p/chromium/issues/detail?id=508602

+    stats->video_capture_ms()->Average(), kLatencyHistogramMin,
+    kLatencyHistogramMax, kLatencyHistogramNumBuckets);
+  uma.HistogramCustomTimes("Chromoting.Video.EncodeLatency",
+    stats->video_encode_ms()->Average(), kLatencyHistogramMin,
+    kLatencyHistogramMax, kLatencyHistogramNumBuckets);
+  uma.HistogramCustomTimes("Chromoting.Video.RoundTripLatency",
+    stats->round_trip_ms()->Average(), kLatencyHistogramMin,
+    kLatencyHistogramMax, kLatencyHistogramNumBuckets);
+}
+
 // static
 void ChromotingInstance::RegisterLogMessageHandler() {
   base::AutoLock lock(g_logging_lock.Get());
 
   VLOG(1) << "Registering global log handler";
 
   // Record previous handler so we can call it in a chain.
   g_logging_old_handler = logging::GetLogMessageHandler();
 
   // Set up log message handler.
@@ skipping 117 matching lines @@
 
 #if !defined(OS_NACL)
   // Log messages are forwarded to the webapp only in PNaCl version of the
   // plugin, so ProcessLogToUI() needs to be called explicitly in the non-PNaCl
   // version.
   ProcessLogToUI(message);
 #endif  // !defined(OS_NACL)
 }
 
 }  // namespace remoting