Merge "Prevent logging ProtoLog messages queued before the session starts or... (3c7c4be9) · Commits · e / os / android_frameworks_base

core/java/android/tracing/perfetto/TracingContext.java

+9 −0

Original line number	Diff line number	Diff line
		@@ -73,6 +73,15 @@ public class TracingContext<DataSourceInstanceType extends DataSourceInstance, T
		return os;
		}

		/**
		* Gets the index of the data source instance this tracing context is associated with.
		*
		* @return The index of the data source instance.
		*/
		public int getInstanceIndex() {
		return mInstanceIndex;
		}

		/**
		* Can optionally be used to store custom per-sequence
		* session data, which is not reset when incremental state is cleared

core/java/com/android/internal/protolog/PerfettoProtoLogImpl.java

+50 −0

Original line number	Diff line number	Diff line
		@@ -118,6 +118,25 @@ public abstract class PerfettoProtoLogImpl extends IProtoLogClient.Stub implemen
		@NonNull
		private final ReadWriteLock mConfigUpdaterLock = new ReentrantReadWriteLock();

		/**
		* This set tracks active tracing instances from the perspective of the {@code
		* mBackgroundLoggingService}. It contains instance indexes, added when a tracing session starts
		* and removed when it stops. This ensures that queued messages are traced only to the expected
		* tracing session.
		*
		* <p>Specifically, it prevents:
		* <ul>
		* <li>Tracing messages logged before a session starts but still in the queue.</li>
		* <li>Tracing messages logged after a session stops but still in the queue.</li>
		* </ul>
		*
		* <p>The set is modified on the single-threaded {@code mBackgroundLoggingService}, ensuring
		* that the add/remove operations happen only after all messages in the queue at that point are
		* processed.
		*/
		@NonNull
		private final Set<Integer> mActiveTracingInstances = new ArraySet<>();

		@NonNull
		private final HandlerThread mBackgroundThread;

		@@ -557,6 +576,12 @@ public abstract class PerfettoProtoLogImpl extends IProtoLogClient.Stub implemen
		@NonNull Message message, @Nullable Object[] args, long tsNanos,
		@Nullable String stacktrace) {
		mDataSource.trace(ctx -> {
		// Ensures the message we are logging here was added to the execution queue after this
		// tracing instance was started and before it was stopped.
		if (!mActiveTracingInstances.contains(ctx.getInstanceIndex())) {
		return;
		}

		final ProtoLogDataSource.TlsState tlsState = ctx.getCustomTlsState();
		final LogLevel logFrom = tlsState.getLogFromLevel(logGroup.name());

		@@ -849,9 +874,22 @@ public abstract class PerfettoProtoLogImpl extends IProtoLogClient.Stub implemen
		writeLock.unlock();
		}

		// It is crucial to add the instanceIdx to mActiveTracingInstances via the
		// mBackgroundLoggingService. This ensures that this operation is enqueued
		// and executed after any log messages that were submitted before this
		// tracing instance started. The check for mActiveTracingInstances.contains(instanceIdx)
		// happens within the logToProto method (which also runs on mBackgroundLoggingService).
		// If we added instanceIdx directly, log messages already in the queue could be
		// incorrectly attributed to this new tracing session.
		queueTracingInstanceAddition(instanceIdx);

		Log.d(LOG_TAG, "Finished onTracingInstanceStart");
		}

		private void queueTracingInstanceAddition(int instanceIdx) {
		mBackgroundHandler.post(() -> mActiveTracingInstances.add(instanceIdx));
		}

		private void onTracingInstanceStartLocked(@NonNull ProtoLogDataSource.ProtoLogConfig config) {
		final LogLevel defaultLogFrom = config.getDefaultGroupConfig().logFrom;
		for (int i = defaultLogFrom.ordinal(); i < LogLevel.values().length; i++) {
		@@ -885,6 +923,14 @@ public abstract class PerfettoProtoLogImpl extends IProtoLogClient.Stub implemen
		int instanceIdx, @NonNull ProtoLogDataSource.ProtoLogConfig config) {
		Log.d(LOG_TAG, "Executing onTracingInstanceStop");

		// Similar to onTracingInstanceStart, it's crucial to remove the instanceIdx
		// via the mBackgroundLoggingService. This ensures that the removal happens
		// after all log messages enqueued before this tracing instance was stopped
		// have been processed and had a chance to be included in this trace.
		// If we removed instanceIdx directly, log messages still in the queue that
		// belong to this session might be dropped.
		queueTracingInstanceRemoval(instanceIdx);

		var writeLock = mConfigUpdaterLock.writeLock();
		writeLock.lock();
		try {
		@@ -896,6 +942,10 @@ public abstract class PerfettoProtoLogImpl extends IProtoLogClient.Stub implemen
		Log.d(LOG_TAG, "Finished onTracingInstanceStop");
		}

		private void queueTracingInstanceRemoval(int instanceIdx) {
		mBackgroundHandler.post(() -> mActiveTracingInstances.remove(instanceIdx));
		}

		private void onTracingInstanceStopLocked(@NonNull ProtoLogDataSource.ProtoLogConfig config) {
		this.mTracingInstances.decrementAndGet();

tests/Tracing/src/com/android/internal/protolog/ProcessedPerfettoProtoLogImplTest.java

+123 −0

Original line number	Diff line number	Diff line
		@@ -17,6 +17,8 @@
		package com.android.internal.protolog;

		import static android.tools.traces.Utils.busyWaitForDataSourceRegistration;
		import static android.tools.traces.Utils.busyWaitTracingSessionDoesntExist;
		import static android.tools.traces.Utils.busyWaitTracingSessionExists;

		import static org.junit.Assert.assertFalse;
		import static org.junit.Assert.assertThrows;
		@@ -956,6 +958,127 @@ public class ProcessedPerfettoProtoLogImplTest {
		Truth.assertThat(TestProtoLogGroup.TEST_GROUP.isLogToLogcat()).isFalse();
		}

		@Test
		public void messagesLoggedWhenProtoDisabledAreNotTraced() throws IOException {
		assertFalse("ProtoLog should be disabled before starting any trace",
		sProtoLog.isProtoEnabled());

		// Log a message when ProtoLog is disabled.
		sProtoLog.log(LogLevel.DEBUG, TestProtoLogGroup.TEST_GROUP, 1,
		LogDataType.BOOLEAN, new Object[]{false}); // "false" to distinguish

		PerfettoTraceMonitor traceMonitor = PerfettoTraceMonitor.newBuilder()
		.enableProtoLog(true, List.of(), TEST_PROTOLOG_DATASOURCE_NAME)
		.build();
		try {
		traceMonitor.start();
		assertTrue("ProtoLog should be enabled after starting the trace.",
		sProtoLog.isProtoEnabled());

		// Log a message when ProtoLog is enabled.
		sProtoLog.log(LogLevel.DEBUG, TestProtoLogGroup.TEST_GROUP, 1,
		LogDataType.BOOLEAN, new Object[]{true}); // "true" to distinguish
		} finally {
		traceMonitor.stop(mWriter);
		}

		final ResultReader reader = new ResultReader(mWriter.write(), mTraceConfig);
		final ProtoLogTrace protolog = reader.readProtoLogTrace();

		Truth.assertThat(protolog.messages).hasSize(1);
		Truth.assertThat(protolog.messages.getFirst().getMessage())
		.isEqualTo("My Test Debug Log Message true"); // Only the "true" message
		}


		@Test
		public void messagesInQueueBeforeNewSessionActivationAreNotTracedInNewSession()
		throws Exception {
		final int numOldMessages = 2;
		final int numNewMessages = 2;

		final CountDownLatch executorBlockedLatch = new CountDownLatch(1);
		final CountDownLatch releaseExecutorLatch = new CountDownLatch(1);

		// Submit task to block the executor.
		sProtoLog.mBackgroundHandler.post(() -> {
		executorBlockedLatch.countDown();
		try {
		if (!releaseExecutorLatch.await(60, TimeUnit.SECONDS)) {
		Truth.assertWithMessage("Timeout waiting for releaseExecutorLatch").fail();
		}
		} catch (InterruptedException e) {
		Thread.currentThread().interrupt();
		throw new RuntimeException("Task_Block interrupted: " + e.getMessage());
		}
		});
		assertTrue("Executor did not block in time",
		executorBlockedLatch.await(5, TimeUnit.SECONDS));

		PerfettoTraceMonitor traceMonitor0 = PerfettoTraceMonitor.newBuilder()
		.enableProtoLog(true, List.of(), TEST_PROTOLOG_DATASOURCE_NAME)
		.setUniqueSessionName("test_session0")
		.build();
		traceMonitor0.start();
		busyWaitTracingSessionExists("test_session0");

		// Log "old" messages. These are queued before we start the second tracing session.
		for (int i = 0; i < numOldMessages; i++) {
		sProtoLog.log(LogLevel.WARN, TestProtoLogGroup.TEST_GROUP, 1,
		LogDataType.BOOLEAN, new Object[]{false}); // Task_LogOld_i
		}

		// At this point, queue on backgroundService is roughly:
		// [Task_Block(paused), Task_Activate0, Task_LogOld1, ..., Task_Deactivate0]

		// Start the actual trace session to inspect (traceMonitor1). Queues Task_Activate1.
		PerfettoTraceMonitor traceMonitor1 = PerfettoTraceMonitor.newBuilder()
		.enableProtoLog(true, List.of(), TEST_PROTOLOG_DATASOURCE_NAME)
		.setUniqueSessionName("test_session1")
		.build();
		traceMonitor1.start();
		busyWaitTracingSessionExists("test_session1");

		// Log "new" messages. These are for traceMonitor1.
		for (int i = 0; i < numNewMessages; i++) {
		sProtoLog.log(LogLevel.DEBUG, TestProtoLogGroup.TEST_GROUP, 1,
		LogDataType.BOOLEAN, new Object[]{true});
		}

		// Unblock the executor.
		releaseExecutorLatch.countDown();

		var writer0 = new ResultWriter()
		.forScenario(new ScenarioBuilder().forClass("scenario0").build())
		.withOutputDir(mTracingDirectory).setRunComplete();
		traceMonitor0.stop(writer0);

		var writer1 = new ResultWriter()
		.forScenario(new ScenarioBuilder().forClass("scenario1").build())
		.withOutputDir(mTracingDirectory).setRunComplete();
		traceMonitor1.stop(writer1);
		busyWaitTracingSessionDoesntExist("test_session1");

		final ResultReader reader0 = new ResultReader(writer0.write(), mTraceConfig);
		final ProtoLogTrace protolog0 = reader0.readProtoLogTrace();

		Truth.assertThat(protolog0.messages).hasSize(numOldMessages + numNewMessages);

		final ResultReader reader1 = new ResultReader(writer1.write(), mTraceConfig);
		final ProtoLogTrace protolog1 = reader1.readProtoLogTrace();

		Truth.assertThat(protolog1.messages).hasSize(numNewMessages);
		for (int i = 0; i < numNewMessages; i++) {
		Truth.assertThat(protolog1.messages.get(i).getLevel()).isEqualTo(LogLevel.DEBUG);
		Truth.assertThat(protolog1.messages.get(i).getMessage())
		.isEqualTo("My Test Debug Log Message true");
		}
		// Ensure no messages (from the "old" batch) are present.
		for (var msg : protolog1.messages) {
		Truth.assertThat(msg.getLevel()).isNotEqualTo(LogLevel.VERBOSE);
		}
		}

		@Test
		public void processesAllPendingMessagesBeforeTraceStop()
		throws IOException, InterruptedException {