From 4ec026930bfbbb5d8923f359c80b465d4b0ccda2 Mon Sep 17 00:00:00 2001 From: Narayan Kamath Date: Tue, 3 May 2016 11:55:23 +0100 Subject: [PATCH] PackageManager : Log stats about the optimizing apps dialog. Logs the following parameters : - Total time spent optimizing apps. - Total number of apps that were dexopted. TESTED: with adb logcat -b events: 05-04 15:24:16.303 2065 2065 I sysui_action: [402,3] 05-04 15:24:16.303 2065 2065 I sysui_action: [403,34] 05-04 15:24:16.303 2065 2065 I sysui_action: [404,0] 05-04 15:24:16.304 2065 2065 I sysui_action: [405,163] 05-04 15:24:16.304 2065 2065 I sysui_action: [406,12168] This shows that: - 3 apps were optimized - 34 apps were skipped - 0 apps failed to optimize - dialog showed a total of 37 (3 + 34 + 0) apps - system has 163 optimizable packages - a total of 12.2 seconds was spent in the optimizing apps dialog bug: 28528058 bug: 28544474 Change-Id: I9eb5229a1589ca0df57d3fc03102992fa90a877f --- proto/src/metrics_constants.proto | 15 ++++ .../server/pm/PackageManagerService.java | 72 ++++++++++++++----- 2 files changed, 70 insertions(+), 17 deletions(-) diff --git a/proto/src/metrics_constants.proto b/proto/src/metrics_constants.proto index c417fe8ae5cc6..fd4c71e12fb27 100644 --- a/proto/src/metrics_constants.proto +++ b/proto/src/metrics_constants.proto @@ -2191,6 +2191,21 @@ message MetricsEvent { // CATEGORY: SETTINGS ACCOUNTS_WORK_PROFILE_SETTINGS = 401; + // The number of packages optimized during the optimizing apps dialog. + OPTIMIZING_APPS_NUM_PKGS_DEXOPTED = 402; + + // The number of packages which did not need optimizing during the optimizing apps dialog. + OPTIMIZING_APPS_NUM_PKGS_SKIPPED = 403; + + // The number of packages which failed to optimize during the optimizing apps dialog. + OPTIMIZING_APPS_NUM_PKGS_FAILED = 404; + + // The number of optimizable packages in the system. + OPTIMIZING_APPS_NUM_PKGS_TOTAL = 405; + + // The total amount of time the user was blocked on the optimizing apps dialog. + OPTIMIZING_APPS_TOTAL_TIME_MS = 406; + // Add new aosp constants above this line. // END OF AOSP CONSTANTS } diff --git a/services/core/java/com/android/server/pm/PackageManagerService.java b/services/core/java/com/android/server/pm/PackageManagerService.java index ff79b24ddb2e5..b9b79c87330f1 100644 --- a/services/core/java/com/android/server/pm/PackageManagerService.java +++ b/services/core/java/com/android/server/pm/PackageManagerService.java @@ -226,6 +226,8 @@ import com.android.internal.app.IMediaContainerService; import com.android.internal.app.ResolverActivity; import com.android.internal.content.NativeLibraryHelper; import com.android.internal.content.PackageHelper; +import com.android.internal.logging.MetricsLogger; +import com.android.internal.logging.MetricsProto.MetricsEvent; import com.android.internal.os.IParcelFileDescriptorFactory; import com.android.internal.os.InstallerConnection.InstallerException; import com.android.internal.os.SomeArgs; @@ -7162,37 +7164,70 @@ public class PackageManagerService extends IPackageManager.Stub { pkgs = PackageManagerServiceUtils.getPackagesForDexopt(mPackages.values(), this); } - int curr = 0; - int total = pkgs.size(); + int numberOfPackagesVisited = 0; + int numberOfPackagesOptimized = 0; + int numberOfPackagesSkipped = 0; + int numberOfPackagesFailed = 0; + final int numberOfPackagesToDexopt = pkgs.size(); + final long startTime = System.nanoTime(); + for (PackageParser.Package pkg : pkgs) { - curr++; + numberOfPackagesVisited++; if (!PackageDexOptimizer.canOptimizePackage(pkg)) { if (DEBUG_DEXOPT) { Log.i(TAG, "Skipping update of of non-optimizable app " + pkg.packageName); } + numberOfPackagesSkipped++; continue; } if (DEBUG_DEXOPT) { - Log.i(TAG, "Extracting app " + curr + " of " + total + ": " + pkg.packageName); + Log.i(TAG, "Updating app " + numberOfPackagesVisited + " of " + + numberOfPackagesToDexopt + ": " + pkg.packageName); } if (!isFirstBoot()) { try { ActivityManagerNative.getDefault().showBootMessage( mContext.getResources().getString(R.string.android_upgrading_apk, - curr, total), true); + numberOfPackagesVisited, numberOfPackagesToDexopt), true); } catch (RemoteException e) { } } - performDexOpt(pkg.packageName, + int dexOptStatus = performDexOptTraced(pkg.packageName, null /* instructionSet */, true /* checkProfiles */, - causeFirstBoot ? REASON_FIRST_BOOT : REASON_BOOT, + getCompilerFilterForReason(causeFirstBoot ? REASON_FIRST_BOOT : REASON_BOOT), false /* force */); + switch (dexOptStatus) { + case PackageDexOptimizer.DEX_OPT_PERFORMED: + numberOfPackagesOptimized++; + break; + case PackageDexOptimizer.DEX_OPT_SKIPPED: + numberOfPackagesSkipped++; + break; + case PackageDexOptimizer.DEX_OPT_FAILED: + numberOfPackagesFailed++; + break; + default: + Log.e(TAG, "Unexpected dexopt return code " + dexOptStatus); + break; + } } + + final int elapsedTime = (int) TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startTime); + MetricsLogger.action(mContext, + MetricsEvent.OPTIMIZING_APPS_NUM_PKGS_DEXOPTED, numberOfPackagesOptimized); + MetricsLogger.action(mContext, + MetricsEvent.OPTIMIZING_APPS_NUM_PKGS_SKIPPED, numberOfPackagesSkipped); + MetricsLogger.action(mContext, + MetricsEvent.OPTIMIZING_APPS_NUM_PKGS_FAILED, numberOfPackagesFailed); + MetricsLogger.action(mContext, + MetricsEvent.OPTIMIZING_APPS_NUM_PKGS_TOTAL, getOptimizablePackages().size()); + MetricsLogger.action(mContext, + MetricsEvent.OPTIMIZING_APPS_TOTAL_TIME_MS, elapsedTime); } @Override @@ -7209,25 +7244,28 @@ public class PackageManagerService extends IPackageManager.Stub { // TODO: this is not used nor needed. Delete it. @Override public boolean performDexOptIfNeeded(String packageName, String instructionSet) { - return performDexOptTraced(packageName, instructionSet, false /* checkProfiles */, - getFullCompilerFilter(), false /* force */); + int dexOptStatus = performDexOptTraced(packageName, instructionSet, + false /* checkProfiles */, getFullCompilerFilter(), false /* force */); + return dexOptStatus != PackageDexOptimizer.DEX_OPT_FAILED; } @Override public boolean performDexOpt(String packageName, String instructionSet, boolean checkProfiles, int compileReason, boolean force) { - return performDexOptTraced(packageName, instructionSet, checkProfiles, + int dexOptStatus = performDexOptTraced(packageName, instructionSet, checkProfiles, getCompilerFilterForReason(compileReason), force); + return dexOptStatus != PackageDexOptimizer.DEX_OPT_FAILED; } @Override public boolean performDexOptMode(String packageName, String instructionSet, boolean checkProfiles, String targetCompilerFilter, boolean force) { - return performDexOptTraced(packageName, instructionSet, checkProfiles, + int dexOptStatus = performDexOptTraced(packageName, instructionSet, checkProfiles, targetCompilerFilter, force); + return dexOptStatus != PackageDexOptimizer.DEX_OPT_FAILED; } - private boolean performDexOptTraced(String packageName, String instructionSet, + private int performDexOptTraced(String packageName, String instructionSet, boolean checkProfiles, String targetCompilerFilter, boolean force) { Trace.traceBegin(TRACE_TAG_PACKAGE_MANAGER, "dexopt"); try { @@ -7240,14 +7278,15 @@ public class PackageManagerService extends IPackageManager.Stub { // Run dexopt on a given package. Returns true if dexopt did not fail, i.e. // if the package can now be considered up to date for the given filter. - private boolean performDexOptInternal(String packageName, String instructionSet, + private int performDexOptInternal(String packageName, String instructionSet, boolean checkProfiles, String targetCompilerFilter, boolean force) { PackageParser.Package p; final String targetInstructionSet; synchronized (mPackages) { p = mPackages.get(packageName); if (p == null) { - return false; + // Package could not be found. Report failure. + return PackageDexOptimizer.DEX_OPT_FAILED; } mPackageUsage.write(false); @@ -7258,9 +7297,8 @@ public class PackageManagerService extends IPackageManager.Stub { try { synchronized (mInstallLock) { final String[] instructionSets = new String[] { targetInstructionSet }; - int result = performDexOptInternalWithDependenciesLI(p, instructionSets, - checkProfiles, targetCompilerFilter, force); - return result != PackageDexOptimizer.DEX_OPT_FAILED; + return performDexOptInternalWithDependenciesLI(p, instructionSets, checkProfiles, + targetCompilerFilter, force); } } finally { Binder.restoreCallingIdentity(callingId);