Add more logging for Wakelocks. (9204cc87) · Commits · e / os / android_frameworks_base

services/core/java/com/android/server/power/Notifier.java

+19 −0

Original line number	Original line	Diff line number	Diff line
	@@ -61,6 +61,8 @@ import com.android.server.inputmethod.InputMethodManagerInternal;
	import com.android.server.policy.WindowManagerPolicy;		import com.android.server.policy.WindowManagerPolicy;
	import com.android.server.statusbar.StatusBarManagerInternal;		import com.android.server.statusbar.StatusBarManagerInternal;

			import java.io.PrintWriter;

	/**		/**
	* Sends broadcasts about important power state changes.		* Sends broadcasts about important power state changes.
	* <p>		* <p>
	@@ -122,6 +124,7 @@ public class Notifier {
	@Nullable private final StatusBarManagerInternal mStatusBarManagerInternal;		@Nullable private final StatusBarManagerInternal mStatusBarManagerInternal;
	private final TrustManager mTrustManager;		private final TrustManager mTrustManager;
	private final Vibrator mVibrator;		private final Vibrator mVibrator;
			private final WakeLockLog mWakeLockLog;

	private final NotifierHandler mHandler;		private final NotifierHandler mHandler;
	private final Intent mScreenOnIntent;		private final Intent mScreenOnIntent;
	@@ -189,6 +192,8 @@ public class Notifier {
	mShowWirelessChargingAnimationConfig = context.getResources().getBoolean(		mShowWirelessChargingAnimationConfig = context.getResources().getBoolean(
	com.android.internal.R.bool.config_showBuiltinWirelessChargingAnim);		com.android.internal.R.bool.config_showBuiltinWirelessChargingAnim);

			mWakeLockLog = new WakeLockLog();

	// Initialize interactive state for battery stats.		// Initialize interactive state for battery stats.
	try {		try {
	mBatteryStats.noteInteractive(true);		mBatteryStats.noteInteractive(true);
	@@ -227,6 +232,8 @@ public class Notifier {
	// Ignore		// Ignore
	}		}
	}		}

			mWakeLockLog.onWakeLockAcquired(tag, ownerUid, flags);
	}		}

	public void onLongPartialWakeLockStart(String tag, int ownerUid, WorkSource workSource,		public void onLongPartialWakeLockStart(String tag, int ownerUid, WorkSource workSource,
	@@ -337,6 +344,7 @@ public class Notifier {
	// Ignore		// Ignore
	}		}
	}		}
			mWakeLockLog.onWakeLockReleased(tag, ownerUid);
	}		}

	private int getBatteryStatsWakeLockMonitorType(int flags) {		private int getBatteryStatsWakeLockMonitorType(int flags) {
	@@ -646,6 +654,17 @@ public class Notifier {
	mHandler.sendMessage(msg);		mHandler.sendMessage(msg);
	}		}

			/**
			* Dumps data for bugreports.
			*
			* @param pw The stream to print to.
			*/
			public void dump(PrintWriter pw) {
			if (mWakeLockLog != null) {
			mWakeLockLog.dump(pw);
			}
			}

	private void updatePendingBroadcastLocked() {		private void updatePendingBroadcastLocked() {
	if (!mBroadcastInProgress		if (!mBroadcastInProgress
	&& mPendingInteractiveState != INTERACTIVE_STATE_UNKNOWN		&& mPendingInteractiveState != INTERACTIVE_STATE_UNKNOWN

services/core/java/com/android/server/power/PowerManagerService.java

+5 −1

Original line number	Original line	Diff line number	Diff line
	@@ -3770,6 +3770,10 @@ public final class PowerManagerService extends SystemService
	if (wcd != null) {		if (wcd != null) {
	wcd.dump(pw);		wcd.dump(pw);
	}		}

			if (mNotifier != null) {
			mNotifier.dump(pw);
			}
	}		}

	private void dumpProto(FileDescriptor fd) {		private void dumpProto(FileDescriptor fd) {
	@@ -4228,7 +4232,7 @@ public final class PowerManagerService extends SystemService
	/**		/**
	* Represents a wake lock that has been acquired by an application.		* Represents a wake lock that has been acquired by an application.
	*/		*/
	private final class WakeLock implements IBinder.DeathRecipient {		/* package */ final class WakeLock implements IBinder.DeathRecipient {
	public final IBinder mLock;		public final IBinder mLock;
	public int mFlags;		public int mFlags;
	public String mTag;		public String mTag;

services/core/java/com/android/server/power/WakeLockLog.java

0 → 100644

+1355 −0

File added.

Preview size limit exceeded, changes collapsed.

services/tests/servicestests/src/com/android/server/power/WakeLockLogTest.java

0 → 100644

+268 −0

Original line number	Original line	Diff line number	Diff line
			/*
			* Copyright (C) 2019 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.power;

			import static org.junit.Assert.assertEquals;
			import static org.mockito.Mockito.spy;
			import static org.mockito.Mockito.when;

			import android.os.Looper;
			import android.os.PowerManager;
			import android.os.test.TestLooper;

			import org.junit.After;
			import org.junit.Before;
			import org.junit.Test;

			import java.io.PrintWriter;
			import java.io.StringWriter;
			import java.text.SimpleDateFormat;
			import java.util.TimeZone;

			/**
			* Tests for {@link WakeLockLog}.
			*/
			public class WakeLockLogTest {

			private TestLooper mTestLooper;

			@Before
			public void setUp() throws Exception {
			mTestLooper = new TestLooper();
			}

			@After
			public void tearDown() throws Exception {
			}

			@Test
			public void testAddTwoItems() {
			final int tagDatabaseSize = 128;
			final int logSize = 20;
			TestInjector injectorSpy = spy(new TestInjector(tagDatabaseSize, logSize));
			WakeLockLog log = new WakeLockLog(injectorSpy);

			when(injectorSpy.currentTimeMillis()).thenReturn(1000L);
			log.onWakeLockAcquired("TagPartial", 101,
			PowerManager.PARTIAL_WAKE_LOCK \| PowerManager.ON_AFTER_RELEASE);

			when(injectorSpy.currentTimeMillis()).thenReturn(1150L);
			log.onWakeLockAcquired("TagFull", 102,
			PowerManager.FULL_WAKE_LOCK \| PowerManager.ACQUIRE_CAUSES_WAKEUP);

			assertEquals("Wake Lock Log\n"
			+ " 01-01 00:00:01.000 - 101 - ACQ TagPartial (partial,on-after-release)\n"
			+ " 01-01 00:00:01.150 - 102 - ACQ TagFull (full,acq-causes-wake)\n"
			+ " -\n"
			+ " Events: 2, Time-Resets: 0\n"
			+ " Buffer, Bytes used: 6\n",
			dispatchAndDump(log, false));
			}

			@Test
			public void testAddTwoItemsWithTimeReset() {
			final int tagDatabaseSize = 128;
			final int logSize = 20;
			TestInjector injectorSpy = spy(new TestInjector(tagDatabaseSize, logSize));
			WakeLockLog log = new WakeLockLog(injectorSpy);

			when(injectorSpy.currentTimeMillis()).thenReturn(1000L);
			log.onWakeLockAcquired("TagPartial", 101, PowerManager.PARTIAL_WAKE_LOCK);

			when(injectorSpy.currentTimeMillis()).thenReturn(1350L);
			log.onWakeLockAcquired("TagFull", 102, PowerManager.FULL_WAKE_LOCK);

			assertEquals("Wake Lock Log\n"
			+ " 01-01 00:00:01.000 - 101 - ACQ TagPartial (partial)\n"
			+ " 01-01 00:00:01.350 - 102 - ACQ TagFull (full)\n"
			+ " -\n"
			+ " Events: 2, Time-Resets: 1\n"
			+ " Buffer, Bytes used: 15\n",
			dispatchAndDump(log, false));
			}

			@Test
			public void testAddTwoItemsWithTagOverwrite() {
			final int tagDatabaseSize = 2;
			final int logSize = 20;
			TestInjector injectorSpy = spy(new TestInjector(tagDatabaseSize, logSize));
			WakeLockLog log = new WakeLockLog(injectorSpy);

			when(injectorSpy.currentTimeMillis()).thenReturn(1000L);
			log.onWakeLockAcquired("TagPartial", 101, PowerManager.PARTIAL_WAKE_LOCK);

			when(injectorSpy.currentTimeMillis()).thenReturn(1150L);
			log.onWakeLockAcquired("TagFull", 102, PowerManager.FULL_WAKE_LOCK);

			assertEquals("Wake Lock Log\n"
			+ " 01-01 00:00:01.000 - --- - ACQ UNKNOWN (partial)\n"
			+ " 01-01 00:00:01.150 - 102 - ACQ TagFull (full)\n"
			+ " -\n"
			+ " Events: 2, Time-Resets: 0\n"
			+ " Buffer, Bytes used: 6\n",
			dispatchAndDump(log, false));
			}

			@Test
			public void testAddFourItemsWithRingBufferOverflow() {
			final int tagDatabaseSize = 6;
			final int logSize = 10;
			TestInjector injectorSpy = spy(new TestInjector(tagDatabaseSize, logSize));
			WakeLockLog log = new WakeLockLog(injectorSpy);

			// This first item will get deleted when ring buffer loops around
			when(injectorSpy.currentTimeMillis()).thenReturn(1000L);
			log.onWakeLockAcquired("TagPartial", 101, PowerManager.PARTIAL_WAKE_LOCK);

			when(injectorSpy.currentTimeMillis()).thenReturn(1150L);
			log.onWakeLockAcquired("TagFull", 102, PowerManager.FULL_WAKE_LOCK);
			when(injectorSpy.currentTimeMillis()).thenReturn(1151L);
			log.onWakeLockAcquired("TagThree", 101, PowerManager.PARTIAL_WAKE_LOCK);
			when(injectorSpy.currentTimeMillis()).thenReturn(1152L);
			log.onWakeLockAcquired("TagFour", 101, PowerManager.PARTIAL_WAKE_LOCK);

			assertEquals("Wake Lock Log\n"
			+ " 01-01 00:00:01.150 - 102 - ACQ TagFull (full)\n"
			+ " 01-01 00:00:01.151 - 101 - ACQ TagThree (partial)\n"
			+ " 01-01 00:00:01.152 - 101 - ACQ TagFour (partial)\n"
			+ " -\n"
			+ " Events: 3, Time-Resets: 0\n"
			+ " Buffer, Bytes used: 9\n",
			dispatchAndDump(log, false));
			}

			@Test
			public void testAddItemWithBadTag() {
			final int tagDatabaseSize = 6;
			final int logSize = 10;
			TestInjector injectorSpy = spy(new TestInjector(tagDatabaseSize, logSize));
			WakeLockLog log = new WakeLockLog(injectorSpy);

			// Bad tag means it wont get written
			when(injectorSpy.currentTimeMillis()).thenReturn(1000L);
			log.onWakeLockAcquired(null /* tag /, 0 / ownerUid */, PowerManager.PARTIAL_WAKE_LOCK);

			assertEquals("Wake Lock Log\n"
			+ " -\n"
			+ " Events: 0, Time-Resets: 0\n"
			+ " Buffer, Bytes used: 0\n",
			dispatchAndDump(log, false));
			}

			@Test
			public void testAddItemWithReducedTagName() {
			final int tagDatabaseSize = 6;
			final int logSize = 10;
			TestInjector injectorSpy = spy(new TestInjector(tagDatabaseSize, logSize));
			WakeLockLog log = new WakeLockLog(injectorSpy);

			when(injectorSpy.currentTimeMillis()).thenReturn(1000L);
			log.onWakeLockAcquired("job/com.one.two.3hree/.one..Last", 101,
			PowerManager.PARTIAL_WAKE_LOCK);

			assertEquals("Wake Lock Log\n"
			+ " 01-01 00:00:01.000 - 101 - ACQ job/c.o.t.3/.o..Last (partial)\n"
			+ " -\n"
			+ " Events: 1, Time-Resets: 0\n"
			+ " Buffer, Bytes used: 3\n",
			dispatchAndDump(log, false));
			}

			@Test
			public void testAddAcquireAndReleaseWithRepeatTagName() {
			final int tagDatabaseSize = 6;
			final int logSize = 10;
			TestInjector injectorSpy = spy(new TestInjector(tagDatabaseSize, logSize));
			WakeLockLog log = new WakeLockLog(injectorSpy);

			when(injectorSpy.currentTimeMillis()).thenReturn(1000L);
			log.onWakeLockAcquired("HowdyTag", 101, PowerManager.PARTIAL_WAKE_LOCK);
			when(injectorSpy.currentTimeMillis()).thenReturn(1001L);
			log.onWakeLockReleased("HowdyTag", 101);

			assertEquals("Wake Lock Log\n"
			+ " 01-01 00:00:01.000 - 101 - ACQ HowdyTag (partial)\n"
			+ " 01-01 00:00:01.001 - 101 - REL HowdyTag\n"
			+ " -\n"
			+ " Events: 2, Time-Resets: 0\n"
			+ " Buffer, Bytes used: 5\n"
			+ " Tag Database: size(5), entries: 1, Bytes used: 80\n",
			dispatchAndDump(log, true));
			}

			@Test
			public void testAddAcquireAndReleaseWithTimeTravel() {
			final int tagDatabaseSize = 6;
			final int logSize = 10;
			TestInjector injectorSpy = spy(new TestInjector(tagDatabaseSize, logSize));
			WakeLockLog log = new WakeLockLog(injectorSpy);

			when(injectorSpy.currentTimeMillis()).thenReturn(1100L);
			log.onWakeLockAcquired("HowdyTag", 101, PowerManager.PARTIAL_WAKE_LOCK);

			// New element goes back in time...should not be written to log.
			when(injectorSpy.currentTimeMillis()).thenReturn(1000L);
			log.onWakeLockReleased("HowdyTag", 101);

			assertEquals("Wake Lock Log\n"
			+ " 01-01 00:00:01.100 - 101 - ACQ HowdyTag (partial)\n"
			+ " -\n"
			+ " Events: 1, Time-Resets: 0\n"
			+ " Buffer, Bytes used: 3\n",
			dispatchAndDump(log, false));
			}

			private String dispatchAndDump(WakeLockLog log, boolean includeTagDb) {
			mTestLooper.dispatchAll();
			StringWriter sw = new StringWriter();
			PrintWriter pw = new PrintWriter(sw);
			log.dump(pw, includeTagDb);
			return sw.toString();
			}

			public class TestInjector extends WakeLockLog.Injector {
			private final int mTagDatabaseSize;
			private final int mLogSize;

			public TestInjector(int tagDatabaseSize, int logSize) {
			mTagDatabaseSize = tagDatabaseSize;
			mLogSize = logSize;
			}

			@Override
			public Looper getLooper() {
			return mTestLooper.getLooper();
			}

			@Override
			public int getTagDatabaseSize() {
			return mTagDatabaseSize;
			}

			@Override
			public int getLogSize() {
			return mLogSize;
			}

			@Override
			public SimpleDateFormat getDateFormat() {
			SimpleDateFormat format = new SimpleDateFormat(super.getDateFormat().toPattern());
			format.setTimeZone(TimeZone.getTimeZone("UTC"));
			return format;
			}
			}
			}