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

Commit 8481e00a authored by Kean Mariotti's avatar Kean Mariotti
Browse files

WindowTracing: fix deadlock 

Do not write WM data to perfetto in the onStart callback.
Offload the writing to the main thread instead and use
DataSourceParams#postponeStop + stopDone() to synchronize
main and perfetto threads.

Bug: 323165543
Flag: EXEMPT bugfix
Test: atest WindowTracingPerfettoTest
Change-Id: I53b8b9b17f656084526ad75ad1c0c1e3dbae803d
parent 5dafa9d6

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

+50 −24
Original line number Diff line number Diff line
@@ -18,6 +18,7 @@ package com.android.server.wm; 


import static android.tracing.perfetto.DataSourceParams.PERFETTO_DS_BUFFER_EXHAUSTED_POLICY_STALL_AND_ABORT;



import android.annotation.IntDef;

import android.annotation.NonNull;

import android.internal.perfetto.protos.DataSourceConfigOuterClass.DataSourceConfig;

import android.internal.perfetto.protos.WindowmanagerConfig.WindowManagerConfig;
@@ -34,19 +35,35 @@ import android.util.proto.ProtoInputStream; 


import java.io.IOException;

import java.lang.ref.WeakReference;

import java.util.concurrent.atomic.AtomicBoolean;

import java.util.concurrent.atomic.AtomicInteger;



public final class WindowTracingDataSource extends DataSource<WindowTracingDataSource.Instance,

        WindowTracingDataSource.TlsState, Void> {



    @IntDef({

            com.android.server.wm.WindowTracingDataSource.Status.STARTING,

            com.android.server.wm.WindowTracingDataSource.Status.STARTED,

            com.android.server.wm.WindowTracingDataSource.Status.STOPPING,

            com.android.server.wm.WindowTracingDataSource.Status.STOPPED,

    })

    @interface Status {

        int STARTING = 0;

        int STARTED = 1;

        int STOPPING = 2;

        int STOPPED = 3;

    }



    public static class TlsState {

        public final Config mConfig;

        public final AtomicBoolean mIsStarting = new AtomicBoolean(true);

        public final AtomicInteger mStatus;



        private TlsState(Config config) {

        private TlsState(Config config, AtomicInteger status) {

            mConfig = config;

            mStatus = status;

        }

    }





    public static class Config {

        public final @WindowTracingLogLevel int mLogLevel;

        public final @WindowTracingLogFrequency int mLogFrequency;
@@ -59,12 +76,34 @@ public final class WindowTracingDataSource extends DataSource<WindowTracingDataS 
        }

    }



    public abstract static class Instance extends DataSourceInstance {

    public static class Instance extends DataSourceInstance {

        public final Config mConfig;

        public final AtomicInteger mStatus = new AtomicInteger(Status.STARTING);

        private final WeakReference<WindowTracingPerfetto> mWindowTracing;



        public Instance(DataSource dataSource, int instanceIndex, Config config) {

        public Instance(DataSource dataSource,

                int instanceIndex,

                Config config,

                WeakReference<WindowTracingPerfetto> windowTracing) {

            super(dataSource, instanceIndex);

            mConfig = config;

            mWindowTracing = windowTracing;

        }



        @Override

        protected void onStart(StartCallbackArguments args) {

            WindowTracingPerfetto windowTracing = mWindowTracing.get();

            if (windowTracing != null) {

                windowTracing.onStart(mConfig);

            }

        }



        @Override

        protected void onStop(StopCallbackArguments args) {

            WindowTracingPerfetto windowTracing = mWindowTracing.get();

            if (windowTracing != null) {

                windowTracing.onStop(this);

            }

        }

    }
@@ -85,6 +124,7 @@ public final class WindowTracingDataSource extends DataSource<WindowTracingDataS 
                new DataSourceParams.Builder()

                        .setBufferExhaustedPolicy(

                                PERFETTO_DS_BUFFER_EXHAUSTED_POLICY_STALL_AND_ABORT)

                        .setPostponeStop(true)

                        .build();

        register(params);

        Log.i(TAG, "Registered with perfetto service");
@@ -94,23 +134,9 @@ public final class WindowTracingDataSource extends DataSource<WindowTracingDataS 
    public Instance createInstance(ProtoInputStream configStream, int instanceIndex) {

        final Config config = parseDataSourceConfig(configStream);



        return new Instance(this, instanceIndex, config != null ? config : CONFIG_DEFAULT) {

            @Override

            protected void onStart(StartCallbackArguments args) {

                WindowTracingPerfetto windowTracing = mWindowTracing.get();

                if (windowTracing != null) {

                    windowTracing.onStart(mConfig);

                }

            }



            @Override

            protected void onStop(StopCallbackArguments args) {

                WindowTracingPerfetto windowTracing = mWindowTracing.get();

                if (windowTracing != null) {

                    windowTracing.onStop(mConfig);

                }

            }

        };

        return new Instance(this,

                instanceIndex,

                config != null ? config : CONFIG_DEFAULT, mWindowTracing);

    }



    @Override
@@ -119,9 +145,9 @@ public final class WindowTracingDataSource extends DataSource<WindowTracingDataS 
        try (Instance dsInstance = args.getDataSourceInstanceLocked()) {

            if (dsInstance == null) {

                // Datasource instance has been removed

                return new TlsState(CONFIG_DEFAULT);

                return new TlsState(CONFIG_DEFAULT,  new AtomicInteger(Status.STARTING));

            }

            return new TlsState(dsInstance.mConfig);

            return new TlsState(dsInstance.mConfig, dsInstance.mStatus);

        }

    }

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

+57 −24
Original line number Diff line number Diff line
@@ -19,6 +19,8 @@ package com.android.server.wm; 
import android.annotation.Nullable;

import android.internal.perfetto.protos.TracePacketOuterClass.TracePacket;

import android.internal.perfetto.protos.WinscopeExtensionsImplOuterClass.WinscopeExtensionsImpl;

import android.os.Handler;

import android.os.Looper;

import android.os.ShellCommand;

import android.os.SystemClock;

import android.os.Trace;
@@ -30,6 +32,7 @@ import android.view.Choreographer; 
import com.android.internal.annotations.VisibleForTesting;



import java.io.PrintWriter;

import java.util.ArrayList;

import java.util.concurrent.atomic.AtomicInteger;



class WindowTracingPerfetto extends WindowTracing {
@@ -39,6 +42,7 @@ class WindowTracingPerfetto extends WindowTracing { 
    private final AtomicInteger mCountSessionsOnFrame = new AtomicInteger();

    private final AtomicInteger mCountSessionsOnTransaction = new AtomicInteger();

    private final WindowTracingDataSource mDataSource;

    private final Handler mMainHandler = new Handler(Looper.getMainLooper());



    WindowTracingPerfetto(WindowManagerService service, Choreographer choreographer) {

        this(service, choreographer, service.mGlobalLock, PRODUCTION_DATA_SOURCE_NAME);
@@ -112,27 +116,40 @@ class WindowTracingPerfetto extends WindowTracing { 
            boolean isStartLogEvent = where == WHERE_START_TRACING;

            boolean isOnFrameLogEvent = where == WHERE_ON_FRAME;



            ArrayList<Runnable> pendingStopDones = new ArrayList<>();



            mDataSource.trace((context) -> {

                WindowTracingDataSource.Config dataSourceConfig =

                        context.getCustomTlsState().mConfig;

                WindowTracingDataSource.TlsState tlsState = context.getCustomTlsState();



                if (isStartLogEvent) {

                    boolean isDataSourceStarting = context.getCustomTlsState()

                            .mIsStarting.compareAndSet(true, false);

                    if (!isDataSourceStarting) {

                    if (tlsState.mConfig.mLogFrequency == WindowTracingLogFrequency.SINGLE_DUMP) {

                        // A single dump gets triggered when the data source is stopping

                        // (onStop() callback)

                        boolean isStopping = tlsState.mStatus.compareAndSet(

                                WindowTracingDataSource.Status.STOPPING,

                                WindowTracingDataSource.Status.STOPPED);

                        if (!isStopping) {

                            return;

                        }

                        pendingStopDones.add(context::stopDone);

                    } else {

                        boolean isStarting = tlsState.mStatus.compareAndSet(

                                WindowTracingDataSource.Status.STARTING,

                                WindowTracingDataSource.Status.STARTED);

                        if (!isStarting) {

                            return;

                        }

                    }

                } else if (isOnFrameLogEvent) {

                    boolean isDataSourceLoggingOnFrame =

                            dataSourceConfig.mLogFrequency == WindowTracingLogFrequency.FRAME;

                    if (!isDataSourceLoggingOnFrame) {

                    if (tlsState.mConfig.mLogFrequency != WindowTracingLogFrequency.FRAME) {

                        return;

                    }

                } else if (dataSourceConfig.mLogFrequency

                        == WindowTracingLogFrequency.SINGLE_DUMP) {

                    // If it is a dump, write only the start log event and skip the following ones

                    boolean isStarted =

                            tlsState.mStatus.get() == WindowTracingDataSource.Status.STARTED;

                    if (!isStarted) {

                        return;

                    }

                }



                ProtoOutputStream os = context.newTracePacket();

                long timestamp = SystemClock.elapsedRealtimeNanos();
@@ -141,10 +158,18 @@ class WindowTracingPerfetto extends WindowTracing { 
                        os.start(TracePacket.WINSCOPE_EXTENSIONS);

                final long tokenExtensionsField =

                        os.start(WinscopeExtensionsImpl.WINDOWMANAGER);

                dumpToProto(os, dataSourceConfig.mLogLevel, where, timestamp);

                dumpToProto(os, tlsState.mConfig.mLogLevel, where, timestamp);

                os.end(tokenExtensionsField);

                os.end(tokenWinscopeExtensions);

            });



            // Execute the stopDone() calls only after DataSource#trace() has returned. Within

            // DataSource#trace() the data is not written to Perfetto yet, hence stopDone()

            // can't be called there.

            for (int i = 0; i < pendingStopDones.size(); ++i) {

                pendingStopDones.get(i).run();

                Log.i(TAG, "Stopped session (frequency=SINGLE_DUMP) (postponed stop)");

            }

        } catch (Exception e) {

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

        } finally {
@@ -170,22 +195,30 @@ class WindowTracingPerfetto extends WindowTracing { 
            Log.i(TAG, "Started session (frequency=TRANSACTION, log level="

                    + config.mLogFrequency + ")");

            mCountSessionsOnTransaction.incrementAndGet();

        } else if (config.mLogFrequency == WindowTracingLogFrequency.SINGLE_DUMP) {

            Log.i(TAG, "Started session (frequency=SINGLE_DUMP, log level="

                    + config.mLogFrequency + ")");

            return; // onStop() will trigger the start log event of SINGLE_DUMP tracing sessions

        }



        Log.i(TAG, getStatus());



        log(WHERE_START_TRACING);

        mMainHandler.post(() -> log(WHERE_START_TRACING));

    }



    void onStop(WindowTracingDataSource.Config config) {

        if (config.mLogFrequency == WindowTracingLogFrequency.FRAME) {

            Log.i(TAG, "Stopped session (frequency=FRAME)");

    void onStop(WindowTracingDataSource.Instance instance) {

        if (instance.mConfig.mLogFrequency == WindowTracingLogFrequency.FRAME) {

            instance.stopDone();

            instance.mStatus.set(WindowTracingDataSource.Status.STOPPED);

            mCountSessionsOnFrame.decrementAndGet();

            Log.i(TAG, "Stopped session (frequency=TRANSACTION)");

        } else if (config.mLogFrequency == WindowTracingLogFrequency.TRANSACTION) {

            Log.i(TAG, "Stopped session (frequency=FRAME)");

        } else if (instance.mConfig.mLogFrequency == WindowTracingLogFrequency.TRANSACTION) {

            instance.stopDone();

            instance.mStatus.set(WindowTracingDataSource.Status.STOPPED);

            mCountSessionsOnTransaction.decrementAndGet();

            Log.i(TAG, "Stopped session (frequency=TRANSACTION)");

        } else if (instance.mConfig.mLogFrequency == WindowTracingLogFrequency.SINGLE_DUMP) {

            Log.i(TAG, "Triggering log event on stop (frequency=SINGLE_DUMP)");

            instance.mStatus.set(WindowTracingDataSource.Status.STOPPING);

            mMainHandler.post(() -> log(WHERE_START_TRACING));

        }



        Log.i(TAG, getStatus());

    }

}