diff --git a/cmds/statsd/src/atoms.proto b/cmds/statsd/src/atoms.proto index 3c9f7eee10b6e..2ecfbe733bcac 100644 --- a/cmds/statsd/src/atoms.proto +++ b/cmds/statsd/src/atoms.proto @@ -133,7 +133,7 @@ message Atom { } // 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; @@ -159,6 +159,7 @@ message Atom { 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 @@ -2203,3 +2204,50 @@ message BinderCallsExceptions { // 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 e6e84550cf5f8..28718823bb321 100644 --- a/cmds/statsd/src/external/StatsPullerManager.cpp +++ b/cmds/statsd/src/external/StatsPullerManager.cpp @@ -183,7 +183,13 @@ const std::map StatsPullerManager::kAllPullAtomInfo = { {{}, {}, 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 684a8ee43c870..ded3a1983fb26 100644 --- a/core/java/android/os/Looper.java +++ b/core/java/android/os/Looper.java @@ -18,7 +18,6 @@ package android.os; 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 @@ public final class Looper { // sThreadLocal.get() will return null unless you've called prepare(). static final ThreadLocal sThreadLocal = new ThreadLocal(); private static Looper sMainLooper; // guarded by Looper.class + private static Observer sObserver; final MessageQueue mQueue; final Thread mThread; @@ -130,6 +130,15 @@ public final class Looper { } } + /** + * 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 @@ public final class Looper { 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 @@ public final class Looper { 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); @@ -397,4 +420,39 @@ public final class Looper { return "Looper (" + mThread.getName() + ", tid " + mThread.getId() + ") {" + Integer.toHexString(System.identityHashCode(this)) + "}"; } + + /** {@hide} */ + public interface Observer { + /** + * Called right before a message is dispatched. + * + *

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 0000000000000..edf475f1dba37 --- /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 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 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 getEntries() { + final ArrayList 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 0000000000000..297202bf4d715 --- /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 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 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 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 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 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 0000000000000..237e169a989f6 --- /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 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 41c0be63a5bb3..b922e40a5d38d 100644 --- a/services/core/java/com/android/server/stats/StatsCompanionService.java +++ b/services/core/java/com/android/server/stats/StatsCompanionService.java @@ -70,6 +70,7 @@ 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; @@ -938,6 +939,29 @@ public class StatsCompanionService extends IStatsCompanionService.Stub { } } + private void pullLooperStats(int tagId, List pulledData) { + LooperStats looperStats = LocalServices.getService(LooperStats.class); + if (looperStats == null) { + return; + } + + List 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. */ @@ -1028,6 +1052,10 @@ public class StatsCompanionService extends IStatsCompanionService.Stub { 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 ecc13b2955397..6431344f218b5 100644 --- a/services/java/com/android/server/SystemServer.java +++ b/services/java/com/android/server/SystemServer.java @@ -747,6 +747,11 @@ public final class SystemServer { traceBeginAndSlog("StartBinderCallsStatsService"); mSystemServiceManager.startService(BinderCallsStatsService.LifeCycle.class); traceEnd(); + + // Tracks time spent in handling messages in handlers. + traceBeginAndSlog("StartLooperStatsService"); + mSystemServiceManager.startService(LooperStatsService.Lifecycle.class); + traceEnd(); } /**