Merge "Add more logging for Wakelocks." (1f294aa9) · Commits · e / os / android_frameworks_base

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

+19 −0

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

		import java.io.PrintWriter;

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

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

		mWakeLockLog = new WakeLockLog();

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

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

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

		private int getBatteryStatsWakeLockMonitorType(int flags) {
		@@ -647,6 +655,17 @@ public class Notifier {
		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() {
		if (!mBroadcastInProgress
		&& mPendingInteractiveState != INTERACTIVE_STATE_UNKNOWN

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

+5 −1

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

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

		private void dumpProto(FileDescriptor fd) {
		@@ -4268,7 +4272,7 @@ public final class PowerManagerService extends SystemService
		/**
		* 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 int mFlags;
		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	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;
		}
		}
		}