[Feed] Add UMA logging for image manager load times & success/failure

This data will be used to monitor the health of the feed image
manager and also to compare to the incoming componentized cached image
fetcher.

Bug: 868604
Change-Id: I2e9ac800bf602db6963f94c0baa487cf74adbc16
Reviewed-on: https://chromium-review.googlesource.com/1155160
Commit-Queue: Brandon Wylie <wylieb@chromium.org>
Reviewed-by: Robert Kaplow (slow) <rkaplow@chromium.org>
Reviewed-by: Filip Gorski <fgorski@chromium.org>
Reviewed-by: Gang Wu <gangwu@chromium.org>
Cr-Commit-Position: refs/heads/master@{#582816}

components/feed/core/feed_image_manager.cc

@@ -7,6 +7,9 @@
 #include <utility>
 
 #include "base/bind.h"
+#include "base/metrics/histogram_macros.h"
+#include "base/threading/thread_task_runner_handle.h"
+#include "base/timer/elapsed_timer.h"
 #include "components/feed/core/time_serialization.h"
 #include "components/image_fetcher/core/image_decoder.h"
 #include "components/image_fetcher/core/image_fetcher.h"
@@ -44,6 +47,9 @@ constexpr net::NetworkTrafficAnnotationTag kTrafficAnnotation =
         }
       })");
 
+void ReportFetchResult(FeedImageFetchResult result) {
+  UMA_HISTOGRAM_ENUMERATION("NewTabPage.Feed.ImageFetchResult", result);
+}
 }  // namespace
 
 FeedImageManager::FeedImageManager(
@@ -72,11 +78,16 @@ void FeedImageManager::FetchImagesFromDatabase(size_t url_index,
                                                ImageFetchedCallback callback) {
   if (url_index >= urls.size()) {
     // Already reached the last entry. Return an empty image.
-    std::move(callback).Run(gfx::Image());
+    base::ThreadTaskRunnerHandle::Get()->PostTask(
+        FROM_HERE, base::BindOnce(std::move(callback), gfx::Image()));
     return;
   }
 
-  std::string image_id = urls[url_index];
+  const std::string& image_id = urls[url_index];
+  // Only take the first instance of the url so we get the worst-case time.
+  if (url_timers_.find(image_id) == url_timers_.end()) {
+    url_timers_.insert(std::make_pair(image_id, base::ElapsedTimer()));
+  }
   image_database_->LoadImage(
       image_id, base::BindOnce(&FeedImageManager::OnImageFetchedFromDatabase,
                                weak_ptr_factory_.GetWeakPtr(), url_index,
@@ -105,21 +116,37 @@ void FeedImageManager::OnImageDecodedFromDatabase(size_t url_index,
                                                   std::vector<std::string> urls,
                                                   ImageFetchedCallback callback,
                                                   const gfx::Image& image) {
+  const std::string& image_id = urls[url_index];
   if (image.IsEmpty()) {
     // If decoding the image failed, delete the DB entry.
-    image_database_->DeleteImage(urls[url_index]);
+    image_database_->DeleteImage(image_id);
     FetchImageFromNetwork(url_index, std::move(urls), std::move(callback));
     return;
   }
 
-  std::move(callback).Run(image);
+  base::ThreadTaskRunnerHandle::Get()->PostTask(
+      FROM_HERE, base::BindOnce(std::move(callback), image));
+
+  // Report success if the url exists.
+  // This check is for concurrent access to the same url.
+  if (url_timers_.find(image_id) != url_timers_.end()) {
+    UMA_HISTOGRAM_TIMES("NewTabPage.Feed.ImageLoadFromCacheTime",
+                        url_timers_[image_id].Elapsed());
+    ClearUmaTimer(image_id);
+    ReportFetchResult(FeedImageFetchResult::kSuccessCached);
+  }
 }
 
 void FeedImageManager::FetchImageFromNetwork(size_t url_index,
                                              std::vector<std::string> urls,
                                              ImageFetchedCallback callback) {
-  GURL url(urls[url_index]);
+  const std::string& image_id = urls[url_index];
+  GURL url(image_id);
   if (!url.is_valid()) {
+    // Report failure.
+    ReportFetchResult(FeedImageFetchResult::kFailure);
+    ClearUmaTimer(image_id);
+
     // url is not valid, go to next URL.
     FetchImagesFromDatabase(url_index + 1, std::move(urls),
                             std::move(callback));
@@ -141,6 +168,10 @@ void FeedImageManager::OnImageFetchedFromNetwork(
     const std::string& image_data,
     const image_fetcher::RequestMetadata& request_metadata) {
   if (image_data.empty()) {
+    // Report failure.
+    ReportFetchResult(FeedImageFetchResult::kFailure);
+    ClearUmaTimer(urls[url_index]);
+
     // Fetching image failed, let's move to the next url.
     FetchImagesFromDatabase(url_index + 1, std::move(urls),
                             std::move(callback));
@@ -160,15 +191,31 @@ void FeedImageManager::OnImageDecodedFromNetwork(size_t url_index,
                                                  ImageFetchedCallback callback,
                                                  const std::string& image_data,
                                                  const gfx::Image& image) {
-  // Decoding urls[url_index] failed, let's move to the next url.
+  std::string image_id = urls[url_index];
   if (image.IsEmpty()) {
+    // Report failure.
+    ReportFetchResult(FeedImageFetchResult::kFailure);
+    ClearUmaTimer(image_id);
+
+    // Decoding failed, let's move to the next url.
     FetchImagesFromDatabase(url_index + 1, std::move(urls),
                             std::move(callback));
     return;
   }
 
-  image_database_->SaveImage(urls[url_index], image_data);
-  std::move(callback).Run(image);
+  image_database_->SaveImage(image_id, image_data);
+
+  base::ThreadTaskRunnerHandle::Get()->PostTask(
+      FROM_HERE, base::BindOnce(std::move(callback), image));
+
+  // Report success if the url exists.
+  // This check is for concurrent access to the same url.
+  if (url_timers_.find(image_id) != url_timers_.end()) {
+    UMA_HISTOGRAM_TIMES("NewTabPage.Feed.ImageLoadFromNetworkTime",
+                        url_timers_[image_id].Elapsed());
+    ClearUmaTimer(image_id);
+    ReportFetchResult(FeedImageFetchResult::kSuccessFetched);
+  }
 }
 
 void FeedImageManager::DoGarbageCollectionIfNeeded() {
@@ -204,4 +251,8 @@ void FeedImageManager::StopGarbageCollection() {
   garbage_collection_timer_.Stop();
 }
 
+void FeedImageManager::ClearUmaTimer(const std::string& url) {
+  url_timers_.erase(url);
+}
+
 }  // namespace feed

components/feed/core/feed_image_manager.h

@@ -9,10 +9,15 @@
 #include <string>
 #include <vector>
 
+#include "base/containers/flat_map.h"
 #include "base/memory/weak_ptr.h"
 #include "base/timer/timer.h"
 #include "components/feed/core/feed_image_database.h"
 
+namespace base {
+class ElapsedTimer;
+}  // namespace base
+
 namespace gfx {
 class Image;
 }  // namespace gfx
@@ -26,6 +31,15 @@ namespace feed {
 
 using ImageFetchedCallback = base::OnceCallback<void(const gfx::Image&)>;
 
+// Enum for the result of the fetch, reported through UMA.
+// New values should be added at the end and things should not be renumbered.
+enum class FeedImageFetchResult {
+  kSuccessCached = 0,
+  kSuccessFetched = 1,
+  kFailure = 2,
+  kMaxValue = kFailure,
+};
+
 // FeedImageManager takes care of fetching images from the network and caching
 // them in the database.
 class FeedImageManager {
@@ -84,6 +98,8 @@ class FeedImageManager {
   void OnGarbageCollectionDone(base::Time garbage_collected_day, bool success);
   void StopGarbageCollection();
 
+  void ClearUmaTimer(const std::string& url);
+
   // The day which image database already ran garbage collection against on.
   base::Time image_garbage_collected_day_;
 
@@ -92,6 +108,9 @@ class FeedImageManager {
   std::unique_ptr<image_fetcher::ImageFetcher> image_fetcher_;
   std::unique_ptr<FeedImageDatabase> image_database_;
 
+  // Track time it takes to get images.
+  base::flat_map<std::string, base::ElapsedTimer> url_timers_;
+
   base::WeakPtrFactory<FeedImageManager> weak_ptr_factory_;
 
   DISALLOW_COPY_AND_ASSIGN(FeedImageManager);

components/feed/core/feed_image_manager_unittest.cc

@@ -11,6 +11,7 @@
 
 #include "base/bind.h"
 #include "base/files/scoped_temp_dir.h"
+#include "base/test/metrics/histogram_tester.h"
 #include "base/test/mock_callback.h"
 #include "base/test/scoped_task_environment.h"
 #include "base/threading/sequenced_task_runner_handle.h"
@@ -24,6 +25,7 @@
 #include "ui/gfx/image/image.h"
 #include "ui/gfx/image/image_unittest_util.h"
 
+using base::HistogramTester;
 using testing::_;
 
 namespace feed {
@@ -34,6 +36,13 @@ const char kImageURL2[] = "http://cake.com/";
 const char kImageData[] = "pie image";
 const char kImageData2[] = "cake image";
 
+const char kUmaImageLoadSuccessHistogramName[] =
+    "NewTabPage.Feed.ImageFetchResult";
+const char kUmaCacheLoadHistogramName[] =
+    "NewTabPage.Feed.ImageLoadFromCacheTime";
+const char kUmaNetworkLoadHistogramName[] =
+    "NewTabPage.Feed.ImageLoadFromNetworkTime";
+
 class FakeImageDecoder : public image_fetcher::ImageDecoder {
  public:
   void DecodeImage(
@@ -116,6 +125,8 @@ class FeedImageManagerTest : public testing::Test {
     return &test_url_loader_factory_;
   }
 
+  HistogramTester& histogram() { return histogram_; }
+
   MOCK_METHOD1(OnImageLoaded, void(const std::string&));
 
  private:
@@ -126,6 +137,7 @@ class FeedImageManagerTest : public testing::Test {
   base::ScopedTempDir database_dir_;
   FakeImageDecoder* fake_image_decoder_;
   base::test::ScopedTaskEnvironment scoped_task_environment_;
+  HistogramTester histogram_;
 
   DISALLOW_COPY_AND_ASSIGN(FeedImageManagerTest);
 };
@@ -260,4 +272,83 @@ TEST_F(FeedImageManagerTest, GarbageCollectionRunOnStart) {
   EXPECT_TRUE(garbage_collection_timer().IsRunning());
 }
 
+TEST_F(FeedImageManagerTest, InvalidUrlHistogramFailure) {
+  base::MockCallback<ImageFetchedCallback> image_callback;
+  feed_image_manager()->FetchImage(std::vector<std::string>({""}),
+                                   image_callback.Get());
+
+  RunUntilIdle();
+
+  histogram().ExpectTotalCount(kUmaCacheLoadHistogramName, 0);
+  histogram().ExpectTotalCount(kUmaNetworkLoadHistogramName, 0);
+  histogram().ExpectTotalCount(kUmaImageLoadSuccessHistogramName, 1);
+  histogram().ExpectBucketCount(kUmaImageLoadSuccessHistogramName,
+                                FeedImageFetchResult::kFailure, 1);
+}
+
+TEST_F(FeedImageManagerTest, FetchImageFromCachHistogram) {
+  // Save the image in the database.
+  image_database()->SaveImage(kImageURL, kImageData);
+  RunUntilIdle();
+
+  base::MockCallback<ImageFetchedCallback> image_callback;
+  feed_image_manager()->FetchImage(std::vector<std::string>({kImageURL}),
+                                   image_callback.Get());
+
+  RunUntilIdle();
+
+  histogram().ExpectTotalCount(kUmaCacheLoadHistogramName, 1);
+  histogram().ExpectTotalCount(kUmaNetworkLoadHistogramName, 0);
+  histogram().ExpectTotalCount(kUmaImageLoadSuccessHistogramName, 1);
+  histogram().ExpectBucketCount(kUmaImageLoadSuccessHistogramName,
+                                FeedImageFetchResult::kSuccessCached, 1);
+}
+
+TEST_F(FeedImageManagerTest, FetchImageFromNetworkHistogram) {
+  test_url_loader_factory()->AddResponse(kImageURL, kImageData);
+  base::MockCallback<ImageFetchedCallback> image_callback;
+  feed_image_manager()->FetchImage(std::vector<std::string>({kImageURL}),
+                                   image_callback.Get());
+
+  RunUntilIdle();
+
+  histogram().ExpectTotalCount(kUmaCacheLoadHistogramName, 0);
+  histogram().ExpectTotalCount(kUmaNetworkLoadHistogramName, 1);
+  histogram().ExpectTotalCount(kUmaImageLoadSuccessHistogramName, 1);
+  histogram().ExpectBucketCount(kUmaImageLoadSuccessHistogramName,
+                                FeedImageFetchResult::kSuccessFetched, 1);
+}
+
+TEST_F(FeedImageManagerTest, FetchImageFromNetworkEmptyHistogram) {
+  test_url_loader_factory()->AddResponse(kImageURL, "");
+  base::MockCallback<ImageFetchedCallback> image_callback;
+  feed_image_manager()->FetchImage(std::vector<std::string>({kImageURL}),
+                                   image_callback.Get());
+
+  RunUntilIdle();
+
+  histogram().ExpectTotalCount(kUmaCacheLoadHistogramName, 0);
+  histogram().ExpectTotalCount(kUmaNetworkLoadHistogramName, 0);
+  histogram().ExpectTotalCount(kUmaImageLoadSuccessHistogramName, 1);
+  histogram().ExpectBucketCount(kUmaImageLoadSuccessHistogramName,
+                                FeedImageFetchResult::kFailure, 1);
+}
+
+TEST_F(FeedImageManagerTest, NetworkDecodingErrorHistogram) {
+  test_url_loader_factory()->AddResponse(kImageURL, kImageData);
+  fake_image_decoder()->SetDecodingValid(false);
+
+  base::MockCallback<ImageFetchedCallback> image_callback;
+  feed_image_manager()->FetchImage(std::vector<std::string>({kImageURL}),
+                                   image_callback.Get());
+
+  RunUntilIdle();
+
+  histogram().ExpectTotalCount(kUmaCacheLoadHistogramName, 0);
+  histogram().ExpectTotalCount(kUmaNetworkLoadHistogramName, 0);
+  histogram().ExpectTotalCount(kUmaImageLoadSuccessHistogramName, 1);
+  histogram().ExpectBucketCount(kUmaImageLoadSuccessHistogramName,
+                                FeedImageFetchResult::kFailure, 1);
+}
+
 }  // namespace feed

tools/metrics/histograms/enums.xml

@@ -19603,6 +19603,12 @@ Called by update_net_error_codes.py.-->
   <int value="7" label="Supervised User Interstitial"/>
 </enum>
 
+<enum name="FeedImageFetchResult">
+  <int value="0" label="Fetch cache success"/>
+  <int value="1" label="Fetch network success"/>
+  <int value="2" label="Fetch failure"/>
+</enum>
+
 <enum name="FetchRequestMode">
   <int value="0" label="SameOrigin"/>
   <int value="1" label="NoCORS"/>

tools/metrics/histograms/histograms.xml

@@ -61134,6 +61134,28 @@ uploading your change for review.
   <summary>The default pane when the NTP is first opened.</summary>
 </histogram>
 
+<histogram name="NewTabPage.Feed.ImageFetchResult" enum="FeedImageFetchResult">
+  <owner>wylieb@chromium.org</owner>
+  <summary>
+    Android: Represents success/failure of Feed image loading. Recorded upon
+    each individual image retrieved from the feed_image_cache.
+  </summary>
+</histogram>
+
+<histogram name="NewTabPage.Feed.ImageLoadFromCacheTime" units="ms">
+  <owner>wylieb@chromium.org</owner>
+  <summary>
+    Android: The time it takes for Feed to load an image from the cache.
+  </summary>
+</histogram>
+
+<histogram name="NewTabPage.Feed.ImageLoadFromNetworkTime" units="ms">
+  <owner>wylieb@chromium.org</owner>
+  <summary>
+    Android: The time it takes for Feed to load an image from the network.
+  </summary>
+</histogram>
+
 <histogram name="NewTabPage.HoverTimeClicked">
   <obsolete>
     Deprecated 2016-02 (and not recorded for some time before that).