Collect telemetry data for System Server Loopers.
Adds LooperStats and LooperStatsService which set a static
Looper.Observer to record the count of dispatched messages and
cpu/latency information. The aggregated stats are collected by
Westworld as pulled atoms.
The collection is disabled by default and requires a manual call to
enable:
adb shell cmd looper_stats enable
Test: Unit tests and tested manually that the collected data seems
reasonable.
Change-Id: I7162fbca4e324f62887f95df3405205cbe4416ca
diff --git a/cmds/statsd/src/atoms.proto b/cmds/statsd/src/atoms.proto
index 6065bbf..cbea484 100644
--- a/cmds/statsd/src/atoms.proto
+++ b/cmds/statsd/src/atoms.proto
@@ -131,7 +131,7 @@
}
// Pulled events will start at field 10000.
- // Next: 10024
+ // Next: 10025
oneof pulled {
WifiBytesTransfer wifi_bytes_transfer = 10000;
WifiBytesTransferByFgBg wifi_bytes_transfer_by_fg_bg = 10001;
@@ -157,6 +157,7 @@
Temperature temperature = 10021;
BinderCalls binder_calls = 10022;
BinderCallsExceptions binder_calls_exceptions = 10023;
+ LooperStats looper_stats = 10024;
}
// DO NOT USE field numbers above 100,000 in AOSP. Field numbers above
@@ -2182,3 +2183,50 @@
// Total number of exceptions.
optional int64 exception_count = 2;
}
+
+message LooperStats {
+ // Currently not collected and always set to 0.
+ optional int32 uid = 1 [(is_uid) = true];
+
+ // Fully qualified class name of the handler target class.
+ //
+ // This field does not contain PII. This is a system server class name.
+ optional string handler_class_name = 2;
+
+ // The name of the thread that runs the Looper.
+ //
+ // This field does not contain PII. This is a system server thread name.
+ optional string looper_thread_name = 3;
+
+ // The name of the dispatched message.
+ //
+ // This field does not contain PII. This is a system server constant or class
+ // name.
+ optional string message_name = 4;
+
+ // Total number of successfully dispatched messages.
+ optional int64 message_count = 5;
+
+ // Total number of messages that failed dispatching.
+ optional int64 exception_count = 6;
+
+ // Total number of processed messages we have data recorded for. If we
+ // collected data for all the messages, message_count will be equal to
+ // recorded_message_count.
+ //
+ // If recorded_message_count is different than message_count, it means data
+ // collection has been sampled. All the fields below will be sampled in this
+ // case.
+ optional int64 recorded_message_count = 7;
+
+ // Total latency of all processed messages.
+ // Average can be computed using recorded_total_latency_micros /
+ // recorded_message_count.
+ optional int64 recorded_total_latency_micros = 8;
+
+ // Total CPU usage of all processed message.
+ // Average can be computed using recorded_total_cpu_micros /
+ // recorded_message_count. Total can be computed using
+ // recorded_total_cpu_micros / recorded_message_count * call_count.
+ optional int64 recorded_total_cpu_micros = 9;
+}
diff --git a/cmds/statsd/src/external/StatsPullerManager.cpp b/cmds/statsd/src/external/StatsPullerManager.cpp
index e6e8455..2871882 100644
--- a/cmds/statsd/src/external/StatsPullerManager.cpp
+++ b/cmds/statsd/src/external/StatsPullerManager.cpp
@@ -183,7 +183,13 @@
{{},
{},
1 * NS_PER_SEC,
- new StatsCompanionServicePuller(android::util::BINDER_CALLS_EXCEPTIONS)}}
+ new StatsCompanionServicePuller(android::util::BINDER_CALLS_EXCEPTIONS)}},
+ // looper_stats
+ {android::util::LOOPER_STATS,
+ {{5, 6, 7, 8, 9},
+ {2, 3, 4},
+ 1 * NS_PER_SEC,
+ new StatsCompanionServicePuller(android::util::LOOPER_STATS)}}
};
StatsPullerManager::StatsPullerManager() : mNextPullTimeNs(NO_ALARM_UPDATE) {
diff --git a/core/java/android/os/Looper.java b/core/java/android/os/Looper.java
index f17e0f0..5b23e92 100644
--- a/core/java/android/os/Looper.java
+++ b/core/java/android/os/Looper.java
@@ -18,7 +18,6 @@
import android.annotation.NonNull;
import android.annotation.Nullable;
-import android.os.LooperProto;
import android.util.Log;
import android.util.Printer;
import android.util.Slog;
@@ -70,6 +69,7 @@
// sThreadLocal.get() will return null unless you've called prepare().
static final ThreadLocal<Looper> sThreadLocal = new ThreadLocal<Looper>();
private static Looper sMainLooper; // guarded by Looper.class
+ private static Observer sObserver;
final MessageQueue mQueue;
final Thread mThread;
@@ -131,6 +131,15 @@
}
/**
+ * Set the transaction observer for all Loopers in this process.
+ *
+ * @hide
+ */
+ public static void setObserver(@Nullable Observer observer) {
+ sObserver = observer;
+ }
+
+ /**
* Run the message queue in this thread. Be sure to call
* {@link #quit()} to end the loop.
*/
@@ -169,6 +178,8 @@
logging.println(">>>>> Dispatching to " + msg.target + " " +
msg.callback + ": " + msg.what);
}
+ // Make sure the observer won't change while processing a transaction.
+ final Observer observer = sObserver;
final long traceTag = me.mTraceTag;
long slowDispatchThresholdMs = me.mSlowDispatchThresholdMs;
@@ -189,9 +200,21 @@
final long dispatchStart = needStartTime ? SystemClock.uptimeMillis() : 0;
final long dispatchEnd;
+ Object token = null;
+ if (observer != null) {
+ token = observer.messageDispatchStarting();
+ }
try {
msg.target.dispatchMessage(msg);
+ if (observer != null) {
+ observer.messageDispatched(token, msg);
+ }
dispatchEnd = needEndTime ? SystemClock.uptimeMillis() : 0;
+ } catch (Exception exception) {
+ if (observer != null) {
+ observer.dispatchingThrewException(token, msg, exception);
+ }
+ throw exception;
} finally {
if (traceTag != 0) {
Trace.traceEnd(traceTag);
@@ -395,4 +418,39 @@
return "Looper (" + mThread.getName() + ", tid " + mThread.getId()
+ ") {" + Integer.toHexString(System.identityHashCode(this)) + "}";
}
+
+ /** {@hide} */
+ public interface Observer {
+ /**
+ * Called right before a message is dispatched.
+ *
+ * <p> The token type is not specified to allow the implementation to specify its own type.
+ *
+ * @return a token used for collecting telemetry when dispatching a single message.
+ * The token token must be passed back exactly once to either
+ * {@link Observer#messageDispatched} or {@link Observer#dispatchingThrewException}
+ * and must not be reused again.
+ *
+ */
+ Object messageDispatchStarting();
+
+ /**
+ * Called when a message was processed by a Handler.
+ *
+ * @param token Token obtained by previously calling
+ * {@link Observer#messageDispatchStarting} on the same Observer instance.
+ * @param msg The message that was dispatched.
+ */
+ void messageDispatched(Object token, Message msg);
+
+ /**
+ * Called when an exception was thrown while processing a message.
+ *
+ * @param token Token obtained by previously calling
+ * {@link Observer#messageDispatchStarting} on the same Observer instance.
+ * @param msg The message that was dispatched and caused an exception.
+ * @param exception The exception that was thrown.
+ */
+ void dispatchingThrewException(Object token, Message msg, Exception exception);
+ }
}
diff --git a/core/java/com/android/internal/os/LooperStats.java b/core/java/com/android/internal/os/LooperStats.java
new file mode 100644
index 0000000..edf475f
--- /dev/null
+++ b/core/java/com/android/internal/os/LooperStats.java
@@ -0,0 +1,269 @@
+/*
+ * Copyright (C) 2018 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.internal.os;
+
+import android.annotation.NonNull;
+import android.os.Handler;
+import android.os.Looper;
+import android.os.Message;
+import android.os.SystemClock;
+import android.util.SparseArray;
+
+import com.android.internal.annotations.GuardedBy;
+
+import java.util.ArrayList;
+import java.util.List;
+import java.util.concurrent.ConcurrentLinkedQueue;
+import java.util.concurrent.ThreadLocalRandom;
+
+/**
+ * Collects aggregated telemetry data about Looper message dispatching.
+ *
+ * @hide Only for use within the system server.
+ */
+public class LooperStats implements Looper.Observer {
+ private static final int TOKEN_POOL_SIZE = 50;
+ private static final int DEFAULT_ENTRIES_SIZE_CAP = 2000;
+ private static final int DEFAULT_SAMPLING_INTERVAL = 100;
+
+ @GuardedBy("mLock")
+ private final SparseArray<Entry> mEntries = new SparseArray<>(256);
+ private final Object mLock = new Object();
+ private final Entry mOverflowEntry = new Entry("OVERFLOW");
+ private final Entry mHashCollisionEntry = new Entry("HASH_COLLISION");
+ private final ConcurrentLinkedQueue<DispatchSession> mSessionPool =
+ new ConcurrentLinkedQueue<>();
+ private final int mSamplingInterval;
+ private final int mEntriesSizeCap;
+
+ public LooperStats() {
+ this(DEFAULT_SAMPLING_INTERVAL, DEFAULT_ENTRIES_SIZE_CAP);
+ }
+
+ public LooperStats(int samplingInterval, int entriesSizeCap) {
+ this.mSamplingInterval = samplingInterval;
+ this.mEntriesSizeCap = entriesSizeCap;
+ }
+
+ @Override
+ public Object messageDispatchStarting() {
+ if (shouldCollectDetailedData()) {
+ DispatchSession session = mSessionPool.poll();
+ session = session == null ? new DispatchSession() : session;
+ session.startTimeMicro = getElapsedRealtimeMicro();
+ session.cpuStartMicro = getThreadTimeMicro();
+ return session;
+ }
+
+ return DispatchSession.NOT_SAMPLED;
+ }
+
+ @Override
+ public void messageDispatched(Object token, Message msg) {
+ DispatchSession session = (DispatchSession) token;
+ Entry entry = getOrCreateEntry(msg);
+ synchronized (entry) {
+ entry.messageCount++;
+ if (session != DispatchSession.NOT_SAMPLED) {
+ entry.recordedMessageCount++;
+ long latency = getElapsedRealtimeMicro() - session.startTimeMicro;
+ long cpuUsage = getThreadTimeMicro() - session.cpuStartMicro;
+ entry.totalLatencyMicro += latency;
+ entry.maxLatencyMicro = Math.max(entry.maxLatencyMicro, latency);
+ entry.cpuUsageMicro += cpuUsage;
+ entry.maxCpuUsageMicro = Math.max(entry.maxCpuUsageMicro, cpuUsage);
+ }
+ }
+
+ recycleSession(session);
+ }
+
+ @Override
+ public void dispatchingThrewException(Object token, Message msg, Exception exception) {
+ DispatchSession session = (DispatchSession) token;
+ Entry entry = getOrCreateEntry(msg);
+ synchronized (entry) {
+ entry.exceptionCount++;
+ }
+ recycleSession(session);
+ }
+
+ /** Returns an array of {@link ExportedEntry entries} with the aggregated statistics. */
+ public List<ExportedEntry> getEntries() {
+ final ArrayList<ExportedEntry> entries;
+ synchronized (mLock) {
+ final int size = mEntries.size();
+ entries = new ArrayList<>(size);
+ for (int i = 0; i < size; i++) {
+ Entry entry = mEntries.valueAt(i);
+ synchronized (entry) {
+ entries.add(new ExportedEntry(entry));
+ }
+ }
+ }
+ // Add the overflow and collision entries only if they have any data.
+ if (mOverflowEntry.messageCount > 0 || mOverflowEntry.exceptionCount > 0) {
+ synchronized (mOverflowEntry) {
+ entries.add(new ExportedEntry(mOverflowEntry));
+ }
+ }
+ if (mHashCollisionEntry.messageCount > 0 || mHashCollisionEntry.exceptionCount > 0) {
+ synchronized (mHashCollisionEntry) {
+ entries.add(new ExportedEntry(mHashCollisionEntry));
+ }
+ }
+ return entries;
+ }
+
+ /** Removes all collected data. */
+ public void reset() {
+ synchronized (mLock) {
+ mEntries.clear();
+ }
+ synchronized (mHashCollisionEntry) {
+ mHashCollisionEntry.reset();
+ }
+ synchronized (mOverflowEntry) {
+ mOverflowEntry.reset();
+ }
+ }
+
+ @NonNull
+ private Entry getOrCreateEntry(Message msg) {
+ final int id = Entry.idFor(msg);
+ Entry entry;
+ synchronized (mLock) {
+ entry = mEntries.get(id);
+ if (entry == null) {
+ if (mEntries.size() >= mEntriesSizeCap) {
+ // If over the size cap, track totals under a single entry.
+ return mOverflowEntry;
+ }
+ entry = new Entry(msg);
+ mEntries.put(id, entry);
+ }
+ }
+
+ if (entry.handler.getClass() != msg.getTarget().getClass()
+ || entry.handler.getLooper().getThread()
+ != msg.getTarget().getLooper().getThread()) {
+ // If a hash collision happened, track totals under a single entry.
+ return mHashCollisionEntry;
+ }
+ return entry;
+ }
+
+ private void recycleSession(DispatchSession session) {
+ if (session != DispatchSession.NOT_SAMPLED && mSessionPool.size() < TOKEN_POOL_SIZE) {
+ mSessionPool.add(session);
+ }
+ }
+
+ protected long getThreadTimeMicro() {
+ return SystemClock.currentThreadTimeMicro();
+ }
+
+ protected long getElapsedRealtimeMicro() {
+ return SystemClock.elapsedRealtimeNanos() / 1000;
+ }
+
+ protected boolean shouldCollectDetailedData() {
+ return ThreadLocalRandom.current().nextInt() % mSamplingInterval == 0;
+ }
+
+ private static class DispatchSession {
+ static final DispatchSession NOT_SAMPLED = new DispatchSession();
+ public long startTimeMicro;
+ public long cpuStartMicro;
+ }
+
+ private static class Entry {
+ public final Handler handler;
+ public final String messageName;
+ public long messageCount;
+ public long recordedMessageCount;
+ public long exceptionCount;
+ public long totalLatencyMicro;
+ public long maxLatencyMicro;
+ public long cpuUsageMicro;
+ public long maxCpuUsageMicro;
+
+ Entry(Message msg) {
+ handler = msg.getTarget();
+ messageName = handler.getMessageName(msg);
+ }
+
+ Entry(String specialEntryName) {
+ handler = null;
+ messageName = specialEntryName;
+ }
+
+ void reset() {
+ messageCount = 0;
+ recordedMessageCount = 0;
+ exceptionCount = 0;
+ totalLatencyMicro = 0;
+ maxLatencyMicro = 0;
+ cpuUsageMicro = 0;
+ maxCpuUsageMicro = 0;
+ }
+
+ static int idFor(Message msg) {
+ int result = 7;
+ result = 31 * result + msg.getTarget().getLooper().getThread().hashCode();
+ result = 31 * result + msg.getTarget().getClass().hashCode();
+ if (msg.getCallback() != null) {
+ return 31 * result + msg.getCallback().getClass().hashCode();
+ } else {
+ return 31 * result + msg.what;
+ }
+ }
+ }
+
+ /** Aggregated data of Looper message dispatching in the in the current process. */
+ public static class ExportedEntry {
+ public final String handlerClassName;
+ public final String threadName;
+ public final String messageName;
+ public final long messageCount;
+ public final long recordedMessageCount;
+ public final long exceptionCount;
+ public final long totalLatencyMicros;
+ public final long maxLatencyMicros;
+ public final long cpuUsageMicros;
+ public final long maxCpuUsageMicros;
+
+ ExportedEntry(Entry entry) {
+ if (entry.handler != null) {
+ this.handlerClassName = entry.handler.getClass().getName();
+ this.threadName = entry.handler.getLooper().getThread().getName();
+ } else {
+ // Overflow/collision entries do not have a handler set.
+ this.handlerClassName = "";
+ this.threadName = "";
+ }
+ this.messageName = entry.messageName;
+ this.messageCount = entry.messageCount;
+ this.recordedMessageCount = entry.recordedMessageCount;
+ this.exceptionCount = entry.exceptionCount;
+ this.totalLatencyMicros = entry.totalLatencyMicro;
+ this.maxLatencyMicros = entry.maxLatencyMicro;
+ this.cpuUsageMicros = entry.cpuUsageMicro;
+ this.maxCpuUsageMicros = entry.maxCpuUsageMicro;
+ }
+ }
+}
diff --git a/core/tests/coretests/src/com/android/internal/os/LooperStatsTest.java b/core/tests/coretests/src/com/android/internal/os/LooperStatsTest.java
new file mode 100644
index 0000000..297202b
--- /dev/null
+++ b/core/tests/coretests/src/com/android/internal/os/LooperStatsTest.java
@@ -0,0 +1,331 @@
+/*
+ * Copyright (C) 2018 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.internal.os;
+
+import static com.google.common.truth.Truth.assertThat;
+
+import android.os.Handler;
+import android.os.HandlerThread;
+import android.os.Looper;
+import android.platform.test.annotations.Presubmit;
+import android.support.test.filters.SmallTest;
+import android.support.test.runner.AndroidJUnit4;
+
+import org.junit.After;
+import org.junit.Assert;
+import org.junit.Before;
+import org.junit.Test;
+import org.junit.runner.RunWith;
+
+import java.util.Comparator;
+import java.util.List;
+
+@SmallTest
+@RunWith(AndroidJUnit4.class)
+@Presubmit
+public final class LooperStatsTest {
+ private HandlerThread mThreadFirst;
+ private HandlerThread mThreadSecond;
+ private Handler mHandlerFirst;
+ private Handler mHandlerSecond;
+ private Handler mHandlerAnonymous;
+
+ @Before
+ public void setUp() {
+ // The tests are all single-threaded. HandlerThreads are created to allow creating Handlers
+ // and to test Thread name collection.
+ mThreadFirst = new HandlerThread("TestThread1");
+ mThreadSecond = new HandlerThread("TestThread2");
+ mThreadFirst.start();
+ mThreadSecond.start();
+
+ mHandlerFirst = new TestHandlerFirst(mThreadFirst.getLooper());
+ mHandlerSecond = new TestHandlerSecond(mThreadSecond.getLooper());
+ mHandlerAnonymous = new Handler(mThreadFirst.getLooper()) {
+ /* To create an anonymous subclass. */
+ };
+ }
+
+ @After
+ public void tearDown() {
+ mThreadFirst.quit();
+ mThreadSecond.quit();
+ }
+
+ @Test
+ public void testSingleMessageDispatched() {
+ TestableLooperStats looperStats = new TestableLooperStats(1, 100);
+
+ Object token = looperStats.messageDispatchStarting();
+ looperStats.tickRealtime(100);
+ looperStats.tickThreadTime(10);
+ looperStats.messageDispatched(token, mHandlerFirst.obtainMessage(1000));
+
+ List<LooperStats.ExportedEntry> entries = looperStats.getEntries();
+ assertThat(entries).hasSize(1);
+ LooperStats.ExportedEntry entry = entries.get(0);
+ assertThat(entry.threadName).isEqualTo("TestThread1");
+ assertThat(entry.handlerClassName).isEqualTo(
+ "com.android.internal.os.LooperStatsTest$TestHandlerFirst");
+ assertThat(entry.messageName).isEqualTo("0x3e8" /* 1000 in hex */);
+ assertThat(entry.messageCount).isEqualTo(1);
+ assertThat(entry.recordedMessageCount).isEqualTo(1);
+ assertThat(entry.exceptionCount).isEqualTo(0);
+ assertThat(entry.totalLatencyMicros).isEqualTo(100);
+ assertThat(entry.maxLatencyMicros).isEqualTo(100);
+ assertThat(entry.cpuUsageMicros).isEqualTo(10);
+ assertThat(entry.maxCpuUsageMicros).isEqualTo(10);
+ }
+
+ @Test
+ public void testThrewException() {
+ TestableLooperStats looperStats = new TestableLooperStats(1, 100);
+
+ Object token = looperStats.messageDispatchStarting();
+ looperStats.tickRealtime(100);
+ looperStats.tickThreadTime(10);
+ looperStats.dispatchingThrewException(token, mHandlerFirst.obtainMessage(7),
+ new ArithmeticException());
+
+ List<LooperStats.ExportedEntry> entries = looperStats.getEntries();
+ assertThat(entries).hasSize(1);
+ LooperStats.ExportedEntry entry = entries.get(0);
+ assertThat(entry.threadName).isEqualTo("TestThread1");
+ assertThat(entry.handlerClassName).isEqualTo(
+ "com.android.internal.os.LooperStatsTest$TestHandlerFirst");
+ assertThat(entry.messageName).isEqualTo("0x7" /* 7 in hex */);
+ assertThat(entry.messageCount).isEqualTo(0);
+ assertThat(entry.recordedMessageCount).isEqualTo(0);
+ assertThat(entry.exceptionCount).isEqualTo(1);
+ assertThat(entry.totalLatencyMicros).isEqualTo(0);
+ assertThat(entry.maxLatencyMicros).isEqualTo(0);
+ assertThat(entry.cpuUsageMicros).isEqualTo(0);
+ assertThat(entry.maxCpuUsageMicros).isEqualTo(0);
+ }
+
+ @Test
+ public void testMultipleMessagesDispatched() {
+ TestableLooperStats looperStats = new TestableLooperStats(2, 100);
+
+ // Contributes to entry2.
+ Object token1 = looperStats.messageDispatchStarting();
+ looperStats.tickRealtime(100);
+ looperStats.tickThreadTime(10);
+ looperStats.messageDispatched(token1, mHandlerFirst.obtainMessage(1000));
+
+ // Contributes to entry2.
+ Object token2 = looperStats.messageDispatchStarting();
+ looperStats.tickRealtime(50);
+ looperStats.tickThreadTime(20);
+ looperStats.messageDispatched(token2, mHandlerFirst.obtainMessage(1000));
+
+ // Contributes to entry3.
+ Object token3 = looperStats.messageDispatchStarting();
+ looperStats.tickRealtime(10);
+ looperStats.tickThreadTime(10);
+ looperStats.messageDispatched(token3, mHandlerSecond.obtainMessage().setCallback(() -> {
+ }));
+
+ // Contributes to entry1.
+ Object token4 = looperStats.messageDispatchStarting();
+ looperStats.tickRealtime(100);
+ looperStats.tickThreadTime(100);
+ looperStats.messageDispatched(token4, mHandlerAnonymous.obtainMessage(1));
+
+ List<LooperStats.ExportedEntry> entries = looperStats.getEntries();
+ assertThat(entries).hasSize(3);
+ entries.sort(Comparator.comparing(e -> e.handlerClassName));
+
+ // Captures data for token4 call.
+ LooperStats.ExportedEntry entry1 = entries.get(0);
+ assertThat(entry1.threadName).isEqualTo("TestThread1");
+ assertThat(entry1.handlerClassName).isEqualTo("com.android.internal.os.LooperStatsTest$1");
+ assertThat(entry1.messageName).isEqualTo("0x1" /* 1 in hex */);
+ assertThat(entry1.messageCount).isEqualTo(1);
+ assertThat(entry1.recordedMessageCount).isEqualTo(0);
+ assertThat(entry1.exceptionCount).isEqualTo(0);
+ assertThat(entry1.totalLatencyMicros).isEqualTo(0);
+ assertThat(entry1.maxLatencyMicros).isEqualTo(0);
+ assertThat(entry1.cpuUsageMicros).isEqualTo(0);
+ assertThat(entry1.maxCpuUsageMicros).isEqualTo(0);
+
+ // Captures data for token1 and token2 calls.
+ LooperStats.ExportedEntry entry2 = entries.get(1);
+ assertThat(entry2.threadName).isEqualTo("TestThread1");
+ assertThat(entry2.handlerClassName).isEqualTo(
+ "com.android.internal.os.LooperStatsTest$TestHandlerFirst");
+ assertThat(entry2.messageName).isEqualTo("0x3e8" /* 1000 in hex */);
+ assertThat(entry2.messageCount).isEqualTo(2);
+ assertThat(entry2.recordedMessageCount).isEqualTo(1);
+ assertThat(entry2.exceptionCount).isEqualTo(0);
+ assertThat(entry2.totalLatencyMicros).isEqualTo(100);
+ assertThat(entry2.maxLatencyMicros).isEqualTo(100);
+ assertThat(entry2.cpuUsageMicros).isEqualTo(10);
+ assertThat(entry2.maxCpuUsageMicros).isEqualTo(10);
+
+ // Captures data for token3 call.
+ LooperStats.ExportedEntry entry3 = entries.get(2);
+ assertThat(entry3.threadName).isEqualTo("TestThread2");
+ assertThat(entry3.handlerClassName).isEqualTo(
+ "com.android.internal.os.LooperStatsTest$TestHandlerSecond");
+ assertThat(entry3.messageName).startsWith(
+ "com.android.internal.os.-$$Lambda$LooperStatsTest$");
+ assertThat(entry3.messageCount).isEqualTo(1);
+ assertThat(entry3.recordedMessageCount).isEqualTo(1);
+ assertThat(entry3.exceptionCount).isEqualTo(0);
+ assertThat(entry3.totalLatencyMicros).isEqualTo(10);
+ assertThat(entry3.maxLatencyMicros).isEqualTo(10);
+ assertThat(entry3.cpuUsageMicros).isEqualTo(10);
+ assertThat(entry3.maxCpuUsageMicros).isEqualTo(10);
+ }
+
+ @Test
+ public void testMessagesOverSizeCap() {
+ TestableLooperStats looperStats = new TestableLooperStats(2, 1 /* sizeCap */);
+
+ Object token1 = looperStats.messageDispatchStarting();
+ looperStats.tickRealtime(100);
+ looperStats.tickThreadTime(10);
+ looperStats.messageDispatched(token1, mHandlerFirst.obtainMessage(1000));
+
+ Object token2 = looperStats.messageDispatchStarting();
+ looperStats.tickRealtime(50);
+ looperStats.tickThreadTime(20);
+ looperStats.messageDispatched(token2, mHandlerFirst.obtainMessage(1001));
+
+ Object token3 = looperStats.messageDispatchStarting();
+ looperStats.tickRealtime(10);
+ looperStats.tickThreadTime(10);
+ looperStats.messageDispatched(token3, mHandlerFirst.obtainMessage(1002));
+
+ Object token4 = looperStats.messageDispatchStarting();
+ looperStats.tickRealtime(10);
+ looperStats.tickThreadTime(10);
+ looperStats.messageDispatched(token4, mHandlerSecond.obtainMessage(1003));
+
+ List<LooperStats.ExportedEntry> entries = looperStats.getEntries();
+ assertThat(entries).hasSize(2);
+ entries.sort(Comparator.comparing(e -> e.handlerClassName));
+
+ LooperStats.ExportedEntry entry1 = entries.get(0);
+ assertThat(entry1.threadName).isEqualTo("");
+ assertThat(entry1.handlerClassName).isEqualTo("");
+ assertThat(entry1.messageName).isEqualTo("OVERFLOW");
+ assertThat(entry1.messageCount).isEqualTo(3);
+ assertThat(entry1.recordedMessageCount).isEqualTo(1);
+ assertThat(entry1.exceptionCount).isEqualTo(0);
+ assertThat(entry1.totalLatencyMicros).isEqualTo(10);
+ assertThat(entry1.maxLatencyMicros).isEqualTo(10);
+ assertThat(entry1.cpuUsageMicros).isEqualTo(10);
+ assertThat(entry1.maxCpuUsageMicros).isEqualTo(10);
+
+ LooperStats.ExportedEntry entry2 = entries.get(1);
+ assertThat(entry2.threadName).isEqualTo("TestThread1");
+ assertThat(entry2.handlerClassName).isEqualTo(
+ "com.android.internal.os.LooperStatsTest$TestHandlerFirst");
+ }
+
+ @Test
+ public void testInvalidTokensCauseException() {
+ TestableLooperStats looperStats = new TestableLooperStats(1, 100);
+ assertThrows(ClassCastException.class,
+ () -> looperStats.dispatchingThrewException(new Object(),
+ mHandlerFirst.obtainMessage(),
+ new ArithmeticException()));
+ assertThrows(ClassCastException.class,
+ () -> looperStats.messageDispatched(new Object(), mHandlerFirst.obtainMessage()));
+ assertThrows(ClassCastException.class,
+ () -> looperStats.messageDispatched(123, mHandlerFirst.obtainMessage()));
+ assertThrows(ClassCastException.class,
+ () -> looperStats.messageDispatched(mHandlerFirst.obtainMessage(),
+ mHandlerFirst.obtainMessage()));
+
+ assertThat(looperStats.getEntries()).hasSize(0);
+ }
+
+ @Test
+ public void testTracksMultipleHandlerInstancesIfSameClass() {
+ TestableLooperStats looperStats = new TestableLooperStats(1, 100);
+ Handler handlerFirstAnother = new TestHandlerFirst(mHandlerFirst.getLooper());
+
+ Object token1 = looperStats.messageDispatchStarting();
+ looperStats.messageDispatched(token1, mHandlerFirst.obtainMessage(1000));
+
+ Object token2 = looperStats.messageDispatchStarting();
+ looperStats.messageDispatched(token2, handlerFirstAnother.obtainMessage(1000));
+
+ assertThat(looperStats.getEntries()).hasSize(1);
+ assertThat(looperStats.getEntries().get(0).messageCount).isEqualTo(2);
+ }
+
+ private static void assertThrows(Class<? extends Exception> exceptionClass, Runnable r) {
+ try {
+ r.run();
+ Assert.fail("Expected " + exceptionClass + " to be thrown.");
+ } catch (Exception exception) {
+ assertThat(exception).isInstanceOf(exceptionClass);
+ }
+ }
+
+ private static final class TestableLooperStats extends LooperStats {
+ private static final long INITIAL_MICROS = 10001000123L;
+ private int mCount;
+ private long mRealtimeMicros;
+ private long mThreadTimeMicros;
+ private int mSamplingInterval;
+
+ TestableLooperStats(int samplingInterval, int sizeCap) {
+ super(samplingInterval, sizeCap);
+ this.mSamplingInterval = samplingInterval;
+ }
+
+ void tickRealtime(long micros) {
+ mRealtimeMicros += micros;
+ }
+
+ void tickThreadTime(long micros) {
+ mThreadTimeMicros += micros;
+ }
+
+ @Override
+ protected long getElapsedRealtimeMicro() {
+ return INITIAL_MICROS + mRealtimeMicros;
+ }
+
+ @Override
+ protected long getThreadTimeMicro() {
+ return INITIAL_MICROS + mThreadTimeMicros;
+ }
+
+ @Override
+ protected boolean shouldCollectDetailedData() {
+ return mCount++ % mSamplingInterval == 0;
+ }
+ }
+
+ private static final class TestHandlerFirst extends Handler {
+ TestHandlerFirst(Looper looper) {
+ super(looper);
+ }
+ }
+
+ private static final class TestHandlerSecond extends Handler {
+ TestHandlerSecond(Looper looper) {
+ super(looper);
+ }
+ }
+}
diff --git a/services/core/java/com/android/server/LooperStatsService.java b/services/core/java/com/android/server/LooperStatsService.java
new file mode 100644
index 0000000..237e169
--- /dev/null
+++ b/services/core/java/com/android/server/LooperStatsService.java
@@ -0,0 +1,135 @@
+/*
+ * Copyright (C) 2018 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.server;
+
+import android.content.Context;
+import android.os.Binder;
+import android.os.Looper;
+import android.os.ResultReceiver;
+import android.os.ShellCallback;
+import android.os.ShellCommand;
+
+import com.android.internal.os.LooperStats;
+import com.android.internal.util.DumpUtils;
+
+import java.io.FileDescriptor;
+import java.io.PrintWriter;
+import java.util.Arrays;
+import java.util.Comparator;
+import java.util.List;
+
+/**
+ * @hide Only for use within the system server.
+ */
+public class LooperStatsService extends Binder {
+ private static final String TAG = "LooperStatsService";
+ private static final String LOOPER_STATS_SERVICE_NAME = "looper_stats";
+
+ private final Context mContext;
+ private final LooperStats mStats;
+ private boolean mEnabled = false;
+
+ private LooperStatsService(Context context, LooperStats stats) {
+ this.mContext = context;
+ this.mStats = stats;
+ }
+
+ @Override
+ public void onShellCommand(FileDescriptor in, FileDescriptor out, FileDescriptor err,
+ String[] args, ShellCallback callback, ResultReceiver resultReceiver) {
+ (new LooperShellCommand()).exec(this, in, out, err, args, callback, resultReceiver);
+ }
+
+ @Override
+ protected void dump(FileDescriptor fd, PrintWriter pw, String[] args) {
+ if (!DumpUtils.checkDumpPermission(mContext, TAG, pw)) return;
+ List<LooperStats.ExportedEntry> entries = mStats.getEntries();
+ entries.sort(Comparator
+ .comparing((LooperStats.ExportedEntry entry) -> entry.threadName)
+ .thenComparing(entry -> entry.handlerClassName)
+ .thenComparing(entry -> entry.messageName));
+ String header = String.join(",", Arrays.asList(
+ "thread_name",
+ "handler_class",
+ "message_name",
+ "message_count",
+ "recorded_message_count",
+ "total_latency_micros",
+ "max_latency_micros",
+ "total_cpu_micros",
+ "max_cpu_micros",
+ "exception_count"));
+ pw.println(header);
+ for (LooperStats.ExportedEntry entry : entries) {
+ pw.printf("%s,%s,%s,%s,%s,%s,%s,%s,%s,%s\n", entry.threadName, entry.handlerClassName,
+ entry.messageName, entry.messageCount, entry.recordedMessageCount,
+ entry.totalLatencyMicros, entry.maxLatencyMicros, entry.cpuUsageMicros,
+ entry.maxCpuUsageMicros, entry.exceptionCount);
+ }
+ }
+
+ private void setEnabled(boolean enabled) {
+ if (mEnabled != enabled) {
+ mEnabled = enabled;
+ mStats.reset();
+ Looper.setObserver(enabled ? mStats : null);
+ }
+ }
+
+ /**
+ * Manages the lifecycle of LooperStatsService within System Server.
+ */
+ public static class Lifecycle extends SystemService {
+ public Lifecycle(Context context) {
+ super(context);
+ }
+
+ @Override
+ public void onStart() {
+ LooperStats stats = new LooperStats();
+ publishLocalService(LooperStats.class, stats);
+ // TODO: publish LooperStatsService as a binder service when the SE Policy is changed.
+ }
+ }
+
+ private class LooperShellCommand extends ShellCommand {
+ @Override
+ public int onCommand(String cmd) {
+ if ("enable".equals(cmd)) {
+ setEnabled(true);
+ return 0;
+ } else if ("disable".equals(cmd)) {
+ setEnabled(false);
+ return 0;
+ } else if ("reset".equals(cmd)) {
+ mStats.reset();
+ return 0;
+ } else {
+ return handleDefaultCommands(cmd);
+ }
+ }
+
+ @Override
+ public void onHelp() {
+ final PrintWriter pw = getOutPrintWriter();
+ pw.println(LOOPER_STATS_SERVICE_NAME + " commands:");
+ pw.println(" enable: Enable collecting stats");
+ pw.println(" disable: Disable collecting stats");
+ pw.println(" reset: Reset stats");
+ }
+ }
+}
diff --git a/services/core/java/com/android/server/stats/StatsCompanionService.java b/services/core/java/com/android/server/stats/StatsCompanionService.java
index 556038f..c1d8892 100644
--- a/services/core/java/com/android/server/stats/StatsCompanionService.java
+++ b/services/core/java/com/android/server/stats/StatsCompanionService.java
@@ -19,7 +19,6 @@
import android.app.ActivityManagerInternal;
import android.app.AlarmManager;
import android.app.AlarmManager.OnAlarmListener;
-import android.app.PendingIntent;
import android.app.ProcessMemoryState;
import android.app.StatsManager;
import android.bluetooth.BluetoothActivityEnergyInfo;
@@ -65,12 +64,13 @@
import com.android.internal.net.NetworkStatsFactory;
import com.android.internal.os.BinderCallsStats.ExportedCallStat;
import com.android.internal.os.KernelCpuSpeedReader;
-import com.android.internal.os.KernelUidCpuTimeReader;
-import com.android.internal.os.KernelUidCpuClusterTimeReader;
import com.android.internal.os.KernelUidCpuActiveTimeReader;
+import com.android.internal.os.KernelUidCpuClusterTimeReader;
import com.android.internal.os.KernelUidCpuFreqTimeReader;
+import com.android.internal.os.KernelUidCpuTimeReader;
import com.android.internal.os.KernelWakelockReader;
import com.android.internal.os.KernelWakelockStats;
+import com.android.internal.os.LooperStats;
import com.android.internal.os.PowerProfile;
import com.android.internal.util.DumpUtils;
import com.android.server.BinderCallsStatsService;
@@ -79,7 +79,6 @@
import java.io.File;
import java.io.FileDescriptor;
-import java.io.IOException;
import java.io.PrintWriter;
import java.util.ArrayList;
import java.util.Arrays;
@@ -942,6 +941,29 @@
}
}
+ private void pullLooperStats(int tagId, List<StatsLogEventWrapper> pulledData) {
+ LooperStats looperStats = LocalServices.getService(LooperStats.class);
+ if (looperStats == null) {
+ return;
+ }
+
+ List<LooperStats.ExportedEntry> entries = looperStats.getEntries();
+ long elapsedNanos = SystemClock.elapsedRealtimeNanos();
+ for (LooperStats.ExportedEntry entry : entries) {
+ StatsLogEventWrapper e = new StatsLogEventWrapper(elapsedNanos, tagId, 9 /* fields */);
+ e.writeLong(0); // uid collection not implemented yet
+ e.writeString(entry.handlerClassName);
+ e.writeString(entry.threadName);
+ e.writeString(entry.messageName);
+ e.writeLong(entry.messageCount);
+ e.writeLong(entry.exceptionCount);
+ e.writeLong(entry.recordedMessageCount);
+ e.writeLong(entry.totalLatencyMicros);
+ e.writeLong(entry.cpuUsageMicros);
+ pulledData.add(e);
+ }
+ }
+
/**
* Pulls various data.
*/
@@ -1032,6 +1054,10 @@
pullBinderCallsStatsExceptions(tagId, ret);
break;
}
+ case StatsLog.LOOPER_STATS: {
+ pullLooperStats(tagId, ret);
+ break;
+ }
default:
Slog.w(TAG, "No such tagId data as " + tagId);
return null;
diff --git a/services/java/com/android/server/SystemServer.java b/services/java/com/android/server/SystemServer.java
index ecc13b2..6431344 100644
--- a/services/java/com/android/server/SystemServer.java
+++ b/services/java/com/android/server/SystemServer.java
@@ -747,6 +747,11 @@
traceBeginAndSlog("StartBinderCallsStatsService");
mSystemServiceManager.startService(BinderCallsStatsService.LifeCycle.class);
traceEnd();
+
+ // Tracks time spent in handling messages in handlers.
+ traceBeginAndSlog("StartLooperStatsService");
+ mSystemServiceManager.startService(LooperStatsService.Lifecycle.class);
+ traceEnd();
}
/**