Add UMA histogram DomDistiller.Time.DistillPage

components/dom_distiller/core/distiller_page.cc

 // Copyright 2013 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 "components/dom_distiller/core/distiller_page.h"
 
 #include "base/bind.h"
 #include "base/json/json_writer.h"
 #include "base/logging.h"
 #include "base/message_loop/message_loop.h"
@@ skipping 70 matching lines @@
 
 void DistillerPage::DistillPage(
     const GURL& gurl,
     const dom_distiller::proto::DomDistillerOptions options,
     const DistillerPageCallback& callback) {
   DCHECK(ready_);
   // It is only possible to distill one page at a time. |ready_| is reset when
   // the callback to OnDistillationDone happens.
   ready_ = false;
   distiller_page_callback_ = callback;
+  distillation_start_ = base::TimeTicks::Now();
   DistillPageImpl(gurl, GetDistillerScriptWithOptions(options,
                                                       StringifyOutput(),
                                                       CreateNewContext()));
 }
 
 void DistillerPage::OnDistillationDone(const GURL& page_url,
                                        const base::Value* value) {
   DCHECK(!ready_);
   ready_ = true;
 
   scoped_ptr<dom_distiller::proto::DomDistillerResult> distiller_result(
       new dom_distiller::proto::DomDistillerResult());
   bool found_content;
   if (value->IsType(base::Value::TYPE_NULL)) {
     found_content = false;
   } else {
     found_content =
         dom_distiller::proto::json::DomDistillerResult::ReadFromValue(
             value, distiller_result.get());
     if (!found_content) {
       DVLOG(1) << "Unable to parse DomDistillerResult.";
     } else {
+      base::TimeDelta distillation_time =
+          base::TimeTicks::Now() - distillation_start_;
+      UMA_HISTOGRAM_TIMES("DomDistiller.Time.DistillPage", distillation_time);
+      VLOG(1) << "DomDistiller.Time.DistillPage = " << distillation_time;

[Mark P, 2015/05/11 18:27:10]

minor comment: do you actually need these VLOGs are were they just meant for
debugging on your own machine?

[wychen, 2015/05/11 20:42:49]

Thanks for your review! I used LOG(ERROR) locally for debugging, and converted
to VLOG(1) so that it is not shown by default, and is kept for future
references. I think VLOG(1 or larger) should be suitable for low volume
debugging like this one.

Ref:
https://sites.google.com/a/google.com/chromeos-team-tok/how-to/debugging-tips
https://sites.google.com/a/google.com/googletv/Home/engineering/platform/chro...
https://groups.google.com/a/google.com/forum/#!msg/chromoting/vmHfJ_5KeWk/BLh...

+
       if (distiller_result->has_timing_info()) {
         const dom_distiller::proto::TimingInfo& timing =
             distiller_result->timing_info();
         if (timing.has_markup_parsing_time()) {
           UMA_HISTOGRAM_TIMES(
               "DomDistiller.Time.MarkupParsing",
               base::TimeDelta::FromMillisecondsD(timing.markup_parsing_time()));
         }
         if (timing.has_document_construction_time()) {
           UMA_HISTOGRAM_TIMES(
               "DomDistiller.Time.DocumentConstruction",
               base::TimeDelta::FromMillisecondsD(
                   timing.document_construction_time()));
         }
         if (timing.has_article_processing_time()) {
           UMA_HISTOGRAM_TIMES(
               "DomDistiller.Time.ArticleProcessing",
               base::TimeDelta::FromMillisecondsD(
                   timing.article_processing_time()));
         }
         if (timing.has_formatting_time()) {
           UMA_HISTOGRAM_TIMES(
               "DomDistiller.Time.Formatting",
               base::TimeDelta::FromMillisecondsD(timing.formatting_time()));
         }
         if (timing.has_total_time()) {
           UMA_HISTOGRAM_TIMES(
               "DomDistiller.Time.DistillationTotal",
               base::TimeDelta::FromMillisecondsD(timing.total_time()));
+          VLOG(1) << "DomDistiller.Time.DistillationTotal = " <<
+              base::TimeDelta::FromMillisecondsD(timing.total_time());
         }
       }
       if (distiller_result->has_statistics_info()) {
         const dom_distiller::proto::StatisticsInfo& statistics =
             distiller_result->statistics_info();
         if (statistics.has_word_count()) {
           UMA_HISTOGRAM_CUSTOM_COUNTS(
             "DomDistiller.Statistics.WordCount",
             statistics.word_count(),
             1, 4000, 50);
         }
       }
     }
   }
 
   base::MessageLoop::current()->PostTask(
       FROM_HERE,
       base::Bind(distiller_page_callback_,
                  base::Passed(&distiller_result),
                  found_content));
 }
 
 }  // namespace dom_distiller