Add debug log mechanism to OomAdjsuter (7b553ea2) · Commits · e / os / android_frameworks_base

services/core/java/com/android/server/am/ActivityManagerConstants.java

+115 −0

Original line number	Diff line number	Diff line
		@@ -51,6 +51,7 @@ import android.text.TextUtils;
		import android.util.ArraySet;
		import android.util.KeyValueListParser;
		import android.util.Slog;
		import android.util.SparseBooleanArray;

		import com.android.internal.R;
		import com.android.internal.annotations.GuardedBy;
		@@ -436,6 +437,18 @@ final class ActivityManagerConstants extends ContentObserver {
		private static final String KEY_MAX_SERVICE_CONNECTIONS_PER_PROCESS =
		"max_service_connections_per_process";

		private static final String KEY_PROC_STATE_DEBUG_UIDS = "proc_state_debug_uids";

		/**
		* UIDs we want to print detailed info in OomAdjuster.
		* It's only used for debugging, and it's almost never updated, so we just create a new
		* array when it's changed to avoid synchronization.
		*/
		volatile SparseBooleanArray mProcStateDebugUids = new SparseBooleanArray(0);
		volatile boolean mEnableProcStateStacktrace = false;
		volatile int mProcStateDebugSetProcStateDelay = 0;
		volatile int mProcStateDebugSetUidStateDelay = 0;

		// Maximum number of cached processes we will allow.
		public int MAX_CACHED_PROCESSES = DEFAULT_MAX_CACHED_PROCESSES;

		@@ -1339,6 +1352,9 @@ final class ActivityManagerConstants extends ContentObserver {
		case KEY_PSS_TO_RSS_THRESHOLD_MODIFIER:
		updatePssToRssThresholdModifier();
		break;
		case KEY_PROC_STATE_DEBUG_UIDS:
		updateProcStateDebugUids();
		break;
		default:
		updateFGSPermissionEnforcementFlagsIfNecessary(name);
		break;
		@@ -2039,6 +2055,76 @@ final class ActivityManagerConstants extends ContentObserver {
		DEFAULT_MAX_PREVIOUS_TIME);
		}

		private void updateProcStateDebugUids() {
		final String val = DeviceConfig.getString(
		DeviceConfig.NAMESPACE_ACTIVITY_MANAGER,
		KEY_PROC_STATE_DEBUG_UIDS,
		"").trim();

		// Parse KEY_PROC_STATE_DEBUG_UIDS as comma-separated values. Each values can be:
		// Number: Enable debugging on the given UID.
		// "stack": Enable stack trace when updating proc/uid-states.s
		// "u" + delay-ms: Enable sleep when updating uid-state
		// "p" + delay-ms: Enable sleep when updating procstate
		//
		// Example:
		// device_config put activity_manager proc_state_debug_uids '10177,10202,stack,p500,u100'
		// means:
		// - Monitor UID 10177 and 10202
		// - Also enable stack trace
		// - Sleep 500 ms when updating the procstate.
		// - Sleep 100 ms when updating the UID state.

		mEnableProcStateStacktrace = false;
		mProcStateDebugSetProcStateDelay = 0;
		mProcStateDebugSetUidStateDelay = 0;
		if (val.length() == 0) {
		mProcStateDebugUids = new SparseBooleanArray(0);
		return;
		}
		final String[] uids = val.split(",");

		final SparseBooleanArray newArray = new SparseBooleanArray(0);

		for (String token : uids) {
		if (token.length() == 0) {
		continue;
		}
		// "stack" -> enable stacktrace.
		if ("stack".equals(token)) {
		mEnableProcStateStacktrace = true;
		continue;
		}
		boolean isUid = true;
		char prefix = token.charAt(0);
		if ('a' <= prefix && prefix <= 'z') {
		// If the token starts with an alphabet, it's not a UID.
		isUid = false;
		token = token.substring(1);
		}

		int value = -1;
		try {
		value = Integer.parseInt(token.trim());
		} catch (NumberFormatException e) {
		Slog.w(TAG, "Invalid number " + token + " in " + val);
		continue;
		}
		if (isUid) {
		newArray.put(value, true);
		} else if (prefix == 'p') {
		// Enable delay in set-proc-state
		mProcStateDebugSetProcStateDelay = value;
		} else if (prefix == 'u') {
		// Enable delay in set-uid-state
		mProcStateDebugSetUidStateDelay = value;
		} else {
		Slog.w(TAG, "Invalid prefix " + prefix + " in " + val);
		}
		}
		mProcStateDebugUids = newArray;
		}

		private void updateMinAssocLogDuration() {
		MIN_ASSOC_LOG_DURATION = DeviceConfig.getLong(
		DeviceConfig.NAMESPACE_ACTIVITY_MANAGER, KEY_MIN_ASSOC_LOG_DURATION,
		@@ -2178,6 +2264,28 @@ final class ActivityManagerConstants extends ContentObserver {
		mDefaultPssToRssThresholdModifier);
		}

		boolean shouldDebugUidForProcState(int uid) {
		SparseBooleanArray ar = mProcStateDebugUids;
		final var size = ar.size();
		if (size == 0) { // Most common case.
		return false;
		}
		// If the array is small (also common), avoid the binary search.
		if (size <= 8) {
		for (int i = 0; i < size; i++) {
		if (ar.keyAt(i) == uid) {
		return ar.valueAt(i);
		}
		}
		return false;
		}
		return ar.get(uid, false);
		}

		boolean shouldEnableProcStateDebug() {
		return mProcStateDebugUids.size() > 0;
		}

		@NeverCompile // Avoid size overhead of debugging code.
		void dump(PrintWriter pw) {
		pw.println("ACTIVITY MANAGER SETTINGS (dumpsys activity settings) "
		@@ -2393,5 +2501,12 @@ final class ActivityManagerConstants extends ContentObserver {
		pw.print(" OOMADJ_UPDATE_QUICK="); pw.println(OOMADJ_UPDATE_QUICK);
		pw.print(" ENABLE_WAIT_FOR_FINISH_ATTACH_APPLICATION=");
		pw.println(mEnableWaitForFinishAttachApplication);

		synchronized (mProcStateDebugUids) {
		pw.print(" "); pw.print(KEY_PROC_STATE_DEBUG_UIDS);
		pw.print("="); pw.println(mProcStateDebugUids);
		pw.print(" uid-state-delay="); pw.println(mProcStateDebugSetUidStateDelay);
		pw.print(" proc-state-delay="); pw.println(mProcStateDebugSetProcStateDelay);
		}
		}
		}

services/core/java/com/android/server/am/EventLogTags.logtags

+6 −0

Original line number	Diff line number	Diff line
		@@ -135,3 +135,9 @@ option java_package com.android.server.am

		# Caller information to clear application data
		30120 am_clear_app_data_caller (pid\|1),(uid\|1),(package\|3)

		30111 am_uid_state_changed (UID\|1\|5),(Seq\|1\|5),(UidState\|1\|5),(OldUidState\|1\|5),(Capability\|1\|5),(OldCapability\|1\|5),(Flags\|1\|5),(reason\|3)
		30112 am_proc_state_changed (UID\|1\|5),(PID\|1\|5),(Seq\|1\|5),(ProcState\|1\|5),(OldProcState\|1\|5),(OomAdj\|1\|5),(OldOomAdj\|1\|5),(reason\|3)

		# "Misc" events. See OomAdjusterDebugLogger.java
		30113 am_oom_adj_misc (Event\|1\|5),(UID\|1\|5),(PID\|1\|5),(Seq\|1\|5),(Arg1\|1\|5),(Arg2\|1\|5),(reason\|3)

services/core/java/com/android/server/am/OomAdjuster.java

+61 −3

Original line number	Diff line number	Diff line
		@@ -401,6 +401,14 @@ public class OomAdjuster {
		@GuardedBy("mService")
		private boolean mPendingFullOomAdjUpdate = false;

		/**
		* Most recent reason string. We update it in sync with the trace.
		*/
		@OomAdjReason
		protected int mLastReason;

		private final OomAdjusterDebugLogger mLogger;

		/** Overrideable by a test */
		@VisibleForTesting
		protected boolean isChangeEnabled(@CachedCompatChangeId int cachedCompatChangeId,
		@@ -433,6 +441,8 @@ public class OomAdjuster {
		mCachedAppOptimizer = new CachedAppOptimizer(mService);
		mCacheOomRanker = new CacheOomRanker(service);

		mLogger = new OomAdjusterDebugLogger(this, mService.mConstants);

		mProcessGroupHandler = new Handler(adjusterThread.getLooper(), msg -> {
		final int pid = msg.arg1;
		final int group = msg.arg2;
		@@ -636,6 +646,7 @@ public class OomAdjuster {
		protected boolean performUpdateOomAdjLSP(ProcessRecord app, @OomAdjReason int oomAdjReason) {
		final ProcessRecord topApp = mService.getTopApp();

		mLastReason = oomAdjReason;
		Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, oomAdjReasonToString(oomAdjReason));
		mService.mOomAdjProfiler.oomAdjStarted();
		mAdjSeq++;
		@@ -916,6 +927,7 @@ public class OomAdjuster {
		protected void performUpdateOomAdjPendingTargetsLocked(@OomAdjReason int oomAdjReason) {
		final ProcessRecord topApp = mService.getTopApp();

		mLastReason = oomAdjReason;
		Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, oomAdjReasonToString(oomAdjReason));
		mService.mOomAdjProfiler.oomAdjStarted();

		@@ -958,6 +970,7 @@ public class OomAdjuster {
		}
		}

		mLastReason = oomAdjReason;
		if (startProfiling) {
		Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, oomAdjReasonToString(oomAdjReason));
		mService.mOomAdjProfiler.oomAdjStarted();
		@@ -1490,6 +1503,7 @@ public class OomAdjuster {
		\|\| uidRec.isSetAllowListed() != uidRec.isCurAllowListed()
		\|\| uidRec.getProcAdjChanged()) {
		int uidChange = 0;
		final boolean shouldLog = mLogger.shouldLog(uidRec.getUid());
		if (DEBUG_UID_OBSERVERS) {
		Slog.i(TAG_UID_OBSERVERS, "Changes in " + uidRec
		+ ": proc state from " + uidRec.getSetProcState() + " to "
		@@ -1510,15 +1524,22 @@ public class OomAdjuster {
		\|\| uidRec.isSetAllowListed()
		\|\| uidRec.getLastBackgroundTime() == 0) {
		uidRec.setLastBackgroundTime(nowElapsed);
		if (shouldLog) {
		mLogger.logSetLastBackgroundTime(uidRec.getUid(), nowElapsed);
		}
		if (mService.mDeterministicUidIdle
		\|\| !mService.mHandler.hasMessages(IDLE_UIDS_MSG)) {
		// Note: the background settle time is in elapsed realtime, while
		// the handler time base is uptime. All this means is that we may
		// stop background uids later than we had intended, but that only
		// happens because the device was sleeping so we are okay anyway.
		mService.mHandler.sendEmptyMessageDelayed(IDLE_UIDS_MSG,
		if (shouldLog) {
		mLogger.logScheduleUidIdle1(uidRec.getUid(),
		mConstants.BACKGROUND_SETTLE_TIME);
		}
		mService.mHandler.sendEmptyMessageDelayed(IDLE_UIDS_MSG,
		mConstants.BACKGROUND_SETTLE_TIME); // XXX
		}
		}
		if (uidRec.isIdle() && !uidRec.isSetIdle()) {
		uidChange \|= UidRecord.CHANGE_IDLE;
		@@ -1535,6 +1556,9 @@ public class OomAdjuster {
		}
		uidRec.setLastBackgroundTime(0);
		uidRec.setLastIdleTime(0);
		if (shouldLog) {
		mLogger.logClearLastBackgroundTime(uidRec.getUid());
		}
		}
		final boolean wasCached = uidRec.getSetProcState()
		> ActivityManager.PROCESS_STATE_RECEIVER;
		@@ -1554,11 +1578,25 @@ public class OomAdjuster {
		if (uidRec.getProcAdjChanged()) {
		uidChange \|= UidRecord.CHANGE_PROCADJ;
		}
		int oldProcState = uidRec.getSetProcState();
		int oldCapability = uidRec.getSetCapability();
		uidRec.setSetProcState(uidRec.getCurProcState());
		uidRec.setSetCapability(uidRec.getCurCapability());
		uidRec.setSetAllowListed(uidRec.isCurAllowListed());
		uidRec.setSetIdle(uidRec.isIdle());
		uidRec.clearProcAdjChanged();
		if (shouldLog
		&& ((uidRec.getSetProcState() != oldProcState)
		\|\| (uidRec.getSetCapability() != oldCapability))) {
		int flags = 0;
		if (uidRec.isSetAllowListed()) {
		flags \|= 1;
		}
		mLogger.logUidStateChanged(uidRec.getUid(),
		uidRec.getSetProcState(), oldProcState,
		uidRec.getSetCapability(), oldCapability,
		flags);
		}
		if ((uidChange & UidRecord.CHANGE_PROCSTATE) != 0
		\|\| (uidChange & UidRecord.CHANGE_CAPABILITY) != 0) {
		mService.mAtmInternal.onUidProcStateChanged(
		@@ -3299,6 +3337,7 @@ public class OomAdjuster {
		mCachedAppOptimizer.onOomAdjustChanged(state.getSetAdj(), state.getCurAdj(), app);
		}

		final int oldOomAdj = state.getSetAdj();
		if (state.getCurAdj() != state.getSetAdj()) {
		ProcessList.setOomAdj(app.getPid(), app.uid, state.getCurAdj());
		if (DEBUG_SWITCH \|\| DEBUG_OOM_ADJ \|\| mService.mCurOomAdjUid == app.info.uid) {
		@@ -3456,6 +3495,7 @@ public class OomAdjuster {
		mService.mAppProfiler.updateNextPssTimeLPf(
		state.getCurProcState(), app.mProfile, now, forceUpdatePssTime);
		}
		int oldProcState = state.getSetProcState();
		if (state.getSetProcState() != state.getCurProcState()) {
		if (DEBUG_SWITCH \|\| DEBUG_OOM_ADJ \|\| mService.mCurOomAdjUid == app.uid) {
		String msg = "Proc state change of " + app.processName
		@@ -3555,6 +3595,11 @@ public class OomAdjuster {
		// Kick off the delayed checkup message if needed.
		if (mService.mDeterministicUidIdle
		\|\| !mService.mHandler.hasMessages(IDLE_UIDS_MSG)) {
		if (mLogger.shouldLog(app.uid)) {
		mLogger.logScheduleUidIdle2(
		uidRec.getUid(), app.getPid(),
		mConstants.mKillBgRestrictedAndCachedIdleSettleTimeMs);
		}
		mService.mHandler.sendEmptyMessageDelayed(IDLE_UIDS_MSG,
		mConstants.mKillBgRestrictedAndCachedIdleSettleTimeMs);
		}
		@@ -3562,6 +3607,12 @@ public class OomAdjuster {
		}
		state.setSetCached(state.isCached());
		state.setSetNoKillOnBgRestrictedAndIdle(state.shouldNotKillOnBgRestrictedAndIdle());
		if (((oldProcState != state.getSetProcState()) \|\| (oldOomAdj != state.getSetAdj()))
		&& mLogger.shouldLog(app.uid)) {
		mLogger.logProcStateChanged(app.uid, app.getPid(),
		state.getSetProcState(), oldProcState,
		state.getSetAdj(), oldOomAdj);
		}

		return success;
		}
		@@ -3703,6 +3754,7 @@ public class OomAdjuster {
		if (mService.mLocalPowerManager != null) {
		mService.mLocalPowerManager.startUidChanges();
		}
		boolean shouldLogMisc = false;
		for (int i = N - 1; i >= 0; i--) {
		final UidRecord uidRec = mActiveUids.valueAt(i);
		final long bgTime = uidRec.getLastBackgroundTime();
		@@ -3720,6 +3772,9 @@ public class OomAdjuster {
		if (nextTime == 0 \|\| nextTime > bgTime) {
		nextTime = bgTime;
		}
		if (mLogger.shouldLog(uidRec.getUid())) {
		shouldLogMisc = true;
		}
		}
		}
		}
		@@ -3741,8 +3796,11 @@ public class OomAdjuster {
		}
		}
		if (nextTime > 0) {
		mService.mHandler.sendEmptyMessageDelayed(IDLE_UIDS_MSG,
		nextTime + mConstants.BACKGROUND_SETTLE_TIME - nowElapsed);
		long delay = nextTime + mConstants.BACKGROUND_SETTLE_TIME - nowElapsed;
		if (shouldLogMisc) {
		mLogger.logScheduleUidIdle3(delay);
		}
		mService.mHandler.sendEmptyMessageDelayed(IDLE_UIDS_MSG, delay);
		}
		}

services/core/java/com/android/server/am/OomAdjusterDebugLogger.java

0 → 100644

+110 −0

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

		import android.app.StackTrace;
		import android.util.Slog;

		/**
		* Helper for writing debug log about proc/uid state changes.
		*/
		class OomAdjusterDebugLogger {
		// Use the "am_" tag to make it similar to event logs.
		private static final String STACK_TRACE_TAG = "am_stack";

		private final OomAdjuster mOomAdjuster;
		private final ActivityManagerConstants mConstants;

		private static final int MISC_SCHEDULE_IDLE_UIDS_MSG_1 = 1;
		private static final int MISC_SCHEDULE_IDLE_UIDS_MSG_2 = 2;
		private static final int MISC_SCHEDULE_IDLE_UIDS_MSG_3 = 3;

		private static final int MISC_SET_LAST_BG_TIME = 10;
		private static final int MISC_CLEAR_LAST_BG_TIME = 11;

		OomAdjusterDebugLogger(OomAdjuster oomAdjuster, ActivityManagerConstants constants) {
		mOomAdjuster = oomAdjuster;
		mConstants = constants;
		}

		boolean shouldLog(int uid) {
		return mConstants.shouldDebugUidForProcState(uid);
		}

		private void maybeLogStacktrace(String msg) {
		if (!mConstants.mEnableProcStateStacktrace) {
		return;
		}
		Slog.i(STACK_TRACE_TAG,
		msg + ": " + OomAdjuster.oomAdjReasonToString(mOomAdjuster.mLastReason),
		new StackTrace("Called here"));
		}

		private void maybeSleep(int millis) {
		if (millis == 0) {
		return;
		}
		try {
		Thread.sleep(millis);
		} catch (InterruptedException e) {
		}
		}

		void logUidStateChanged(int uid, int uidstate, int olduidstate,
		int capability, int oldcapability, int flags) {
		EventLogTags.writeAmUidStateChanged(
		uid, mOomAdjuster.mAdjSeq, uidstate, olduidstate, capability, oldcapability, flags,
		OomAdjuster.oomAdjReasonToString(mOomAdjuster.mLastReason));
		maybeLogStacktrace("uidStateChanged");
		maybeSleep(mConstants.mProcStateDebugSetUidStateDelay);
		}

		void logProcStateChanged(int uid, int pid, int procstate, int oldprocstate,
		int oomadj, int oldoomadj) {
		EventLogTags.writeAmProcStateChanged(
		uid, pid, mOomAdjuster.mAdjSeq, procstate, oldprocstate, oomadj, oldoomadj,
		OomAdjuster.oomAdjReasonToString(mOomAdjuster.mLastReason));
		maybeLogStacktrace("procStateChanged");
		maybeSleep(mConstants.mProcStateDebugSetProcStateDelay);
		}

		void logScheduleUidIdle1(int uid, long delay) {
		EventLogTags.writeAmOomAdjMisc(MISC_SCHEDULE_IDLE_UIDS_MSG_1,
		uid, 0, mOomAdjuster.mAdjSeq, (int) delay, 0, "");
		}

		void logScheduleUidIdle2(int uid, int pid, long delay) {
		EventLogTags.writeAmOomAdjMisc(MISC_SCHEDULE_IDLE_UIDS_MSG_2,
		uid, pid, mOomAdjuster.mAdjSeq, (int) delay, 0, "");
		}

		void logScheduleUidIdle3(long delay) {
		EventLogTags.writeAmOomAdjMisc(MISC_SCHEDULE_IDLE_UIDS_MSG_3,
		0, 0, mOomAdjuster.mAdjSeq, (int) delay, 0, "");
		}

		void logSetLastBackgroundTime(int uid, long time) {
		EventLogTags.writeAmOomAdjMisc(MISC_SET_LAST_BG_TIME,
		uid, 0, mOomAdjuster.mAdjSeq, (int) time, 0,
		OomAdjuster.oomAdjReasonToString(mOomAdjuster.mLastReason));
		}

		void logClearLastBackgroundTime(int uid) {
		EventLogTags.writeAmOomAdjMisc(MISC_CLEAR_LAST_BG_TIME,
		uid, 0, mOomAdjuster.mAdjSeq, 0, 0,
		OomAdjuster.oomAdjReasonToString(mOomAdjuster.mLastReason));
		}
		}

services/core/java/com/android/server/am/OomAdjusterModernImpl.java

+2 −0

Original line number	Diff line number	Diff line
		@@ -741,6 +741,7 @@ public class OomAdjusterModernImpl extends OomAdjuster {
		mPendingProcessSet.clear();
		mService.mAppProfiler.mHasPreviousProcess = mService.mAppProfiler.mHasHomeProcess = false;

		mLastReason = oomAdjReason;
		Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, oomAdjReasonToString(oomAdjReason));
		mService.mOomAdjProfiler.oomAdjStarted();

		@@ -761,6 +762,7 @@ public class OomAdjusterModernImpl extends OomAdjuster {
		@GuardedBy("mService")
		@Override
		protected void performUpdateOomAdjPendingTargetsLocked(@OomAdjReason int oomAdjReason) {
		mLastReason = oomAdjReason;
		Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, oomAdjReasonToString(oomAdjReason));
		mService.mOomAdjProfiler.oomAdjStarted();