Small improvements to Looper Idle tracing

content/public/android/java/src/org/chromium/content/common/TraceEvent.java

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 package org.chromium.content.common;
 
 import android.os.Build;
 import android.os.Looper;
 import android.os.MessageQueue;
 import android.os.SystemClock;
@@ skipping 57 matching lines @@
         private int mNumTasksSeen = 0;
         private int mNumIdlesSeen = 0;
         private int mNumTasksSinceLastIdle = 0;
 
         // State
         private boolean mIdleMonitorAttached = false;
 
         @Override
         public void println(final String line) {
             if (line.startsWith(">")) {
-                TraceEvent.begin(DISPATCH_EVENT_NAME, line);
                 begin(line);
             } else {
                 assert line.startsWith("<");
-                TraceEvent.end(DISPATCH_EVENT_NAME);
                 end(line);
             }
         }
 
         // Called from within the begin/end methods only.
         // This method can only execute on the looper thread, because that is
         // the only thread that is permitted to call Looper.myqueue().
         private final void syncIdleMonitoring() {
             if (sEnabled && !mIdleMonitorAttached) {
                 // approximate start time for computational purposes
                 mLastIdleStartedAt = SystemClock.elapsedRealtime();
                 Looper.myQueue().addIdleHandler(
                         LooperMonitor.getInstance());
                 mIdleMonitorAttached = true;
                 Log.v(TAG, "attached idle handler");
             } else if (mIdleMonitorAttached && !sEnabled) {
                 Looper.myQueue().removeIdleHandler(
                         LooperMonitor.getInstance());
                 mIdleMonitorAttached = false;
                 Log.v(TAG, "detached idle handler");
             }
         }
 
         private final void begin(final String line) {
+            // Close-out any prior 'idle' period before starting new task.
             if (mNumTasksSinceLastIdle == 0) {
                 TraceEvent.end(IDLE_EVENT_NAME);
             }
+            TraceEvent.begin(DISPATCH_EVENT_NAME, line);
             mLastWorkStartedAt = SystemClock.elapsedRealtime();
             syncIdleMonitoring();
         }
 
         private final void end(final String line) {
             final long elapsed = SystemClock.elapsedRealtime()
                     - mLastWorkStartedAt;
             if (elapsed > MIN_INTERESTING_DURATION_MILLIS) {
-                Log.w(TAG, "observed a task that took "
+                traceAndLog(Log.WARN, "observed a task that took "
                         + elapsed + "ms: " + line);
             }
+            TraceEvent.end(DISPATCH_EVENT_NAME);
             syncIdleMonitoring();
             mNumTasksSeen++;
             mNumTasksSinceLastIdle++;
         }
 
+        private static void traceAndLog(int level, String message) {
+            TraceEvent.instant("TraceEvent.LooperMonitor:IdleStats", message);
+            Log.println(level, TAG, message);
+        }
+
         @Override
         public final boolean queueIdle() {
             final long now =  SystemClock.elapsedRealtime();
             if (mLastIdleStartedAt == 0) mLastIdleStartedAt = now;
             final long elapsed = now - mLastIdleStartedAt;
             mNumIdlesSeen++;
+            TraceEvent.begin(IDLE_EVENT_NAME, "Tasks since last idle " + mNumTasksSinceLastIdle);

[Andrew Hayden (chromium.org), 2013/06/08 08:32:07]

nit:
mNumTasksSinceLastIdle + " tasks since last idle"
or
"Tasks since last idle: " + mNumTasksSinceLastIdle

             if (elapsed > MIN_INTERESTING_BURST_DURATION_MILLIS) {
                 // Dump stats
                 String statsString = mNumTasksSeen + " tasks and "
                         + mNumIdlesSeen + " idles processed so far, "
                         + mNumTasksSinceLastIdle + " tasks bursted and "
                         + elapsed + "ms elapsed since last idle";
-                Log.d(TAG, statsString);
-                instant("TraceEvent.LooperMonitor:IdleStats", statsString);
-                TraceEvent.begin(IDLE_EVENT_NAME, statsString);
-            } else {
-                TraceEvent.begin(IDLE_EVENT_NAME);
+                traceAndLog(Log.DEBUG, statsString);
             }
             mLastIdleStartedAt = now;
             mNumTasksSinceLastIdle = 0;
             return true; // stay installed
         }
 
         // Holder for monitor avoids unnecessary construction on non-debug runs
         private final static class Holder {
             private final static LooperMonitor sInstance = new LooperMonitor();
         }
@@ skipping 238 matching lines @@
 
     private static native boolean nativeTraceEnabled();
     private static native void nativeStartATrace();
     private static native void nativeStopATrace();
     private static native void nativeInstant(String name, String arg);
     private static native void nativeBegin(String name, String arg);
     private static native void nativeEnd(String name, String arg);
     private static native void nativeStartAsync(String name, long id, String arg);
     private static native void nativeFinishAsync(String name, long id, String arg);
 }