Log file manager APIs that take too long.

Only "very long" API calls are logged to the user's log. Regular "long"
APIs are logged to the drive-internals log.

BUG=904658

Change-Id: Ic959174f9927e7fe398706b8270a60c35df82e70
Reviewed-on: https://chromium-review.googlesource.com/c/1488393
Commit-Queue: Anand Mistry <amistry@chromium.org>
Reviewed-by: Sam McNally <sammc@chromium.org>
Reviewed-by: Luciano Pacheco <lucmult@chromium.org>
Cr-Commit-Position: refs/heads/master@{#635841}

chrome/browser/chromeos/extensions/file_manager/file_browser_handler_api.h

@@ -16,6 +16,7 @@
 #include <vector>
 
 #include "base/files/file_path.h"
+#include "chrome/browser/chromeos/extensions/file_manager/private_api_base.h"
 #include "extensions/browser/extension_function.h"
 
 class Browser;
@@ -80,7 +81,7 @@ class FileSelectorFactory {
 // The fileBrowserHandlerInternal.selectFile extension function implementation.
 // See the file description for more info.
 class FileBrowserHandlerInternalSelectFileFunction
-    : public UIThreadExtensionFunction {
+    : public extensions::LoggedUIThreadExtensionFunction {
  public:
   // Default constructor used in production code.
   // It will create its own FileSelectorFactory implementation, and set the

chrome/browser/chromeos/extensions/file_manager/private_api_base.cc

@@ -4,9 +4,10 @@
 
 #include "chrome/browser/chromeos/extensions/file_manager/private_api_base.h"
 
+#include <inttypes.h>
 #include <stdint.h>
 
-#include "base/strings/string_number_conversions.h"
+#include "base/strings/stringprintf.h"
 #include "chrome/browser/chromeos/extensions/file_manager/private_api_util.h"
 #include "chrome/browser/extensions/chrome_extension_function_details.h"
 #include "components/drive/event_logger.h"
@@ -14,36 +15,60 @@
 namespace extensions {
 namespace {
 
-const int kSlowOperationThresholdMs = 500;  // In ms.
+constexpr base::TimeDelta kDefaultSlowOperationThreshold =
+    base::TimeDelta::FromMilliseconds(500);
+constexpr base::TimeDelta kDefaultVerySlowOperationThreshold =
+    base::TimeDelta::FromSeconds(5);
 
 }  // namespace
 
 LoggedUIThreadExtensionFunction::LoggedUIThreadExtensionFunction()
-    : log_on_completion_(false) {
-  start_time_ = base::Time::Now();
+    : log_on_completion_(false),
+      slow_threshold_(kDefaultSlowOperationThreshold),
+      very_slow_threshold_(kDefaultVerySlowOperationThreshold) {
+  start_time_ = base::TimeTicks::Now();
 }
 
 LoggedUIThreadExtensionFunction::~LoggedUIThreadExtensionFunction() = default;
 
 void LoggedUIThreadExtensionFunction::OnResponded() {
+  base::TimeDelta elapsed = base::TimeTicks::Now() - start_time_;
+
   const ChromeExtensionFunctionDetails chrome_details(this);
   drive::EventLogger* logger =
       file_manager::util::GetLogger(chrome_details.GetProfile());
-  if (logger) {
-    int64_t elapsed = (base::Time::Now() - start_time_).InMilliseconds();
+  if (logger && log_on_completion_) {
     DCHECK(response_type());
     bool success = *response_type() == SUCCEEDED;
-    if (log_on_completion_) {
-      logger->Log(logging::LOG_INFO, "%s[%d] %s. (elapsed time: %sms)", name(),
-                  request_id(), success ? "succeeded" : "failed",
-                  base::NumberToString(elapsed).c_str());
-    } else if (elapsed >= kSlowOperationThresholdMs) {
-      logger->Log(logging::LOG_WARNING,
-                  "PEFORMANCE WARNING: %s[%d] was slow. (elapsed time: %sms)",
-                  name(), request_id(), base::NumberToString(elapsed).c_str());
+    logger->Log(logging::LOG_INFO, "%s[%d] %s. (elapsed time: %" PRId64 "ms)",
+                name(), request_id(), success ? "succeeded" : "failed",
+                elapsed.InMilliseconds());
+  }
+
+  // Log performance issues separately from completion.
+  if (elapsed >= very_slow_threshold_) {
+    auto log_message = base::StringPrintf(
+        "%s[%d] was VERY slow. (elapsed time: %" PRId64 "ms)", name(),
+        request_id(), elapsed.InMilliseconds());
+    LOG(WARNING) << log_message;
+    if (logger) {
+      logger->LogRawString(logging::LOG_ERROR,
+                           "PEFORMANCE WARNING: " + log_message);
     }
+  } else if (logger && elapsed >= slow_threshold_) {
+    logger->Log(logging::LOG_WARNING,
+                "PEFORMANCE WARNING: %s[%d] was slow. (elapsed time: %" PRId64
+                "ms)",
+                name(), request_id(), elapsed.InMilliseconds());
   }
   UIThreadExtensionFunction::OnResponded();
 }
 
+void LoggedUIThreadExtensionFunction::SetWarningThresholds(
+    base::TimeDelta slow_threshold,
+    base::TimeDelta very_slow_threshold) {
+  slow_threshold_ = slow_threshold;
+  very_slow_threshold_ = very_slow_threshold;
+}
+
 }  // namespace extensions

chrome/browser/chromeos/extensions/file_manager/private_api_base.h

@@ -30,14 +30,20 @@ class LoggedUIThreadExtensionFunction : public UIThreadExtensionFunction {
   // UIThreadExtensionFunction overrides.
   void OnResponded() override;
 
+  void SetWarningThresholds(base::TimeDelta slow_threshold,
+                            base::TimeDelta very_slow_threshold);
+
   // Sets the logging on completion flag. By default, logging is turned off.
   void set_log_on_completion(bool log_on_completion) {
     log_on_completion_ = log_on_completion;
   }
 
  private:
-  base::Time start_time_;
+  base::TimeTicks start_time_;
   bool log_on_completion_;
+
+  base::TimeDelta slow_threshold_;
+  base::TimeDelta very_slow_threshold_;
 };
 
 }  // namespace extensions

chrome/browser/chromeos/extensions/file_manager/private_api_drive.cc

@@ -90,6 +90,12 @@ const char kDriveConnectionReasonNoService[] = "no_service";
 // thumbnail. Given that we support hdpi devices, maximum dimension is 360.
 const int kFileManagerMaximumThumbnailDimension = 360;
 
+// Thresholds for logging slow operations.
+constexpr base::TimeDelta kDriveSlowOperationThreshold =
+    base::TimeDelta::FromSeconds(5);
+constexpr base::TimeDelta kDriveVerySlowOperationThreshold =
+    base::TimeDelta::FromMinutes(1);
+
 std::unique_ptr<std::string> GetShareUrlFromAlternateUrl(
     const GURL& alternate_url) {
   // Set |share_url| to a modified version of |alternate_url| that opens the
@@ -869,6 +875,8 @@ std::unique_ptr<base::ListValue> MakeBlankReturnValue() {
 FileManagerPrivateInternalGetEntryPropertiesFunction::
     FileManagerPrivateInternalGetEntryPropertiesFunction()
     : processed_count_(0) {
+  SetWarningThresholds(kDriveSlowOperationThreshold,
+                       kDriveVerySlowOperationThreshold);
 }
 
 FileManagerPrivateInternalGetEntryPropertiesFunction::
@@ -955,6 +963,12 @@ void FileManagerPrivateInternalGetEntryPropertiesFunction::
                        GetEntryProperties::Results::Create(properties_list_)));
 }
 
+FileManagerPrivateInternalPinDriveFileFunction::
+    FileManagerPrivateInternalPinDriveFileFunction() {
+  SetWarningThresholds(kDriveSlowOperationThreshold,
+                       kDriveVerySlowOperationThreshold);
+}
+
 ExtensionFunction::ResponseAction
 FileManagerPrivateInternalPinDriveFileFunction::Run() {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
@@ -1050,6 +1064,12 @@ void FileManagerPrivateInternalPinDriveFileFunction::OnPinStateSet(
   }
 }
 
+FileManagerPrivateInternalEnsureFileDownloadedFunction::
+    FileManagerPrivateInternalEnsureFileDownloadedFunction() {
+  SetWarningThresholds(kDriveSlowOperationThreshold,
+                       kDriveVerySlowOperationThreshold);
+}
+
 ExtensionFunction::ResponseAction
 FileManagerPrivateInternalEnsureFileDownloadedFunction::Run() {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
@@ -1141,6 +1161,11 @@ FileManagerPrivateInternalCancelFileTransfersFunction::Run() {
   return RespondNow(NoArguments());
 }
 
+FileManagerPrivateSearchDriveFunction::FileManagerPrivateSearchDriveFunction() {
+  SetWarningThresholds(kDriveSlowOperationThreshold,
+                       kDriveVerySlowOperationThreshold);
+}
+
 ExtensionFunction::ResponseAction FileManagerPrivateSearchDriveFunction::Run() {
   using extensions::api::file_manager_private::SearchDrive::Params;
   const std::unique_ptr<Params> params(Params::Create(*args_));
@@ -1245,6 +1270,12 @@ void FileManagerPrivateSearchDriveFunction::OnEntryDefinitionList(
       operation_start_);
 }
 
+FileManagerPrivateSearchDriveMetadataFunction::
+    FileManagerPrivateSearchDriveMetadataFunction() {
+  SetWarningThresholds(kDriveSlowOperationThreshold,
+                       kDriveVerySlowOperationThreshold);
+}
+
 ExtensionFunction::ResponseAction
 FileManagerPrivateSearchDriveMetadataFunction::Run() {
   using api::file_manager_private::SearchDriveMetadata::Params;
@@ -1486,6 +1517,12 @@ FileManagerPrivateGetDriveConnectionStateFunction::Run() {
           result)));
 }
 
+FileManagerPrivateRequestAccessTokenFunction::
+    FileManagerPrivateRequestAccessTokenFunction() {
+  SetWarningThresholds(kDriveSlowOperationThreshold,
+                       kDriveVerySlowOperationThreshold);
+}
+
 ExtensionFunction::ResponseAction
 FileManagerPrivateRequestAccessTokenFunction::Run() {
   using extensions::api::file_manager_private::RequestAccessToken::Params;
@@ -1520,6 +1557,12 @@ void FileManagerPrivateRequestAccessTokenFunction::OnAccessTokenFetched(
   Respond(OneArgument(std::make_unique<base::Value>(access_token)));
 }
 
+FileManagerPrivateInternalRequestDriveShareFunction::
+    FileManagerPrivateInternalRequestDriveShareFunction() {
+  SetWarningThresholds(kDriveSlowOperationThreshold,
+                       kDriveVerySlowOperationThreshold);
+}
+
 ExtensionFunction::ResponseAction
 FileManagerPrivateInternalRequestDriveShareFunction::Run() {
   using extensions::api::file_manager_private_internal::RequestDriveShare::
@@ -1584,7 +1627,10 @@ void FileManagerPrivateInternalRequestDriveShareFunction::OnAddPermission(
 }
 
 FileManagerPrivateInternalGetDownloadUrlFunction::
-    FileManagerPrivateInternalGetDownloadUrlFunction() = default;
+    FileManagerPrivateInternalGetDownloadUrlFunction() {
+  SetWarningThresholds(kDriveSlowOperationThreshold,
+                       kDriveVerySlowOperationThreshold);
+}
 
 FileManagerPrivateInternalGetDownloadUrlFunction::
     ~FileManagerPrivateInternalGetDownloadUrlFunction() = default;
@@ -1736,7 +1782,10 @@ void FileManagerPrivateInternalGetDownloadUrlFunction::OnGotMetadata(
 }
 
 FileManagerPrivateInternalGetThumbnailFunction::
-    FileManagerPrivateInternalGetThumbnailFunction() = default;
+    FileManagerPrivateInternalGetThumbnailFunction() {
+  SetWarningThresholds(kDriveSlowOperationThreshold,
+                       kDriveVerySlowOperationThreshold);
+}
 
 FileManagerPrivateInternalGetThumbnailFunction::
     ~FileManagerPrivateInternalGetThumbnailFunction() = default;

chrome/browser/chromeos/extensions/file_manager/private_api_drive.h

@@ -41,6 +41,8 @@ struct EntryProperties;
 class FileManagerPrivateInternalEnsureFileDownloadedFunction
     : public LoggedUIThreadExtensionFunction {
  public:
+  FileManagerPrivateInternalEnsureFileDownloadedFunction();
+
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivateInternal.ensureFileDownloaded",
                              FILEMANAGERPRIVATE_ENSUREFILEDOWNLOADED)
 
@@ -89,6 +91,8 @@ class FileManagerPrivateInternalGetEntryPropertiesFunction
 class FileManagerPrivateInternalPinDriveFileFunction
     : public LoggedUIThreadExtensionFunction {
  public:
+  FileManagerPrivateInternalPinDriveFileFunction();
+
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivateInternal.pinDriveFile",
                              FILEMANAGERPRIVATEINTERNAL_PINDRIVEFILE)
 
@@ -110,7 +114,7 @@ class FileManagerPrivateInternalPinDriveFileFunction
 
 // Implements the chrome.fileManagerPrivate.cancelFileTransfers method.
 class FileManagerPrivateInternalCancelFileTransfersFunction
-    : public LoggedUIThreadExtensionFunction {
+    : public UIThreadExtensionFunction {
  public:
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivateInternal.cancelFileTransfers",
                              FILEMANAGERPRIVATEINTERNAL_CANCELFILETRANSFERS)
@@ -127,6 +131,8 @@ class FileManagerPrivateSearchDriveFunction
  public:
   typedef std::vector<drive::SearchResultInfo> SearchResultInfoList;
 
+  FileManagerPrivateSearchDriveFunction();
+
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivate.searchDrive",
                              FILEMANAGERPRIVATE_SEARCHDRIVE)
 
@@ -167,6 +173,8 @@ class FileManagerPrivateSearchDriveMetadataFunction
     kOffline,
   };
 
+  FileManagerPrivateSearchDriveMetadataFunction();
+
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivate.searchDriveMetadata",
                              FILEMANAGERPRIVATE_SEARCHDRIVEMETADATA)
 
@@ -214,6 +222,8 @@ class FileManagerPrivateGetDriveConnectionStateFunction
 class FileManagerPrivateRequestAccessTokenFunction
     : public LoggedUIThreadExtensionFunction {
  public:
+  FileManagerPrivateRequestAccessTokenFunction();
+
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivate.requestAccessToken",
                              FILEMANAGERPRIVATE_REQUESTACCESSTOKEN)
 
@@ -232,6 +242,8 @@ class FileManagerPrivateRequestAccessTokenFunction
 class FileManagerPrivateInternalRequestDriveShareFunction
     : public LoggedUIThreadExtensionFunction {
  public:
+  FileManagerPrivateInternalRequestDriveShareFunction();
+
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivateInternal.requestDriveShare",
                              FILEMANAGERPRIVATEINTERNAL_REQUESTDRIVESHARE)
 

chrome/browser/chromeos/extensions/file_manager/private_api_file_system.h

@@ -291,7 +291,7 @@ class FileManagerPrivateCancelCopyFunction
 // Implements the chrome.fileManagerPrivateInternal.resolveIsolatedEntries
 // method.
 class FileManagerPrivateInternalResolveIsolatedEntriesFunction
-    : public UIThreadExtensionFunction {
+    : public LoggedUIThreadExtensionFunction {
  public:
   DECLARE_EXTENSION_FUNCTION(
       "fileManagerPrivateInternal.resolveIsolatedEntries",
@@ -380,7 +380,7 @@ class FileManagerPrivateIsUMAEnabledFunction
 
 // Implements the chrome.fileManagerPrivate.setEntryTag method.
 class FileManagerPrivateInternalSetEntryTagFunction
-    : public UIThreadExtensionFunction {
+    : public LoggedUIThreadExtensionFunction {
  public:
   FileManagerPrivateInternalSetEntryTagFunction();
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivateInternal.setEntryTag",

chrome/browser/chromeos/extensions/file_manager/private_api_misc.cc

@@ -80,6 +80,12 @@ using api::file_manager_private::ProfileInfo;
 
 const char kCWSScope[] = "https://www.googleapis.com/auth/chromewebstore";
 
+// Thresholds for mountCrostini() API.
+constexpr base::TimeDelta kMountCrostiniSlowOperationThreshold =
+    base::TimeDelta::FromSeconds(10);
+constexpr base::TimeDelta kMountCrostiniVerySlowOperationThreshold =
+    base::TimeDelta::FromSeconds(30);
+
 // Obtains the current app window.
 AppWindow* GetCurrentAppWindow(UIThreadExtensionFunction* function) {
   content::WebContents* const contents = function->GetSenderWebContents();
@@ -642,7 +648,11 @@ FileManagerPrivateIsCrostiniEnabledFunction::Run() {
 }
 
 FileManagerPrivateMountCrostiniFunction::
-    FileManagerPrivateMountCrostiniFunction() = default;
+    FileManagerPrivateMountCrostiniFunction() {
+  // Mounting crostini shares may require the crostini VM to be started.
+  SetWarningThresholds(kMountCrostiniSlowOperationThreshold,
+                       kMountCrostiniVerySlowOperationThreshold);
+}
 
 FileManagerPrivateMountCrostiniFunction::
     ~FileManagerPrivateMountCrostiniFunction() = default;

chrome/browser/chromeos/extensions/file_manager/private_api_misc.h

@@ -249,7 +249,7 @@ class FileManagerPrivateAddProvidedFileSystemFunction
 
 // Implements the chrome.fileManagerPrivate.configureVolume method.
 class FileManagerPrivateConfigureVolumeFunction
-    : public UIThreadExtensionFunction {
+    : public LoggedUIThreadExtensionFunction {
  public:
   FileManagerPrivateConfigureVolumeFunction();
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivate.configureVolume",
@@ -305,7 +305,7 @@ class FileManagerPrivateMountCrostiniFunction
 // Implements the chrome.fileManagerPrivate.sharePathsWithCrostini
 // method.  Shares specified paths.
 class FileManagerPrivateInternalSharePathsWithCrostiniFunction
-    : public UIThreadExtensionFunction {
+    : public LoggedUIThreadExtensionFunction {
  public:
   DECLARE_EXTENSION_FUNCTION(
       "fileManagerPrivateInternal.sharePathsWithCrostini",
@@ -326,7 +326,7 @@ class FileManagerPrivateInternalSharePathsWithCrostiniFunction
 // Implements the chrome.fileManagerPrivate.unsharePathWithCrostini
 // method.  Unshares specified path.
 class FileManagerPrivateInternalUnsharePathWithCrostiniFunction
-    : public UIThreadExtensionFunction {
+    : public LoggedUIThreadExtensionFunction {
  public:
   DECLARE_EXTENSION_FUNCTION(
       "fileManagerPrivateInternal.unsharePathWithCrostini",
@@ -367,7 +367,7 @@ class FileManagerPrivateInternalGetCrostiniSharedPathsFunction
 // Implements the chrome.fileManagerPrivate.getLinuxPackageInfo method.
 // Retrieves information about a Linux package.
 class FileManagerPrivateInternalGetLinuxPackageInfoFunction
-    : public UIThreadExtensionFunction {
+    : public LoggedUIThreadExtensionFunction {
  public:
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivateInternal.getLinuxPackageInfo",
                              FILEMANAGERPRIVATEINTERNAL_GETLINUXPACKAGEINFO)
@@ -387,7 +387,7 @@ class FileManagerPrivateInternalGetLinuxPackageInfoFunction
 // Implements the chrome.fileManagerPrivate.installLinuxPackage method.
 // Starts installation of a Linux package.
 class FileManagerPrivateInternalInstallLinuxPackageFunction
-    : public UIThreadExtensionFunction {
+    : public LoggedUIThreadExtensionFunction {
  public:
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivateInternal.installLinuxPackage",
                              FILEMANAGERPRIVATEINTERNAL_INSTALLLINUXPACKAGE)
@@ -405,7 +405,7 @@ class FileManagerPrivateInternalInstallLinuxPackageFunction
 
 // Implements the chrome.fileManagerPrivate.getCustomActions method.
 class FileManagerPrivateInternalGetCustomActionsFunction
-    : public UIThreadExtensionFunction {
+    : public LoggedUIThreadExtensionFunction {
  public:
   FileManagerPrivateInternalGetCustomActionsFunction();
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivateInternal.getCustomActions",
@@ -424,7 +424,7 @@ class FileManagerPrivateInternalGetCustomActionsFunction
 
 // Implements the chrome.fileManagerPrivate.executeCustomAction method.
 class FileManagerPrivateInternalExecuteCustomActionFunction
-    : public UIThreadExtensionFunction {
+    : public LoggedUIThreadExtensionFunction {
  public:
   FileManagerPrivateInternalExecuteCustomActionFunction();
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivateInternal.executeCustomAction",
@@ -443,7 +443,7 @@ class FileManagerPrivateInternalExecuteCustomActionFunction
 
 // Implements the chrome.fileManagerPrivateInternal.getRecentFiles method.
 class FileManagerPrivateInternalGetRecentFilesFunction
-    : public UIThreadExtensionFunction {
+    : public LoggedUIThreadExtensionFunction {
  public:
   FileManagerPrivateInternalGetRecentFilesFunction();
   DECLARE_EXTENSION_FUNCTION("fileManagerPrivateInternal.getRecentFiles",