Adding a utility method to simplify method tracing
Change-Id: I79ef0aa5d65b933f4b7f0520fc8bac26e366da2d
diff --git a/src/com/android/launcher3/FirstFrameAnimatorHelper.java b/src/com/android/launcher3/FirstFrameAnimatorHelper.java
index 3cbc989..cea7e43 100644
--- a/src/com/android/launcher3/FirstFrameAnimatorHelper.java
+++ b/src/com/android/launcher3/FirstFrameAnimatorHelper.java
@@ -24,6 +24,7 @@
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 @@
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 99f3803..d1c84b3 100644
--- a/src/com/android/launcher3/Launcher.java
+++ b/src/com/android/launcher3/Launcher.java
@@ -130,6 +130,7 @@
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.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 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 @@
.penaltyDeath()
.build());
}
- if (LauncherAppState.PROFILE_STARTUP) {
- Trace.beginSection("Launcher-onCreate");
- }
+ TraceHelper.beginSection("Launcher-onCreate");
if (mLauncherCallbacks != null) {
mLauncherCallbacks.preOnCreate();
@@ -365,6 +361,7 @@
overrideTheme(wallpaperColorInfo.isDark(), wallpaperColorInfo.supportsDarkText());
super.onCreate(savedInstanceState);
+ TraceHelper.partitionSection("Launcher-onCreate", "super call");
LauncherAppState app = LauncherAppState.getInstance(this);
@@ -415,10 +412,6 @@
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 @@
if (mLauncherCallbacks != null) {
mLauncherCallbacks.onCreate(savedInstanceState);
}
+
+ TraceHelper.endSection("Launcher-onCreate");
}
@Override
@@ -887,17 +882,13 @@
@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 @@
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 @@
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 @@
mLauncherCallbacks.onResume();
}
+ TraceHelper.endSection("ON_RESUME");
}
@Override
@@ -1574,10 +1553,7 @@
@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 @@
}
}
- if (DEBUG_RESUME_TIME) {
- Log.d(TAG, "Time spent in onNewIntent: " + (System.currentTimeMillis() - startTime));
- }
+ TraceHelper.endSection("NEW_INTENT");
}
@Override
@@ -3043,10 +3017,7 @@
* 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 @@
if (mHotseat != null) {
mHotseat.resetLayout();
}
- if (LauncherAppState.PROFILE_STARTUP) {
- Trace.endSection();
- }
+ TraceHelper.endSection("startBinding");
}
@Override
@@ -3264,10 +3233,7 @@
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 @@
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 @@
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 @@
}
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 @@
if (waitUntilResume(r)) {
return;
}
- if (LauncherAppState.PROFILE_STARTUP) {
- Trace.beginSection("Page bind completed");
- }
+ TraceHelper.beginSection("finishBindingItems");
mWorkspace.restoreInstanceStateForRemainingPages();
setWorkspaceLoading(false);
@@ -3480,9 +3434,7 @@
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 1ffe41b..7bebf44 100644
--- a/src/com/android/launcher3/LauncherAppState.java
+++ b/src/com/android/launcher3/LauncherAppState.java
@@ -42,8 +42,6 @@
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 b31df98..f222a97 100644
--- a/src/com/android/launcher3/LauncherProvider.java
+++ b/src/com/android/launcher3/LauncherProvider.java
@@ -149,9 +149,6 @@
*/
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 @@
// 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 e1b208a..5386fb4 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.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 @@
* - 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 @@
}
}
+ 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 @@
}
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 @@
LauncherModel.updateWorkspaceScreenOrder(context, mBgDataModel.workspaceScreens);
}
}
- if (LauncherAppState.PROFILE_STARTUP) {
- Trace.endSection();
- }
}
private void updateIconCache() {
@@ -793,21 +777,13 @@
}
private void loadAllApps() {
- final long loadTime = DEBUG_LOADERS ? SystemClock.uptimeMillis() : 0;
-
final List<UserHandle> 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<LauncherActivityInfo> 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 @@
}
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 0000000..5b66fcd
--- /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<String, MutableLong> sUpTimes =
+ ENABLED ? new ArrayMap<String, MutableLong>() : 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));
+ }
+ }
+ }
+}