Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 22f182d1 authored by TreeHugger Robot's avatar TreeHugger Robot Committed by Android (Google) Code Review
Browse files

Merge "LooperStats - track time to message dispatch"

parents 9f364bd2 44272725

core/java/android/os/Message.java

+9 −1
Original line number Diff line number Diff line
@@ -19,6 +19,8 @@ package android.os; 
import android.util.TimeUtils;

import android.util.proto.ProtoOutputStream;



import com.android.internal.annotations.VisibleForTesting;



/**

 *

 * Defines a message containing a description and arbitrary data object that can be
@@ -111,7 +113,13 @@ public final class Message implements Parcelable { 


    /*package*/ int flags;



    /*package*/ long when;

    /**

     * The targeted delivery time of this message. The time-base is

     * {@link SystemClock#uptimeMillis}.

     * @hide Only for use within the tests.

     */

    @VisibleForTesting(visibility = VisibleForTesting.Visibility.PACKAGE)

    public long when;



    /*package*/ Bundle data;

core/java/com/android/internal/os/LooperStats.java

+26 −2
Original line number Diff line number Diff line
@@ -66,6 +66,7 @@ public class LooperStats implements Looper.Observer { 
            session = session == null ? new DispatchSession() : session;

            session.startTimeMicro = getElapsedRealtimeMicro();

            session.cpuStartMicro = getThreadTimeMicro();

            session.systemUptimeMillis = getSystemUptimeMillis();

            return session;

        }
@@ -85,12 +86,18 @@ public class LooperStats implements Looper.Observer { 
                entry.messageCount++;

                if (session != DispatchSession.NOT_SAMPLED) {

                    entry.recordedMessageCount++;

                    long latency = getElapsedRealtimeMicro() - session.startTimeMicro;

                    long cpuUsage = getThreadTimeMicro() - session.cpuStartMicro;

                    final long latency = getElapsedRealtimeMicro() - session.startTimeMicro;

                    final 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);

                    if (msg.getWhen() > 0) {

                        final long delay = Math.max(0L, session.systemUptimeMillis - msg.getWhen());

                        entry.delayMillis += delay;

                        entry.maxDelayMillis = Math.max(entry.maxDelayMillis, delay);

                        entry.recordedDelayMessageCount++;

                    }

                }

            }

        }
@@ -206,6 +213,10 @@ public class LooperStats implements Looper.Observer { 
        return SystemClock.elapsedRealtimeNanos() / 1000;

    }



    protected long getSystemUptimeMillis() {

        return SystemClock.uptimeMillis();

    }



    protected boolean shouldCollectDetailedData() {

        return ThreadLocalRandom.current().nextInt() % mSamplingInterval == 0;

    }
@@ -214,6 +225,7 @@ public class LooperStats implements Looper.Observer { 
        static final DispatchSession NOT_SAMPLED = new DispatchSession();

        public long startTimeMicro;

        public long cpuStartMicro;

        public long systemUptimeMillis;

    }



    private static class Entry {
@@ -228,6 +240,9 @@ public class LooperStats implements Looper.Observer { 
        public long maxLatencyMicro;

        public long cpuUsageMicro;

        public long maxCpuUsageMicro;

        public long recordedDelayMessageCount;

        public long delayMillis;

        public long maxDelayMillis;



        Entry(Message msg, boolean isInteractive) {

            this.workSourceUid = msg.workSourceUid;
@@ -251,6 +266,9 @@ public class LooperStats implements Looper.Observer { 
            maxLatencyMicro = 0;

            cpuUsageMicro = 0;

            maxCpuUsageMicro = 0;

            delayMillis = 0;

            maxDelayMillis = 0;

            recordedDelayMessageCount = 0;

        }



        static int idFor(Message msg, boolean isInteractive) {
@@ -281,6 +299,9 @@ public class LooperStats implements Looper.Observer { 
        public final long maxLatencyMicros;

        public final long cpuUsageMicros;

        public final long maxCpuUsageMicros;

        public final long maxDelayMillis;

        public final long delayMillis;

        public final long recordedDelayMessageCount;



        ExportedEntry(Entry entry) {

            this.workSourceUid = entry.workSourceUid;
@@ -301,6 +322,9 @@ public class LooperStats implements Looper.Observer { 
            this.maxLatencyMicros = entry.maxLatencyMicro;

            this.cpuUsageMicros = entry.cpuUsageMicro;

            this.maxCpuUsageMicros = entry.maxCpuUsageMicro;

            this.delayMillis = entry.delayMillis;

            this.maxDelayMillis = entry.maxDelayMillis;

            this.recordedDelayMessageCount = entry.recordedDelayMessageCount;

        }

    }

}

core/tests/coretests/src/com/android/internal/os/LooperStatsTest.java

+68 −0
Original line number Diff line number Diff line
@@ -77,9 +77,13 @@ public final class LooperStatsTest { 


        Message message = mHandlerFirst.obtainMessage(1000);

        message.workSourceUid = 1000;

        message.when = looperStats.getSystemUptimeMillis();



        looperStats.tickUptime(30);

        Object token = looperStats.messageDispatchStarting();

        looperStats.tickRealtime(100);

        looperStats.tickThreadTime(10);

        looperStats.tickUptime(200);

        looperStats.messageDispatched(token, message);



        List<LooperStats.ExportedEntry> entries = looperStats.getEntries();
@@ -98,6 +102,10 @@ public final class LooperStatsTest { 
        assertThat(entry.maxLatencyMicros).isEqualTo(100);

        assertThat(entry.cpuUsageMicros).isEqualTo(10);

        assertThat(entry.maxCpuUsageMicros).isEqualTo(10);

        assertThat(entry.recordedDelayMessageCount).isEqualTo(1);

        assertThat(entry.delayMillis).isEqualTo(30);

        assertThat(entry.maxDelayMillis).isEqualTo(30);



    }



    @Test
@@ -214,6 +222,56 @@ public final class LooperStatsTest { 
        assertThat(entry3.maxCpuUsageMicros).isEqualTo(10);

    }



    @Test

    public void testDispatchDelayIsRecorded() {

        TestableLooperStats looperStats = new TestableLooperStats(1, 100);



        // Dispatched right on time.

        Message message1 = mHandlerFirst.obtainMessage(1000);

        message1.when = looperStats.getSystemUptimeMillis();

        Object token1 = looperStats.messageDispatchStarting();

        looperStats.tickUptime(10);

        looperStats.messageDispatched(token1, message1);



        // Dispatched 100ms late.

        Message message2 = mHandlerFirst.obtainMessage(1000);

        message2.when = looperStats.getSystemUptimeMillis() - 100;

        Object token2 = looperStats.messageDispatchStarting();

        looperStats.tickUptime(10);

        looperStats.messageDispatched(token2, message2);



        // No target dispatching time.

        Message message3 = mHandlerFirst.obtainMessage(1000);

        message3.when = 0;

        Object token3 = looperStats.messageDispatchStarting();

        looperStats.tickUptime(10);

        looperStats.messageDispatched(token3, message3);



        // Dispatched too soon (should never happen).

        Message message4 = mHandlerFirst.obtainMessage(1000);

        message4.when = looperStats.getSystemUptimeMillis() + 200;

        Object token4 = looperStats.messageDispatchStarting();

        looperStats.tickUptime(10);

        looperStats.messageDispatched(token4, message4);



        // Dispatched 300ms late.

        Message message5 = mHandlerFirst.obtainMessage(1000);

        message5.when = looperStats.getSystemUptimeMillis() - 300;

        Object token5 = looperStats.messageDispatchStarting();

        looperStats.tickUptime(10);

        looperStats.messageDispatched(token5, message5);



        List<LooperStats.ExportedEntry> entries = looperStats.getEntries();

        assertThat(entries).hasSize(1);



        LooperStats.ExportedEntry entry = entries.get(0);

        assertThat(entry.messageCount).isEqualTo(5);

        assertThat(entry.recordedMessageCount).isEqualTo(5);

        assertThat(entry.recordedDelayMessageCount).isEqualTo(4);

        assertThat(entry.delayMillis).isEqualTo(400);

        assertThat(entry.maxDelayMillis).isEqualTo(300);

    }



    @Test

    public void testDataNotCollectedBeforeDeviceStateSet() {

        TestableLooperStats looperStats = new TestableLooperStats(1, 100);
@@ -385,6 +443,7 @@ public final class LooperStatsTest { 
        private int mCount;

        private long mRealtimeMicros;

        private long mThreadTimeMicros;

        private long mUptimeMillis;

        private int mSamplingInterval;



        TestableLooperStats(int samplingInterval, int sizeCap) {
@@ -401,6 +460,10 @@ public final class LooperStatsTest { 
            mThreadTimeMicros += micros;

        }



        void tickUptime(long millis) {

            mUptimeMillis += millis;

        }



        @Override

        protected long getElapsedRealtimeMicro() {

            return INITIAL_MICROS + mRealtimeMicros;
@@ -411,6 +474,11 @@ public final class LooperStatsTest { 
            return INITIAL_MICROS + mThreadTimeMicros;

        }



        @Override

        protected long getSystemUptimeMillis() {

            return INITIAL_MICROS / 1000 + mUptimeMillis;

        }



        @Override

        protected boolean shouldCollectDetailedData() {

            return mCount++ % mSamplingInterval == 0;

services/core/java/com/android/server/LooperStatsService.java

+19 −5
Original line number Diff line number Diff line
@@ -109,14 +109,28 @@ public class LooperStatsService extends Binder { 
                "max_latency_micros",

                "total_cpu_micros",

                "max_cpu_micros",

                "recorded_delay_message_count",

                "total_delay_millis",

                "max_delay_millis",

                "exception_count"));

        pw.println(header);

        for (LooperStats.ExportedEntry entry : entries) {

            pw.printf("%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s\n", entry.workSourceUid,

                    entry.threadName, entry.handlerClassName, entry.messageName,

                    entry.isInteractive, entry.messageCount, entry.recordedMessageCount,

                    entry.totalLatencyMicros, entry.maxLatencyMicros, entry.cpuUsageMicros,

                    entry.maxCpuUsageMicros, entry.exceptionCount);

            pw.printf("%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s\n",

                    entry.workSourceUid,

                    entry.threadName,

                    entry.handlerClassName,

                    entry.messageName,

                    entry.isInteractive,

                    entry.messageCount,

                    entry.recordedMessageCount,

                    entry.totalLatencyMicros,

                    entry.maxLatencyMicros,

                    entry.cpuUsageMicros,

                    entry.maxCpuUsageMicros,

                    entry.recordedDelayMessageCount,

                    entry.delayMillis,

                    entry.maxDelayMillis,

                    entry.exceptionCount);

        }

    }