From 792364371b3489218036d41b558cb5f3cc80693c Mon Sep 17 00:00:00 2001 From: Brandon Wylie Date: Tue, 14 Aug 2018 03:35:37 +0000 Subject: [PATCH] [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 Reviewed-by: Robert Kaplow (slow) Reviewed-by: Filip Gorski Reviewed-by: Gang Wu Cr-Commit-Position: refs/heads/master@{#582816} --- components/feed/core/feed_image_manager.cc | 67 ++++++++++++-- components/feed/core/feed_image_manager.h | 19 ++++ .../feed/core/feed_image_manager_unittest.cc | 91 +++++++++++++++++++ tools/metrics/histograms/enums.xml | 6 ++ tools/metrics/histograms/histograms.xml | 22 +++++ 5 files changed, 197 insertions(+), 8 deletions(-) diff --git a/components/feed/core/feed_image_manager.cc b/components/feed/core/feed_image_manager.cc index 59b4960978f5cd..f4e81e5c1ecbe0 100644 --- a/components/feed/core/feed_image_manager.cc +++ b/components/feed/core/feed_image_manager.cc @@ -7,6 +7,9 @@ #include #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 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 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 diff --git a/components/feed/core/feed_image_manager.h b/components/feed/core/feed_image_manager.h index 13af33b8dcc0fc..a9681ced3ae152 100644 --- a/components/feed/core/feed_image_manager.h +++ b/components/feed/core/feed_image_manager.h @@ -9,10 +9,15 @@ #include #include +#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; +// 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_; std::unique_ptr image_database_; + // Track time it takes to get images. + base::flat_map url_timers_; + base::WeakPtrFactory weak_ptr_factory_; DISALLOW_COPY_AND_ASSIGN(FeedImageManager); diff --git a/components/feed/core/feed_image_manager_unittest.cc b/components/feed/core/feed_image_manager_unittest.cc index 26315409256e7b..35eb596cbb3ff0 100644 --- a/components/feed/core/feed_image_manager_unittest.cc +++ b/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 image_callback; + feed_image_manager()->FetchImage(std::vector({""}), + 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 image_callback; + feed_image_manager()->FetchImage(std::vector({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 image_callback; + feed_image_manager()->FetchImage(std::vector({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 image_callback; + feed_image_manager()->FetchImage(std::vector({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 image_callback; + feed_image_manager()->FetchImage(std::vector({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 diff --git a/tools/metrics/histograms/enums.xml b/tools/metrics/histograms/enums.xml index e9d95d94b52685..fe72d973f5dcf2 100644 --- a/tools/metrics/histograms/enums.xml +++ b/tools/metrics/histograms/enums.xml @@ -19603,6 +19603,12 @@ Called by update_net_error_codes.py.--> + + + + + + diff --git a/tools/metrics/histograms/histograms.xml b/tools/metrics/histograms/histograms.xml index 72982253b8e43f..b0ed027fd91267 100644 --- a/tools/metrics/histograms/histograms.xml +++ b/tools/metrics/histograms/histograms.xml @@ -61134,6 +61134,28 @@ uploading your change for review. The default pane when the NTP is first opened. + + wylieb@chromium.org + + Android: Represents success/failure of Feed image loading. Recorded upon + each individual image retrieved from the feed_image_cache. + + + + + wylieb@chromium.org + + Android: The time it takes for Feed to load an image from the cache. + + + + + wylieb@chromium.org + + Android: The time it takes for Feed to load an image from the network. + + + Deprecated 2016-02 (and not recorded for some time before that).