Small improvements to Looper Idle tracing

- Avoid overlapping the Looper.queueIdle with the first task run
  post-idle
- include consistent stats in every queueIdle trace, and just do the
  burst logging info via an instant() trace

BUG=

Review URL: https://chromiumcodereview.appspot.com/15927042

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@205588 0039d316-1c4b-4281-b951-d872f2087c98

1 files changed, 11 insertions, 8 deletions

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 de75f21..85954e3 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, mNumTasksSinceLastIdle + " tasks since last idle.");
             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;