Adding a utility method to simplify method tracing

Change-Id: I79ef0aa5d65b933f4b7f0520fc8bac26e366da2d

6 files changed, 130 insertions, 127 deletions

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<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 @@ 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<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));
+            }
+        }
+    }
+}