Offline pages tracing instrumentation: new and improvements

This change adds new and improves existing code instrumentation for
tracing reports. They should help both with performance tracking and
memory usage investigation.

Bug: 806137, 793109
Change-Id: I45fd4ef567e83c174d09cf41424a961c13adaf23
Reviewed-on: https://chromium-review.googlesource.com/888087
Commit-Queue: Carlos Knippschild <carlosk@chromium.org>
Reviewed-by: David Trainor <dtrainor@chromium.org>
Reviewed-by: Yafei Duan <romax@chromium.org>
Cr-Commit-Position: refs/heads/master@{#533059}

chrome/android/java/src/org/chromium/chrome/browser/download/ui/DownloadManagerUi.java

@@ -22,6 +22,7 @@ import org.chromium.base.CollectionUtil;
 import org.chromium.base.DiscardableReferencePool;
 import org.chromium.base.FileUtils;
 import org.chromium.base.ObserverList;
+import org.chromium.base.TraceEvent;
 import org.chromium.base.VisibleForTesting;
 import org.chromium.base.metrics.RecordHistogram;
 import org.chromium.base.metrics.RecordUserAction;
@@ -212,6 +213,7 @@ public class DownloadManagerUi
     public DownloadManagerUi(Activity activity, boolean isOffTheRecord,
             ComponentName parentComponent, boolean isSeparateActivity,
             SnackbarManager snackbarManager) {
+        TraceEvent.startAsync("DownloadManagerUi shown", hashCode());
         mActivity = activity;
         ChromeApplication application = (ChromeApplication) activity.getApplication();
         mBackendProvider = sProviderForTests == null
@@ -302,6 +304,7 @@ public class DownloadManagerUi
         mBackendProvider.destroy();
 
         mSelectableListLayout.onDestroyed();
+        TraceEvent.finishAsync("DownloadManagerUi shown", hashCode());
     }
 
     /**

components/offline_pages/core/downloads/download_ui_adapter.cc

@@ -8,6 +8,7 @@
 #include "base/guid.h"
 #include "base/logging.h"
 #include "base/threading/thread_task_runner_handle.h"
+#include "base/trace_event/trace_event.h"
 #include "components/offline_pages/core/background/request_coordinator.h"
 #include "components/offline_pages/core/background/save_page_request.h"
 #include "components/offline_pages/core/client_namespace_constants.h"
@@ -386,6 +387,8 @@ void DownloadUIAdapter::ClearCache() {
   }
   items_.clear();
   state_ = State::NOT_LOADED;
+  TRACE_EVENT_ASYNC_END0("offline_pages", "DownloadUIAdapter: items cached",
+                         this);
 }
 
 void DownloadUIAdapter::OnOfflinePagesLoaded(
@@ -437,6 +440,8 @@ void DownloadUIAdapter::OnRequestsLoaded(
   request_coordinator_->AddObserver(this);
 
   state_ = State::LOADED;
+  TRACE_EVENT_ASYNC_BEGIN1("offline_pages", "DownloadUIAdapter: items cached",
+                           this, "initial count", items_.size());
   for (auto& observer : observers_)
     observer.OnItemsAvailable(this);
 

components/offline_pages/core/model/clear_legacy_temporary_pages_task.cc

@@ -10,6 +10,7 @@
 
 #include "base/bind.h"
 #include "base/files/file_util.h"
+#include "base/trace_event/trace_event.h"
 #include "components/offline_pages/core/client_policy_controller.h"
 #include "components/offline_pages/core/offline_page_metadata_store_sql.h"
 #include "components/offline_pages/core/offline_store_utils.h"
@@ -128,6 +129,8 @@ ClearLegacyTemporaryPagesTask::ClearLegacyTemporaryPagesTask(
 ClearLegacyTemporaryPagesTask::~ClearLegacyTemporaryPagesTask() {}
 
 void ClearLegacyTemporaryPagesTask::Run() {
+  TRACE_EVENT_ASYNC_BEGIN0("offline_pages",
+                           "ClearLegacyTemporaryPagesTask running", this);
   std::vector<std::string> temp_namespaces =
       policy_controller_->GetNamespacesRemovedOnCacheReset();
   store_->Execute(
@@ -145,6 +148,9 @@ void ClearLegacyTemporaryPagesTask::OnClearLegacyTemporaryPagesDone(
   // indicating which part failed.
   DVLOG(1) << "ClearLegacyTemporaryPagesTask returns with result: " << result;
   TaskComplete();
+  TRACE_EVENT_ASYNC_END1("offline_pages",
+                         "ClearLegacyTemporaryPagesTask running", this,
+                         "result", result);
 }
 
 }  // namespace offline_pages

components/offline_pages/core/model/clear_storage_task.cc

@@ -16,6 +16,7 @@
 #include "base/time/clock.h"
 #include "base/time/default_clock.h"
 #include "base/time/time.h"
+#include "base/trace_event/trace_event.h"
 #include "components/offline_pages/core/client_policy_controller.h"
 #include "components/offline_pages/core/offline_page_client_policy.h"
 #include "components/offline_pages/core/offline_page_metadata_store_sql.h"
@@ -240,6 +241,7 @@ ClearStorageTask::ClearStorageTask(OfflinePageMetadataStoreSQL* store,
 ClearStorageTask::~ClearStorageTask() {}
 
 void ClearStorageTask::Run() {
+  TRACE_EVENT_ASYNC_BEGIN0("offline_pages", "ClearStorageTask running", this);
   archive_manager_->GetStorageStats(
       base::Bind(&ClearStorageTask::OnGetStorageStatsDone,
                  weak_ptr_factory_.GetWeakPtr()));
@@ -272,6 +274,9 @@ void ClearStorageTask::InformClearStorageDone(size_t pages_cleared,
                                               ClearStorageResult result) {
   std::move(callback_).Run(pages_cleared, result);
   TaskComplete();
+  TRACE_EVENT_ASYNC_END2("offline_pages", "ClearStorageTask running", this,
+                         "result", static_cast<int>(result), "pages_cleared",
+                         pages_cleared);
 }
 
 }  // namespace offline_pages

components/offline_pages/core/model/persistent_pages_consistency_check_task.cc

@@ -14,6 +14,7 @@
 #include "base/files/file_enumerator.h"
 #include "base/files/file_util.h"
 #include "base/metrics/histogram_macros.h"
+#include "base/trace_event/trace_event.h"
 #include "components/offline_pages/core/client_policy_controller.h"
 #include "components/offline_pages/core/offline_page_metadata_store_sql.h"
 #include "components/offline_pages/core/offline_page_types.h"
@@ -172,6 +173,8 @@ PersistentPagesConsistencyCheckTask::PersistentPagesConsistencyCheckTask(
 PersistentPagesConsistencyCheckTask::~PersistentPagesConsistencyCheckTask() {}
 
 void PersistentPagesConsistencyCheckTask::Run() {
+  TRACE_EVENT_ASYNC_BEGIN0("offline_pages",
+                           "PersistentPagesConsistencyCheckTask running", this);
   std::vector<std::string> namespaces = policy_controller_->GetAllNamespaces();
   std::vector<std::string> persistent_namespace_names;
   for (const auto& name_space : namespaces) {
@@ -191,6 +194,9 @@ void PersistentPagesConsistencyCheckTask::OnCheckConsistencyDone(
   UMA_HISTOGRAM_ENUMERATION("OfflinePages.ConsistencyCheck.Persistent.Result",
                             result, SyncOperationResult::RESULT_COUNT);
   TaskComplete();
+  TRACE_EVENT_ASYNC_END1("offline_pages",
+                         "PersistentPagesConsistencyCheckTask running", this,
+                         "result", static_cast<int>(result));
 }
 
 }  // namespace offline_pages

components/offline_pages/core/model/temporary_pages_consistency_check_task.cc

@@ -14,6 +14,7 @@
 #include "base/files/file_enumerator.h"
 #include "base/files/file_util.h"
 #include "base/metrics/histogram_macros.h"
+#include "base/trace_event/trace_event.h"
 #include "components/offline_pages/core/client_policy_controller.h"
 #include "components/offline_pages/core/offline_page_metadata_store_sql.h"
 #include "components/offline_pages/core/offline_page_types.h"
@@ -171,6 +172,8 @@ TemporaryPagesConsistencyCheckTask::TemporaryPagesConsistencyCheckTask(
 TemporaryPagesConsistencyCheckTask::~TemporaryPagesConsistencyCheckTask() {}
 
 void TemporaryPagesConsistencyCheckTask::Run() {
+  TRACE_EVENT_ASYNC_BEGIN0("offline_pages",
+                           "TemporaryPagesConsistencyCheckTask running", this);
   std::vector<std::string> temp_namespaces =
       policy_controller_->GetNamespacesRemovedOnCacheReset();
   store_->Execute(
@@ -185,6 +188,9 @@ void TemporaryPagesConsistencyCheckTask::OnCheckConsistencyDone(
   UMA_HISTOGRAM_ENUMERATION("OfflinePages.ConsistencyCheck.Temporary.Result",
                             result, SyncOperationResult::RESULT_COUNT);
   TaskComplete();
+  TRACE_EVENT_ASYNC_END1("offline_pages",
+                         "TemporaryPagesConsistencyCheckTask running", this,
+                         "result", static_cast<int>(result));
 }
 
 }  // namespace offline_pages

components/offline_pages/core/offline_page_metadata_store_sql.h

@@ -123,9 +123,9 @@ class OfflinePageMetadataStoreSQL : public OfflinePageMetadataStore {
       return;
     }
 
-    TRACE_EVENT_ASYNC_BEGIN1("offline_pages",
-                             "Metadata Store: Command execution", this,
-                             "is store loaded", state_ == StoreState::LOADED);
+    TRACE_EVENT_ASYNC_BEGIN1("offline_pages", "Metadata Store: task execution",
+                             this, "is store loaded",
+                             state_ == StoreState::LOADED);
     // This if allows to run commands later, after store was given a chance to
     // initialize. They would be failing immediately otherwise.
     if (state_ == StoreState::INITIALIZING) {
@@ -133,9 +133,8 @@ class OfflinePageMetadataStoreSQL : public OfflinePageMetadataStore {
           base::BindOnce(&OfflinePageMetadataStoreSQL::Execute<T>,
                          weak_ptr_factory_.GetWeakPtr(),
                          std::move(run_callback), std::move(result_callback)));
-      TRACE_EVENT_ASYNC_END1("offline_pages",
-                             "Metadata Store: Command execution", this,
-                             "postponed", true);
+      TRACE_EVENT_ASYNC_END1("offline_pages", "Metadata Store: task execution",
+                             this, "postponed", true);
       return;
     }
 
@@ -172,10 +171,16 @@ class OfflinePageMetadataStoreSQL : public OfflinePageMetadataStore {
         base::BindOnce(&OfflinePageMetadataStoreSQL::CloseInternal,
                        closing_weak_ptr_factory_.GetWeakPtr()),
         kClosingDelay);
-    TRACE_EVENT_ASYNC_END0("offline_pages", "Metadata Store: Command execution",
-                           this);
 
+    // Note: the time recorded for this trace step will include thread hop wait
+    // times to the background thread and back.
+    TRACE_EVENT_ASYNC_STEP_PAST0(
+        "offline_pages", "Metadata Store: task execution", this, "Task");
     std::move(result_callback).Run(std::move(result));
+    TRACE_EVENT_ASYNC_STEP_PAST0(
+        "offline_pages", "Metadata Store: task execution", this, "Callback");
+    TRACE_EVENT_ASYNC_END0("offline_pages", "Metadata Store: task execution",
+                           this);
   }
 
   // Internal function initiating the closing.

components/offline_pages/core/prefetch/prefetch_downloader_impl.cc

@@ -9,6 +9,7 @@
 #include "base/strings/string_util.h"
 #include "base/time/default_clock.h"
 #include "base/time/time.h"
+#include "base/trace_event/trace_event.h"
 #include "components/download/public/background_service/download_params.h"
 #include "components/download/public/background_service/download_service.h"
 #include "components/offline_pages/core/offline_event_logger.h"
@@ -146,6 +147,15 @@ void PrefetchDownloaderImpl::OnDownloadServiceReady(
         success_downloads) {
   DCHECK_EQ(DownloadServiceStatus::INITIALIZING, download_service_status_);
   download_service_status_ = DownloadServiceStatus::STARTED;
+  // Given the imposed simultaneous downloads limits, outstanding_download_ids
+  // will only ever contain a handful of elements and so only a negligible
+  // performance impact is expected from the trace-only loop below.
+  for (const std::string& outstanding_download_id : outstanding_download_ids) {
+    TRACE_EVENT_ASYNC_BEGIN2(
+        "offline_pages", "PrefetchDownloaderImpl: downloading article",
+        std::hash<std::string>{}(outstanding_download_id), "download_id",
+        outstanding_download_id, "resumed after restart", "true");
+  }
 
   prefetch_service_->GetLogger()->RecordActivity("Downloader: Service ready.");
 
@@ -177,6 +187,9 @@ void PrefetchDownloaderImpl::OnDownloadSucceeded(
     const std::string& download_id,
     const base::FilePath& file_path,
     int64_t file_size) {
+  TRACE_EVENT_ASYNC_END1(
+      "offline_pages", "PrefetchDownloaderImpl: downloading article",
+      std::hash<std::string>{}(download_id), "succeeded", "true");
   prefetch_service_->GetLogger()->RecordActivity(
       "Downloader: Download succeeded, download_id=" + download_id);
   NotifyDispatcher(prefetch_service_,
@@ -184,6 +197,9 @@ void PrefetchDownloaderImpl::OnDownloadSucceeded(
 }
 
 void PrefetchDownloaderImpl::OnDownloadFailed(const std::string& download_id) {
+  TRACE_EVENT_ASYNC_END1(
+      "offline_pages", "PrefetchDownloaderImpl: downloading article",
+      std::hash<std::string>{}(download_id), "succeeded", "false");
   PrefetchDownloadResult result;
   result.download_id = download_id;
   prefetch_service_->GetLogger()->RecordActivity(
@@ -206,8 +222,13 @@ void PrefetchDownloaderImpl::OnStartDownload(
   // to simplify the control flow since this situation should rarely happen. The
   // Download.Service.Request.StartResult.OfflinePage histogram tracks these
   // cases and would signal the need to revisit this decision.
-  if (result != download::DownloadParams::StartResult::ACCEPTED)
+  if (result != download::DownloadParams::StartResult::ACCEPTED) {
     OnDownloadFailed(download_id);
+  } else {
+    TRACE_EVENT_ASYNC_BEGIN1(
+        "offline_pages", "PrefetchDownloaderImpl: downloading article",
+        std::hash<std::string>{}(download_id), "download_id", download_id);
+  }
 }
 
 void PrefetchDownloaderImpl::CleanupDownloads(

components/offline_pages/core/prefetch/store/prefetch_store.h

@@ -86,7 +86,7 @@ class PrefetchStore {
     }
 
     TRACE_EVENT_ASYNC_BEGIN1(
-        "offline_pages", "Prefetch Store: Command execution", this,
+        "offline_pages", "Prefetch Store: task execution", this,
         "is store loaded",
         initialization_status_ == InitializationStatus::SUCCESS);
     // Ensure that any scheduled close operations are canceled.
@@ -128,10 +128,16 @@ class PrefetchStore {
         base::BindOnce(&PrefetchStore::CloseInternal,
                        closing_weak_ptr_factory_.GetWeakPtr()),
         kClosingDelay);
-    TRACE_EVENT_ASYNC_END0("offline_pages", "Prefetch Store: Command execution",
-                           this);
 
+    // Note: the time recorded for this trace step will include thread hop wait
+    // times to the background thread and back.
+    TRACE_EVENT_ASYNC_STEP_PAST0(
+        "offline_pages", "Prefetch Store: task execution", this, "Task");
     std::move(result_callback).Run(std::move(result));
+    TRACE_EVENT_ASYNC_STEP_PAST0(
+        "offline_pages", "Prefetch Store: task execution", this, "Callback");
+    TRACE_EVENT_ASYNC_END0("offline_pages", "Prefetch Store: task execution",
+                           this);
   }
 
   // Internal function initiating the closing.