diff options
5 files changed, 294 insertions, 3 deletions
diff --git a/services/core/java/com/android/server/am/ActivityManagerConstants.java b/services/core/java/com/android/server/am/ActivityManagerConstants.java index ff837974bf3c..272e84b80870 100644 --- a/services/core/java/com/android/server/am/ActivityManagerConstants.java +++ b/services/core/java/com/android/server/am/ActivityManagerConstants.java @@ -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); + } } } diff --git a/services/core/java/com/android/server/am/EventLogTags.logtags b/services/core/java/com/android/server/am/EventLogTags.logtags index 80387322b038..b142781418e8 100644 --- a/services/core/java/com/android/server/am/EventLogTags.logtags +++ b/services/core/java/com/android/server/am/EventLogTags.logtags @@ -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) diff --git a/services/core/java/com/android/server/am/OomAdjuster.java b/services/core/java/com/android/server/am/OomAdjuster.java index cd6964ea2631..c2125b68fd3f 100644 --- a/services/core/java/com/android/server/am/OomAdjuster.java +++ b/services/core/java/com/android/server/am/OomAdjuster.java @@ -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,14 +1524,21 @@ 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. + if (shouldLog) { + mLogger.logScheduleUidIdle1(uidRec.getUid(), + mConstants.BACKGROUND_SETTLE_TIME); + } mService.mHandler.sendEmptyMessageDelayed(IDLE_UIDS_MSG, - mConstants.BACKGROUND_SETTLE_TIME); + mConstants.BACKGROUND_SETTLE_TIME); // XXX } } if (uidRec.isIdle() && !uidRec.isSetIdle()) { @@ -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); } } diff --git a/services/core/java/com/android/server/am/OomAdjusterDebugLogger.java b/services/core/java/com/android/server/am/OomAdjusterDebugLogger.java new file mode 100644 index 000000000000..1294a4d25c44 --- /dev/null +++ b/services/core/java/com/android/server/am/OomAdjusterDebugLogger.java @@ -0,0 +1,110 @@ +/* + * 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)); + } +} diff --git a/services/core/java/com/android/server/am/OomAdjusterModernImpl.java b/services/core/java/com/android/server/am/OomAdjusterModernImpl.java index dd75bc0442d0..86684b6a193f 100644 --- a/services/core/java/com/android/server/am/OomAdjusterModernImpl.java +++ b/services/core/java/com/android/server/am/OomAdjusterModernImpl.java @@ -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(); |