Add metrics for tracking UX impact of non-static CLD data providers

chrome/renderer/translate/translate_helper.cc

Index: chrome/renderer/translate/translate_helper.cc
diff --git a/chrome/renderer/translate/translate_helper.cc b/chrome/renderer/translate/translate_helper.cc
index cffcfc55d92e040870ff44f43a00362d74e1cde9..678b0dccd05ea8ad10d8cee0c40adb658a470fa0 100644
--- a/chrome/renderer/translate/translate_helper.cc
+++ b/chrome/renderer/translate/translate_helper.cc
@@ -8,6 +8,7 @@
 #include "base/compiler_specific.h"
 #include "base/logging.h"
 #include "base/message_loop/message_loop.h"
+#include "base/metrics/histogram.h"
 #include "base/strings/string16.h"
 #include "base/strings/string_util.h"
 #include "base/strings/utf_string_conversions.h"
@@ -17,6 +18,8 @@
 #include "components/translate/core/common/translate_metrics.h"
 #include "components/translate/core/common/translate_util.h"
 #include "components/translate/core/language_detection/language_detection_util.h"
+#include "content/public/common/content_constants.h"
+#include "content/public/renderer/render_thread.h"
 #include "content/public/renderer/render_view.h"
 #include "extensions/common/constants.h"
 #include "extensions/renderer/extension_groups.h"
@@ -140,17 +143,25 @@ void TranslateHelper::PageCapturedImpl(int page_seq_no,
   if (!main_frame || page_seq_no_ != page_seq_no)
     return;
 
-  // TODO(andrewhayden): UMA insertion point here: Track if data is available.
-  // TODO(andrewhayden): Retry insertion point here, retry till data available.
   if (!cld_data_provider_->IsCldDataAvailable()) {
     // We're in dynamic mode and CLD data isn't loaded. Retry when CLD data
     // is loaded, if ever.
     deferred_page_capture_ = true;
     deferred_page_seq_no_ = page_seq_no;
     deferred_contents_ = contents;
+    RecordLanguageDetectionTiming(DEFERRED);
     return;
   }
 
+  if (deferred_page_seq_no_ == -1) {

[jar (doing other things), 2014/07/16 16:44:44]

nit: Although I'm not usually a big fan of the ternary ?: operators, this code
seems to cry out to use it:

   RecordLanguageDetectionTiming((deferred_page_seq_no_ == -1) ?
                                 ON_TIME : RESUMED);

If you really like it as is, OK... but IMO, it is a lot less reading for a
person looking to understand the code.  Your comments could be a block comment
in front of this line.

[andrewhayden, 2014/07/17 08:36:19]

Ha. OK, will do :)

[Andrew Hayden (chromium.org), 2014/07/17 14:00:43]

Changed my mind on this one, I like the comments. Ternary is just sugar anyways.

+    // CLD data was available before language detection was requested.
+    RecordLanguageDetectionTiming(ON_TIME);
+  } else {
+    // This is a request that was triggered because CLD data is now available
+    // and was previously deferred.
+    RecordLanguageDetectionTiming(RESUMED);
+  }
+
   WebDocument document = main_frame->document();
   std::string content_language = document.contentLanguage().utf8();
   WebElement html_element = document.documentElement();
@@ -608,3 +619,68 @@ void TranslateHelper::OnCldDataAvailable() {
     deferred_contents_.clear(); // Clean up for sanity
   }
 }
+

[Takashi Toyoshima, 2014/07/17 02:09:31]

Having comments on implementation details in source files is nice. But this
looks a kind of information for developers who are interested in using this
class. So, I prefer having following comments in the header. WDYT?

[Andrew Hayden (chromium.org), 2014/07/17 14:00:43]

I moved it to the header file. I considered kicking it out to the docs but I
think it's better here. I will also add to the docs, but the info really does
belong with the class.

+// Note on metrics:
+//
+// This class provides metrics that allow tracking the user experience impact
+// of non-static CldDataProvider implementations. For background on the data
+// providers, please refer to the following documentation:
+// http://www.chromium.org/developers/how-tos/compact-language-detector-cld-data-source-configuration
+//
+// Available metrics (from the LanguageDetectionTiming enum):
+// 1. ON_TIME
+//    Recorded if PageCaptured(...) is invoked after CLD is available. This is
+//    the ideal case, indicating that CLD is available before it is needed.
+// 2. DEFERRED
+//    Recorded if PageCaptured(...) is invoked before CLD is available.
+//    Sub-optimal case indicating that CLD wasn't available when it was needed,
+//    so the request for detection has been deferred until CLD is available or
+//    until the user navigates to a different page.
+// 3. RESUMED
+//    Recorded if CLD becomes available after a language detection request was
+//    deferred, but before the user navigated to a different page. Language
+//    detection is ultimately completed, it just didn't happen on time.
+//
+// Note that there is NOT a metric that records the number of times that
+// language detection had to be aborted because CLD never became available in
+// time. This is because there is no reasonable way to cover all the cases
+// under which this could occur, particularly the destruction of the renderer
+// for which this object was created. However, this value can be synthetically
+// derived, using the logic below.
+//
+// Every page load that triggers language detection will result in the
+// recording of exactly one of the first two events: ON_TIME or DEFERRED. If
+// CLD is available in time to satisfy the request, the third event (RESUMED)
+// will be recorded; thus, the number of times when language detection
+// ultimately fails because CLD isn't ever available is implied as the number of
+// times that detection is deferred minus the number of times that language
+// detection is late:
+//
+//   count(FAILED) ~= count(DEFERRED) - count(RESUMED)
+//
+// Note that this is not 100% accurate: some renderer process are so short-lived
+// that language detection wouldn't have been relevant anyway, and so a failure
+// to detect the language in a timely manner might be completely innocuous. The
+// overall problem with language detection is that it isn't possible to know
+// whether it was required or not until after it has been performed!
+//
+// We use histograms for recording these metrics. On Android, the renderer can
+// be killed without the chance to clean up or transmit these histograms,
+// leading to dropped metrics. To work around this, this method forces an IPC
+// message to be sent to the browser process immediately.
+void TranslateHelper::RecordLanguageDetectionTiming(LanguageDetectionTiming

[Alexei Svitkine (slow), 2014/07/16 14:50:40]

Nit: Wrap after ( instead and indent next line 4.

[andrewhayden, 2014/07/17 08:36:19]

Will do.

+                                                    timing) {
+  // The following comment is copied from page_load_histograms.cc, and applies
+  // just as equally here:
+  //
+  // Since there are currently no guarantees that renderer histograms will be
+  // sent to the browser, we initiate a PostTask here to be sure that we send
+  // the histograms we generated.  Without this call, pages that don't have an
+  // on-close-handler might generate data that is lost when the renderer is
+  // shutdown abruptly (perchance because the user closed the tab).
+  VLOG(1) << "Language detection timing: " << timing;

[Alexei Svitkine (slow), 2014/07/16 14:50:40]

Do you need the VLOG(1) message or is this left over from your own debugging?

In general, log messages are discouraged (other than debug variants that are
compiled out of release builds). Plus, since you're recording the histogram
anyway, you can just see the status in chrome://histograms.

[andrewhayden, 2014/07/17 08:36:19]

I put this here so that I don't have to scan through the ENORMOUS page at
chrome://histograms to find my data, and also can be sure that it was actually
invoked even if the IPC machinery somehow fails. My understanding of VLOG is
that it is designed to overcome these problems that make logging bad.

[Alexei Svitkine (slow), 2014/07/17 13:20:25]

You can filter chrome://histograms/ by substring - e.g.
chrome://histograms/Translate.LanguageDetectionTiming

I don't think VLOG() overcomes the problems. It still bloats the binary. DVLOG
does overcome the problems though (since it will only be enabled in debug builds
which we don't ship to users).

[Andrew Hayden (chromium.org), 2014/07/17 14:00:43]

DVLOG it is, then.

+  UMA_HISTOGRAM_ENUMERATION("Translate.LanguageDetectionTiming", timing,
+                            kLanguageDetectionTimingMax);
+  content::RenderThread::Get()->UpdateHistograms(

[jar (doing other things), 2014/07/16 16:44:44]

How often (max) could this be called? Is it really infrequent, or could it be
several times per page?  This is where I was pondering aggregation.  As you
noted, this call will post a task... so there is some chance that it will be
delayed... and maybe never get to effectively run.

Perhaps at a minimum, we should look into aggregation inside UpadetHistograms().

[andrewhayden, 2014/07/17 08:36:19]

As above, in the great majority of cases this should get called once. Twice
should be a very rare occurrence, I estimate less than 1% of the time. Of
course, we won't know for sure till we turn it on.

The max number of times this would be called per page load is 2.

As stated above, I'm happy to file a crbug and contribute to the long-term fix,
but adding aggregation is way out of scope for this task. I'm up for helping
out, but I think we should do it in a separate change.

[Andrew Hayden (chromium.org), 2014/07/17 14:00:43]

Performance comments added here.

+      content::kHistogramSynchronizerReservedSequenceNumber);
+}