From fca6bc9dce9f78981a972a22a2e195e0e1f0a4cf Mon Sep 17 00:00:00 2001 From: Sunny Goyal Date: Thu, 28 Sep 2017 16:28:34 -0700 Subject: Adding a utility method to simplify method tracing Change-Id: I79ef0aa5d65b933f4b7f0520fc8bac26e366da2d --- .../launcher3/FirstFrameAnimatorHelper.java | 10 +-- src/com/android/launcher3/Launcher.java | 88 +++++---------------- src/com/android/launcher3/LauncherAppState.java | 2 - src/com/android/launcher3/LauncherProvider.java | 7 -- src/com/android/launcher3/model/LoaderTask.java | 60 ++++----------- src/com/android/launcher3/util/TraceHelper.java | 90 ++++++++++++++++++++++ 6 files changed, 130 insertions(+), 127 deletions(-) create mode 100644 src/com/android/launcher3/util/TraceHelper.java diff --git a/src/com/android/launcher3/FirstFrameAnimatorHelper.java b/src/com/android/launcher3/FirstFrameAnimatorHelper.java index 3cbc989eb..cea7e431a 100644 --- a/src/com/android/launcher3/FirstFrameAnimatorHelper.java +++ b/src/com/android/launcher3/FirstFrameAnimatorHelper.java @@ -24,6 +24,7 @@ import android.view.View; import android.view.ViewPropertyAnimator; import android.view.ViewTreeObserver; import com.android.launcher3.util.Thunk; +import com.android.launcher3.util.TraceHelper; /* * This is a helper class that listens to updates from the corresponding animation. @@ -71,15 +72,12 @@ public class FirstFrameAnimatorHelper extends AnimatorListenerAdapter if (sGlobalDrawListener != null) { view.getViewTreeObserver().removeOnDrawListener(sGlobalDrawListener); } + + TraceHelper.beginSection("TICK"); sGlobalDrawListener = new ViewTreeObserver.OnDrawListener() { - private long mTime = System.currentTimeMillis(); public void onDraw() { sGlobalFrameCounter++; - if (DEBUG) { - long newTime = System.currentTimeMillis(); - Log.d(TAG, "TICK " + (newTime - mTime)); - mTime = newTime; - } + TraceHelper.partitionSection("TICK", "Frame drawn"); } }; view.getViewTreeObserver().addOnDrawListener(sGlobalDrawListener); diff --git a/src/com/android/launcher3/Launcher.java b/src/com/android/launcher3/Launcher.java index 99f3803b1..d1c84b30e 100644 --- a/src/com/android/launcher3/Launcher.java +++ b/src/com/android/launcher3/Launcher.java @@ -130,6 +130,7 @@ import com.android.launcher3.util.SystemUiController; import com.android.launcher3.util.TestingUtils; import com.android.launcher3.util.Themes; import com.android.launcher3.util.Thunk; +import com.android.launcher3.util.TraceHelper; import com.android.launcher3.util.ViewOnDrawExecutor; import com.android.launcher3.widget.PendingAddShortcutInfo; import com.android.launcher3.widget.PendingAddWidgetInfo; @@ -142,7 +143,6 @@ import java.io.FileDescriptor; import java.io.PrintWriter; import java.util.ArrayList; import java.util.Collection; -import java.util.HashMap; import java.util.HashSet; import java.util.List; import java.util.Set; @@ -162,9 +162,7 @@ public class Launcher extends BaseActivity public static final String TAG = "Launcher"; static final boolean LOGD = false; - static final boolean DEBUG_WIDGETS = false; static final boolean DEBUG_STRICT_MODE = false; - static final boolean DEBUG_RESUME_TIME = false; private static final int REQUEST_CREATE_SHORTCUT = 1; private static final int REQUEST_CREATE_APPWIDGET = 5; @@ -352,9 +350,7 @@ public class Launcher extends BaseActivity .penaltyDeath() .build()); } - if (LauncherAppState.PROFILE_STARTUP) { - Trace.beginSection("Launcher-onCreate"); - } + TraceHelper.beginSection("Launcher-onCreate"); if (mLauncherCallbacks != null) { mLauncherCallbacks.preOnCreate(); @@ -365,6 +361,7 @@ public class Launcher extends BaseActivity overrideTheme(wallpaperColorInfo.isDark(), wallpaperColorInfo.supportsDarkText()); super.onCreate(savedInstanceState); + TraceHelper.partitionSection("Launcher-onCreate", "super call"); LauncherAppState app = LauncherAppState.getInstance(this); @@ -415,10 +412,6 @@ public class Launcher extends BaseActivity restoreState(savedInstanceState); - if (LauncherAppState.PROFILE_STARTUP) { - Trace.endSection(); - } - // We only load the page synchronously if the user rotates (or triggers a // configuration change) while launcher is in the foreground int currentScreen = PagedView.INVALID_RESTORE_PAGE; @@ -473,6 +466,8 @@ public class Launcher extends BaseActivity if (mLauncherCallbacks != null) { mLauncherCallbacks.onCreate(savedInstanceState); } + + TraceHelper.endSection("Launcher-onCreate"); } @Override @@ -887,17 +882,13 @@ public class Launcher extends BaseActivity @Override protected void onResume() { - long startTime = 0; - if (DEBUG_RESUME_TIME) { - startTime = System.currentTimeMillis(); - Log.v(TAG, "Launcher.onResume()"); - } - + TraceHelper.beginSection("ON_RESUME"); if (mLauncherCallbacks != null) { mLauncherCallbacks.preOnResume(); } - super.onResume(); + TraceHelper.partitionSection("ON_RESUME", "superCall"); + getUserEventDispatcher().resetElapsedSessionMillis(); // Restore the previous launcher state @@ -926,19 +917,10 @@ public class Launcher extends BaseActivity if (mBindOnResumeCallbacks.size() > 0) { // We might have postponed some bind calls until onResume (see waitUntilResume) -- // execute them here - long startTimeCallbacks = 0; - if (DEBUG_RESUME_TIME) { - startTimeCallbacks = System.currentTimeMillis(); - } - for (int i = 0; i < mBindOnResumeCallbacks.size(); i++) { mBindOnResumeCallbacks.get(i).run(); } mBindOnResumeCallbacks.clear(); - if (DEBUG_RESUME_TIME) { - Log.d(TAG, "Time spent processing callbacks in onResume: " + - (System.currentTimeMillis() - startTimeCallbacks)); - } } if (mOnResumeCallbacks.size() > 0) { for (int i = 0; i < mOnResumeCallbacks.size(); i++) { @@ -962,10 +944,6 @@ public class Launcher extends BaseActivity getWorkspace().reinflateWidgetsIfNecessary(); } - if (DEBUG_RESUME_TIME) { - Log.d(TAG, "Time spent in onResume: " + (System.currentTimeMillis() - startTime)); - } - updateInteraction(Workspace.State.NORMAL, mWorkspace.getState()); mWorkspace.onResume(); @@ -983,6 +961,7 @@ public class Launcher extends BaseActivity mLauncherCallbacks.onResume(); } + TraceHelper.endSection("ON_RESUME"); } @Override @@ -1574,10 +1553,7 @@ public class Launcher extends BaseActivity @Override protected void onNewIntent(Intent intent) { - long startTime = 0; - if (DEBUG_RESUME_TIME) { - startTime = System.currentTimeMillis(); - } + TraceHelper.beginSection("NEW_INTENT"); super.onNewIntent(intent); boolean alreadyOnHome = mHasFocus && ((intent.getFlags() & @@ -1674,9 +1650,7 @@ public class Launcher extends BaseActivity } } - if (DEBUG_RESUME_TIME) { - Log.d(TAG, "Time spent in onNewIntent: " + (System.currentTimeMillis() - startTime)); - } + TraceHelper.endSection("NEW_INTENT"); } @Override @@ -3043,10 +3017,7 @@ public class Launcher extends BaseActivity * Implementation of the method from LauncherModel.Callbacks. */ public void startBinding() { - if (LauncherAppState.PROFILE_STARTUP) { - Trace.beginSection("Starting page bind"); - } - + TraceHelper.beginSection("startBinding"); AbstractFloatingView.closeAllOpenViews(this); setWorkspaceLoading(true); @@ -3058,9 +3029,7 @@ public class Launcher extends BaseActivity if (mHotseat != null) { mHotseat.resetLayout(); } - if (LauncherAppState.PROFILE_STARTUP) { - Trace.endSection(); - } + TraceHelper.endSection("startBinding"); } @Override @@ -3264,10 +3233,7 @@ public class Launcher extends BaseActivity return view; } - final long start = DEBUG_WIDGETS ? SystemClock.uptimeMillis() : 0; - if (DEBUG_WIDGETS) { - Log.d(TAG, "bindAppWidget: " + item); - } + TraceHelper.beginSection("BIND_WIDGET"); final LauncherAppWidgetProviderInfo appWidgetInfo; @@ -3285,11 +3251,9 @@ public class Launcher extends BaseActivity if (!item.hasRestoreFlag(LauncherAppWidgetInfo.FLAG_PROVIDER_NOT_READY) && (item.restoreStatus != LauncherAppWidgetInfo.RESTORE_COMPLETED)) { if (appWidgetInfo == null) { - if (DEBUG_WIDGETS) { - Log.d(TAG, "Removing restored widget: id=" + item.appWidgetId - + " belongs to component " + item.providerName - + ", as the provider is null"); - } + Log.d(TAG, "Removing restored widget: id=" + item.appWidgetId + + " belongs to component " + item.providerName + + ", as the provider is null"); getModelWriter().deleteItemFromDatabase(item); return null; } @@ -3350,11 +3314,6 @@ public class Launcher extends BaseActivity final AppWidgetHostView view; if (item.restoreStatus == LauncherAppWidgetInfo.RESTORE_COMPLETED) { - if (DEBUG_WIDGETS) { - Log.d(TAG, "bindAppWidget: id=" + item.appWidgetId + " belongs to component " - + appWidgetInfo.provider); - } - // Verify that we own the widget if (appWidgetInfo == null) { FileLog.e(TAG, "Removing invalid widget: id=" + item.appWidgetId); @@ -3370,10 +3329,7 @@ public class Launcher extends BaseActivity } prepareAppWidget(view, item); - if (DEBUG_WIDGETS) { - Log.d(TAG, "bound widget id="+item.appWidgetId+" in " - + (SystemClock.uptimeMillis()-start) + "ms"); - } + TraceHelper.endSection("BIND_WIDGET", "id=" + item.appWidgetId); return view; } @@ -3459,9 +3415,7 @@ public class Launcher extends BaseActivity if (waitUntilResume(r)) { return; } - if (LauncherAppState.PROFILE_STARTUP) { - Trace.beginSection("Page bind completed"); - } + TraceHelper.beginSection("finishBindingItems"); mWorkspace.restoreInstanceStateForRemainingPages(); setWorkspaceLoading(false); @@ -3480,9 +3434,7 @@ public class Launcher extends BaseActivity if (mLauncherCallbacks != null) { mLauncherCallbacks.finishBindingItems(false); } - if (LauncherAppState.PROFILE_STARTUP) { - Trace.endSection(); - } + TraceHelper.endSection("finishBindingItems"); } private boolean canRunNewAppsAnimation() { diff --git a/src/com/android/launcher3/LauncherAppState.java b/src/com/android/launcher3/LauncherAppState.java index 1ffe41bc6..7bebf445b 100644 --- a/src/com/android/launcher3/LauncherAppState.java +++ b/src/com/android/launcher3/LauncherAppState.java @@ -42,8 +42,6 @@ import static com.android.launcher3.SettingsActivity.NOTIFICATION_BADGING; public class LauncherAppState { - public static final boolean PROFILE_STARTUP = FeatureFlags.IS_DOGFOOD_BUILD; - // We do not need any synchronization for this variable as its only written on UI thread. private static LauncherAppState INSTANCE; diff --git a/src/com/android/launcher3/LauncherProvider.java b/src/com/android/launcher3/LauncherProvider.java index b31df9894..f222a97bb 100644 --- a/src/com/android/launcher3/LauncherProvider.java +++ b/src/com/android/launcher3/LauncherProvider.java @@ -149,9 +149,6 @@ public class LauncherProvider extends ContentProvider { */ protected synchronized void createDbIfNotExists() { if (mOpenHelper == null) { - if (LauncherAppState.PROFILE_STARTUP) { - Trace.beginSection("Opening workspace DB"); - } mOpenHelper = new DatabaseHelper(getContext(), mListenerHandler); if (RestoreDbTask.isPending(getContext())) { @@ -162,10 +159,6 @@ public class LauncherProvider extends ContentProvider { // executed again. RestoreDbTask.setPending(getContext(), false); } - - if (LauncherAppState.PROFILE_STARTUP) { - Trace.endSection(); - } } } diff --git a/src/com/android/launcher3/model/LoaderTask.java b/src/com/android/launcher3/model/LoaderTask.java index e1b208a05..5386fb4a5 100644 --- a/src/com/android/launcher3/model/LoaderTask.java +++ b/src/com/android/launcher3/model/LoaderTask.java @@ -66,6 +66,7 @@ import com.android.launcher3.util.ManagedProfileHeuristic; import com.android.launcher3.util.MultiHashMap; import com.android.launcher3.util.PackageManagerHelper; import com.android.launcher3.util.Provider; +import com.android.launcher3.util.TraceHelper; import java.util.ArrayList; import java.util.Collections; @@ -85,7 +86,6 @@ import static com.android.launcher3.folder.ClippedFolderIconLayoutRule.MAX_NUM_I * - deep shortcuts within apps */ public class LoaderTask implements Runnable { - private static final boolean DEBUG_LOADERS = false; private static final String TAG = "LoaderTask"; private final LauncherAppState mApp; @@ -142,73 +142,64 @@ public class LoaderTask implements Runnable { } } + TraceHelper.beginSection(TAG); try (LauncherModel.LoaderTransaction transaction = mApp.getModel().beginLoader(this)) { - long now = 0; - if (DEBUG_LOADERS) Log.d(TAG, "step 1.1: loading workspace"); + TraceHelper.partitionSection(TAG, "step 1.1: loading workspace"); loadWorkspace(); verifyNotStopped(); - if (DEBUG_LOADERS) Log.d(TAG, "step 1.2: bind workspace workspace"); + TraceHelper.partitionSection(TAG, "step 1.2: bind workspace workspace"); mResults.bindWorkspace(); // Take a break - if (DEBUG_LOADERS) { - Log.d(TAG, "step 1 completed, wait for idle"); - now = SystemClock.uptimeMillis(); - } + TraceHelper.partitionSection(TAG, "step 1 completed, wait for idle"); waitForIdle(); - if (DEBUG_LOADERS) Log.d(TAG, "Waited " + (SystemClock.uptimeMillis() - now) + "ms"); verifyNotStopped(); // second step - if (DEBUG_LOADERS) Log.d(TAG, "step 2.1: loading all apps"); + TraceHelper.partitionSection(TAG, "step 2.1: loading all apps"); loadAllApps(); - if (DEBUG_LOADERS) Log.d(TAG, "step 2.2: Binding all apps"); + TraceHelper.partitionSection(TAG, "step 2.2: Binding all apps"); verifyNotStopped(); mResults.bindAllApps(); verifyNotStopped(); - if (DEBUG_LOADERS) Log.d(TAG, "step 2.3: Update icon cache"); + TraceHelper.partitionSection(TAG, "step 2.3: Update icon cache"); updateIconCache(); // Take a break - if (DEBUG_LOADERS) { - Log.d(TAG, "step 2 completed, wait for idle"); - now = SystemClock.uptimeMillis(); - } + TraceHelper.partitionSection(TAG, "step 2 completed, wait for idle"); waitForIdle(); - if (DEBUG_LOADERS) Log.d(TAG, "Waited " + (SystemClock.uptimeMillis() - now) + "ms"); verifyNotStopped(); // third step - if (DEBUG_LOADERS) Log.d(TAG, "step 3.1: loading deep shortcuts"); + TraceHelper.partitionSection(TAG, "step 3.1: loading deep shortcuts"); loadDeepShortcuts(); verifyNotStopped(); - if (DEBUG_LOADERS) Log.d(TAG, "step 3.2: bind deep shortcuts"); + TraceHelper.partitionSection(TAG, "step 3.2: bind deep shortcuts"); mResults.bindDeepShortcuts(); // Take a break - if (DEBUG_LOADERS) Log.d(TAG, "step 3 completed, wait for idle"); + TraceHelper.partitionSection(TAG, "step 3 completed, wait for idle"); waitForIdle(); verifyNotStopped(); // fourth step - if (DEBUG_LOADERS) Log.d(TAG, "step 4.1: loading widgets"); + TraceHelper.partitionSection(TAG, "step 4.1: loading widgets"); mBgDataModel.widgetsModel.update(mApp, null); verifyNotStopped(); - if (DEBUG_LOADERS) Log.d(TAG, "step 4.2: Binding widgets"); + TraceHelper.partitionSection(TAG, "step 4.2: Binding widgets"); mResults.bindWidgets(); transaction.commit(); } catch (CancellationException e) { // Loader stopped, ignore - if (DEBUG_LOADERS) { - Log.d(TAG, "Loader cancelled", e); - } + TraceHelper.partitionSection(TAG, "Cancelled"); } + TraceHelper.endSection(TAG); } public synchronized void stopLocked() { @@ -217,10 +208,6 @@ public class LoaderTask implements Runnable { } private void loadWorkspace() { - if (LauncherAppState.PROFILE_STARTUP) { - Trace.beginSection("Loading Workspace"); - } - final Context context = mApp.getContext(); final ContentResolver contentResolver = context.getContentResolver(); final PackageManagerHelper pmHelper = new PackageManagerHelper(context); @@ -766,9 +753,6 @@ public class LoaderTask implements Runnable { LauncherModel.updateWorkspaceScreenOrder(context, mBgDataModel.workspaceScreens); } } - if (LauncherAppState.PROFILE_STARTUP) { - Trace.endSection(); - } } private void updateIconCache() { @@ -793,21 +777,13 @@ public class LoaderTask implements Runnable { } private void loadAllApps() { - final long loadTime = DEBUG_LOADERS ? SystemClock.uptimeMillis() : 0; - final List profiles = mUserManager.getUserProfiles(); // Clear the list of apps mBgAllAppsList.clear(); for (UserHandle user : profiles) { // Query for the set of apps - final long qiaTime = DEBUG_LOADERS ? SystemClock.uptimeMillis() : 0; final List apps = mLauncherApps.getActivityList(null, user); - if (DEBUG_LOADERS) { - Log.d(TAG, "getActivityList took " - + (SystemClock.uptimeMillis()-qiaTime) + "ms for user " + user); - Log.d(TAG, "getActivityList got " + apps.size() + " apps for user " + user); - } // Fail if we don't have any apps // TODO: Fix this. Only fail for the current user. if (apps == null || apps.isEmpty()) { @@ -834,10 +810,6 @@ public class LoaderTask implements Runnable { } mBgAllAppsList.added = new ArrayList<>(); - if (DEBUG_LOADERS) { - Log.d(TAG, "All apps loaded in in " - + (SystemClock.uptimeMillis() - loadTime) + "ms"); - } } private void loadDeepShortcuts() { diff --git a/src/com/android/launcher3/util/TraceHelper.java b/src/com/android/launcher3/util/TraceHelper.java new file mode 100644 index 000000000..5b66fcda6 --- /dev/null +++ b/src/com/android/launcher3/util/TraceHelper.java @@ -0,0 +1,90 @@ +/* + * Copyright (C) 2017 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package com.android.launcher3.util; + +import android.os.SystemClock; +import android.os.Trace; +import android.util.ArrayMap; +import android.util.Log; +import android.util.MutableLong; + +import com.android.launcher3.config.FeatureFlags; + +/** + * A wrapper around {@link Trace} to allow easier proguarding for production builds. + * + * To enable any tracing log, execute the following command: + * $ adb shell setprop log.tag.TAGNAME VERBOSE + */ +public class TraceHelper { + + private static final boolean ENABLED = FeatureFlags.IS_DOGFOOD_BUILD; + + private static final boolean SYSTEM_TRACE = true; + private static final ArrayMap sUpTimes = + ENABLED ? new ArrayMap() : null; + + public static void beginSection(String sectionName) { + if (ENABLED) { + MutableLong time = sUpTimes.get(sectionName); + if (time == null) { + time = new MutableLong(Log.isLoggable(sectionName, Log.VERBOSE) ? 0 : -1); + sUpTimes.put(sectionName, time); + } + if (time.value >= 0) { + if (SYSTEM_TRACE) { + Trace.beginSection(sectionName); + } + time.value = SystemClock.uptimeMillis(); + } + } + } + + public static void partitionSection(String sectionName, String partition) { + if (ENABLED) { + MutableLong time = sUpTimes.get(sectionName); + if (time.value >= 0) { + + if (SYSTEM_TRACE) { + Trace.endSection(); + Trace.beginSection(sectionName); + } + + long now = SystemClock.uptimeMillis(); + Log.d(sectionName, partition + " : " + (now - time.value)); + time.value = now; + } + } + } + + public static void endSection(String sectionName) { + if (ENABLED) { + endSection(sectionName, "End"); + } + } + + public static void endSection(String sectionName, String msg) { + if (ENABLED) { + MutableLong time = sUpTimes.get(sectionName); + if (time.value >= 0) { + if (SYSTEM_TRACE) { + Trace.endSection(); + } + Log.d(sectionName, msg + " : " + (SystemClock.uptimeMillis() - time.value)); + } + } + } +} -- cgit v1.2.3