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

Commit 48d9aa96 authored by Nataniel Borges's avatar Nataniel Borges
Browse files

Log window trace data per frame in continuous mode 

When using non-continuous mode the WM Service logs each transaction
applied. This is incur in performance loss.

For continuous mode we need a more efficient mechanism to log the data,
thus we log only 1x per frame and only if a transaction has been
applied.

Test: Flash a device. Enable the continuous mode for tracing using
`adb shell cmd window tracing continuous true` and start the trace with
`adb shell cmd window tracing start`. Use the device. To stop the trace
and log the data to disk use `adb shell cmd window tracing stop`. Open
the trace in Winscope and check if all `entry` elements have the
following property: `where: onFrame`

Change-Id: I1034d9e1b7b8a105d4e16a1aeb4b7341fff5f157
parent 580a7429

services/core/java/com/android/server/wm/WindowManagerService.java

+4 −13
Original line number Diff line number Diff line
@@ -188,6 +188,7 @@ import android.util.SparseBooleanArray; 
import android.util.TimeUtils;

import android.util.TypedValue;

import android.util.proto.ProtoOutputStream;

import android.view.Choreographer;

import android.view.Display;

import android.view.DisplayCutout;

import android.view.DisplayInfo;
@@ -843,7 +844,7 @@ public class WindowManagerService extends IWindowManager.Stub 
            Trace.traceBegin(TRACE_TAG_WINDOW_MANAGER, "closeSurfaceTransaction");

            synchronized (mGlobalLock) {

                SurfaceControl.closeTransaction();

                traceStateLocked(where);

                mWindowTracing.logState(where);

            }

        } finally {

            Trace.traceEnd(TRACE_TAG_WINDOW_MANAGER);
@@ -967,7 +968,8 @@ public class WindowManagerService extends IWindowManager.Stub 
        mWindowPlacerLocked = new WindowSurfacePlacer(this);

        mTaskSnapshotController = new TaskSnapshotController(this);



        mWindowTracing = WindowTracing.createDefaultAndStartLooper(context);

        mWindowTracing = WindowTracing.createDefaultAndStartLooper(this,

                Choreographer.getInstance());



        LocalServices.addService(WindowManagerPolicy.class, mPolicy);
@@ -5765,17 +5767,6 @@ public class WindowManagerService extends IWindowManager.Stub 
        proto.write(LAST_ORIENTATION, defaultDisplayContent.getLastOrientation());

    }



    void traceStateLocked(String where) {

        Trace.traceBegin(TRACE_TAG_WINDOW_MANAGER, "traceStateLocked");

        try {

            mWindowTracing.traceStateLocked(where, this);

        } catch (Exception e) {

            Log.wtf(TAG, "Exception while tracing state", e);

        } finally {

            Trace.traceEnd(TRACE_TAG_WINDOW_MANAGER);

        }

    }



    private void dumpWindowsLocked(PrintWriter pw, boolean dumpAll,

            ArrayList<WindowState> windows) {

        pw.println("WINDOW MANAGER WINDOWS (dumpsys window windows)");

services/core/java/com/android/server/wm/WindowTracing.java

+79 −29
Original line number Diff line number Diff line
@@ -24,12 +24,14 @@ import static com.android.server.wm.WindowManagerTraceProto.WHERE; 
import static com.android.server.wm.WindowManagerTraceProto.WINDOW_MANAGER_SERVICE;



import android.annotation.Nullable;

import android.content.Context;

import android.os.ShellCommand;

import android.os.SystemClock;

import android.os.Trace;

import android.util.Log;

import android.util.proto.ProtoOutputStream;

import android.view.Choreographer;



import com.android.internal.annotations.VisibleForTesting;



import java.io.File;

import java.io.IOException;
@@ -48,6 +50,10 @@ class WindowTracing { 
    private static final int WINDOW_TRACE_BUFFER_SIZE = 512 * 1024;

    private static final String TAG = "WindowTracing";



    private final WindowManagerService mService;

    private final Choreographer mChoreographer;

    private final WindowManagerGlobalLock mGlobalLock;



    private final Object mLock = new Object();

    private final WindowTraceBuffer.Builder mBufferBuilder;
@@ -57,11 +63,24 @@ class WindowTracing { 
    private boolean mContinuousMode;

    private boolean mEnabled;

    private volatile boolean mEnabledLockFree;

    private boolean mScheduled;

    private Choreographer.FrameCallback mFrameCallback = (frameTimeNanos) ->

            log("onFrame" /* where */);



    private WindowTracing(File file, WindowManagerService service, Choreographer choreographer) {

        this(file, service, choreographer, service.mGlobalLock);

    }



    WindowTracing(File file) {

    @VisibleForTesting

    WindowTracing(File file, WindowManagerService service, Choreographer choreographer,

            WindowManagerGlobalLock globalLock) {

        mBufferBuilder = new WindowTraceBuffer.Builder()

                .setTraceFile(file)

                .setBufferCapacity(WINDOW_TRACE_BUFFER_SIZE);



        mChoreographer = choreographer;

        mService = service;

        mGlobalLock = globalLock;

    }



    void startTrace(@Nullable PrintWriter pw) throws IOException {
@@ -111,7 +130,8 @@ class WindowTracing { 
        }

    }



    private void setContinuousMode(boolean continuous, PrintWriter pw) {

    @VisibleForTesting

    void setContinuousMode(boolean continuous, PrintWriter pw) {

        logAndPrintln(pw, "Setting window tracing continuous mode to " + continuous);



        if (mEnabled) {
@@ -123,21 +143,14 @@ class WindowTracing { 
                WindowTraceLogLevel.TRIM;

    }



    private void appendTraceEntry(ProtoOutputStream proto) {

        if (!mEnabledLockFree) {

            return;

        }



        mTraceBuffer.add(proto);

    }



    boolean isEnabled() {

        return mEnabledLockFree;

    }



    static WindowTracing createDefaultAndStartLooper(Context context) {

    static WindowTracing createDefaultAndStartLooper(WindowManagerService service,

            Choreographer choreographer) {

        File file = new File("/data/misc/wmtrace/wm_trace.pb");

        return new WindowTracing(file);

        return new WindowTracing(file, service, choreographer);

    }



    int onShellCommand(ShellCommand shell) {
@@ -164,13 +177,45 @@ class WindowTracing { 
        }

    }



    void traceStateLocked(String where, WindowManagerService service) {

    /**

     * If tracing is enabled, log the current state or schedule the next frame to be logged,

     * according to {@link #mContinuousMode}.

     *

     * @param where Logging point descriptor

     */

    void logState(String where) {

        if (!isEnabled()) {

            return;

        }



        Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "writeToBufferLocked");

        if (mContinuousMode) {

            schedule();

        } else {

            log(where);

        }

    }



    /**

     * Schedule the log to trace the next frame

     */

    private void schedule() {

        if (mScheduled) {

            return;

        }



        mScheduled = true;

        mChoreographer.postFrameCallback(mFrameCallback);

    }



    /**

     * Write the current frame to the buffer

     *

     * @param where Logging point descriptor

     */

    private void log(String where) {

        Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "traceStateLocked");

        try {

            synchronized (mGlobalLock) {

                ProtoOutputStream os = new ProtoOutputStream();

                long tokenOuter = os.start(ENTRY);

                os.write(ELAPSED_REALTIME_NANOS, SystemClock.elapsedRealtimeNanos());
@@ -179,13 +224,18 @@ class WindowTracing { 
                Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "writeToProtoLocked");

                try {

                    long tokenInner = os.start(WINDOW_MANAGER_SERVICE);

                service.writeToProtoLocked(os, mWindowTraceLogLevel);

                    mService.writeToProtoLocked(os, mWindowTraceLogLevel);

                    os.end(tokenInner);

                } finally {

                    Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER);

                }

                os.end(tokenOuter);

            appendTraceEntry(os);

                mTraceBuffer.add(os);



                mScheduled = false;

            }

        } catch (Exception e) {

            Log.wtf(TAG, "Exception while tracing state", e);

        } finally {

            Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER);

        }

services/tests/wmtests/src/com/android/server/wm/WindowTracingTest.java

+9 −6
Original line number Diff line number Diff line
@@ -34,8 +34,8 @@ import android.content.Context; 
import android.platform.test.annotations.Presubmit;

import android.testing.DexmakerShareClassLoaderRule;

import android.util.proto.ProtoOutputStream;

import android.view.Choreographer;



import androidx.test.filters.FlakyTest;

import androidx.test.filters.SmallTest;



import com.android.internal.util.Preconditions;
@@ -74,6 +74,8 @@ public class WindowTracingTest { 


    @Mock

    private WindowManagerService mWmMock;

    @Mock

    private Choreographer mChoreographer;

    private WindowTracing mWindowTracing;

    private File mFile;
@@ -85,7 +87,9 @@ public class WindowTracingTest { 
        mFile = testContext.getFileStreamPath("tracing_test.dat");

        mFile.delete();



        mWindowTracing = new WindowTracing(mFile);

        mWindowTracing = new WindowTracing(mFile, mWmMock, mChoreographer,

                new WindowManagerGlobalLock());

        mWindowTracing.setContinuousMode(false /* continuous */, null /* pw */);

    }



    @After
@@ -113,15 +117,14 @@ public class WindowTracingTest { 


    @Test

    public void trace_discared_whenNotTracing() {

        mWindowTracing.traceStateLocked("where", mWmMock);

        mWindowTracing.logState("where");

        verifyZeroInteractions(mWmMock);

    }



    @Test

    public void trace_dumpsWindowManagerState_whenTracing() throws Exception {

        mWindowTracing.startTrace(mock(PrintWriter.class));

        mWindowTracing.traceStateLocked("where", mWmMock);



        mWindowTracing.logState("where");

        verify(mWmMock).writeToProtoLocked(any(), eq(WindowTraceLogLevel.TRIM));

    }
@@ -147,7 +150,7 @@ public class WindowTracingTest { 
                    WindowManagerTraceProto.WHERE, "TEST_WM_PROTO");

            return null;

        }).when(mWmMock).writeToProtoLocked(any(), any());

        mWindowTracing.traceStateLocked("TEST_WHERE", mWmMock);

        mWindowTracing.logState("TEST_WHERE");



        mWindowTracing.stopTrace(mock(PrintWriter.class));