Small improvements to Looper Idle tracing

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

Index: content/public/android/java/src/org/chromium/content/common/TraceEvent.java
diff --git a/content/public/android/java/src/org/chromium/content/common/TraceEvent.java b/content/public/android/java/src/org/chromium/content/common/TraceEvent.java
index de75f215f25d69fb130e46c20802e303af1016fe..d595323bef30c2b6f165bf28c10f15a211525b0b 100644
--- a/content/public/android/java/src/org/chromium/content/common/TraceEvent.java
+++ b/content/public/android/java/src/org/chromium/content/common/TraceEvent.java
@@ -75,11 +75,9 @@ public class TraceEvent {
         @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);
             }
         }
@@ -104,9 +102,11 @@ public class TraceEvent {
         }
 
         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();
         }
@@ -115,31 +115,34 @@ public class TraceEvent {
             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;