From: Bryce Lee Date: Tue, 16 Jan 2018 23:59:47 +0000 (-0800) Subject: Add more logging to Activity Lifecycler. X-Git-Tag: android-x86-9.0-r1~259^2~30^2 X-Git-Url: http://git.osdn.net/view?a=commitdiff_plain;h=d946f86f124fca87c757100e49ba7d5b206c8a44;p=android-x86%2Fframeworks-base.git Add more logging to Activity Lifecycler. This changelist introduces temporary logging targeting an issue where lifecycle transactions are executing for non-existent client records. Additional details are retained and exposed in this case to help better understand what is happening. Bug: 71506345 Test: manual Change-Id: Ibfdbbd5ef0c465294709383405403aa0d3508ecb --- diff --git a/core/java/android/app/ActivityThread.java b/core/java/android/app/ActivityThread.java index 70c383b29c63..78d6e0a080bf 100644 --- a/core/java/android/app/ActivityThread.java +++ b/core/java/android/app/ActivityThread.java @@ -166,6 +166,7 @@ import java.lang.reflect.Field; import java.lang.reflect.Method; import java.net.InetAddress; import java.text.DateFormat; +import java.util.ArrayDeque; import java.util.ArrayList; import java.util.Arrays; import java.util.List; @@ -220,6 +221,9 @@ public final class ActivityThread extends ClientTransactionHandler { // Whether to invoke an activity callback after delivering new configuration. private static final boolean REPORT_TO_ACTIVITY = true; + // Maximum number of recent tokens to maintain for debugging purposes + private static final int MAX_RECENT_TOKENS = 10; + /** * Denotes an invalid sequence number corresponding to a process state change. */ @@ -252,6 +256,8 @@ public final class ActivityThread extends ClientTransactionHandler { final H mH = new H(); final Executor mExecutor = new HandlerExecutor(mH); final ArrayMap mActivities = new ArrayMap<>(); + final ArrayDeque mRecentTokens = new ArrayDeque<>(); + // List of new activities (via ActivityRecord.nextIdle) that should // be reported when next we idle. ActivityClientRecord mNewActivities = null; @@ -2168,6 +2174,18 @@ public final class ActivityThread extends ClientTransactionHandler { pw.println(String.format(format, objs)); } + @Override + public void dump(PrintWriter pw, String prefix) { + pw.println(prefix + "mActivities:"); + + for (ArrayMap.Entry entry : mActivities.entrySet()) { + pw.println(prefix + " [token:" + entry.getKey().hashCode() + " record:" + + entry.getValue().toString() + "]"); + } + + pw.println(prefix + "mRecentTokens:" + mRecentTokens); + } + public static void dumpMemInfoTable(PrintWriter pw, Debug.MemoryInfo memInfo, boolean checkin, boolean dumpFullInfo, boolean dumpDalvik, boolean dumpSummaryOnly, int pid, String processName, @@ -2852,6 +2870,11 @@ public final class ActivityThread extends ClientTransactionHandler { r.setState(ON_CREATE); mActivities.put(r.token, r); + mRecentTokens.push(r.token.hashCode()); + + if (mRecentTokens.size() > MAX_RECENT_TOKENS) { + mRecentTokens.removeLast(); + } } catch (SuperNotCalledException e) { throw e; diff --git a/core/java/android/app/ClientTransactionHandler.java b/core/java/android/app/ClientTransactionHandler.java index 45c0e0cdfb25..0f66652af76c 100644 --- a/core/java/android/app/ClientTransactionHandler.java +++ b/core/java/android/app/ClientTransactionHandler.java @@ -24,6 +24,7 @@ import android.os.IBinder; import com.android.internal.content.ReferrerIntent; +import java.io.PrintWriter; import java.util.List; /** @@ -121,4 +122,11 @@ public abstract class ClientTransactionHandler { * provided token. */ public abstract ActivityThread.ActivityClientRecord getActivityClient(IBinder token); + + /** + * Debugging output. + * @param pw {@link PrintWriter} to write logs to. + * @param prefix Prefix to prepend to output. + */ + public abstract void dump(PrintWriter pw, String prefix); } diff --git a/core/java/android/app/servertransaction/ActivityLifecycleItem.java b/core/java/android/app/servertransaction/ActivityLifecycleItem.java index 0fdc7c56fd01..9a50a009ce34 100644 --- a/core/java/android/app/servertransaction/ActivityLifecycleItem.java +++ b/core/java/android/app/servertransaction/ActivityLifecycleItem.java @@ -17,7 +17,9 @@ package android.app.servertransaction; import android.annotation.IntDef; +import android.os.Parcel; +import java.io.PrintWriter; import java.lang.annotation.Retention; import java.lang.annotation.RetentionPolicy; @@ -26,6 +28,7 @@ import java.lang.annotation.RetentionPolicy; * @hide */ public abstract class ActivityLifecycleItem extends ClientTransactionItem { + private String mDescription; @IntDef(prefix = { "UNDEFINED", "PRE_", "ON_" }, value = { UNDEFINED, @@ -53,4 +56,39 @@ public abstract class ActivityLifecycleItem extends ClientTransactionItem { /** A final lifecycle state that an activity should reach. */ @LifecycleState public abstract int getTargetState(); + + + protected ActivityLifecycleItem() { + } + + protected ActivityLifecycleItem(Parcel in) { + mDescription = in.readString(); + } + + @Override + public void writeToParcel(Parcel dest, int flags) { + dest.writeString(mDescription); + } + + /** + * Sets a description that can be retrieved later for debugging purposes. + * @param description Description to set. + * @return The {@link ActivityLifecycleItem}. + */ + public ActivityLifecycleItem setDescription(String description) { + mDescription = description; + return this; + } + + /** + * Retrieves description if set through {@link #setDescription(String)}. + */ + public String getDescription() { + return mDescription; + } + + void dump(PrintWriter pw, String prefix) { + pw.println(prefix + "target state:" + getTargetState()); + pw.println(prefix + "description: " + mDescription); + } } diff --git a/core/java/android/app/servertransaction/ClientTransaction.java b/core/java/android/app/servertransaction/ClientTransaction.java index 08ad2f055774..fc078798f6b9 100644 --- a/core/java/android/app/servertransaction/ClientTransaction.java +++ b/core/java/android/app/servertransaction/ClientTransaction.java @@ -26,6 +26,7 @@ import android.os.RemoteException; import com.android.internal.annotations.VisibleForTesting; +import java.io.PrintWriter; import java.util.ArrayList; import java.util.List; import java.util.Objects; @@ -237,4 +238,12 @@ public class ClientTransaction implements Parcelable, ObjectPoolItem { result = 31 * result + Objects.hashCode(mLifecycleStateRequest); return result; } + + void dump(PrintWriter pw, String prefix) { + pw.println(prefix + "mActivityToken:" + mActivityToken.hashCode()); + pw.println(prefix + "mLifecycleStateRequest:"); + if (mLifecycleStateRequest != null) { + mLifecycleStateRequest.dump(pw, prefix + " "); + } + } } diff --git a/core/java/android/app/servertransaction/DestroyActivityItem.java b/core/java/android/app/servertransaction/DestroyActivityItem.java index 83da5f33c62a..cbcf6c750fed 100644 --- a/core/java/android/app/servertransaction/DestroyActivityItem.java +++ b/core/java/android/app/servertransaction/DestroyActivityItem.java @@ -76,12 +76,14 @@ public class DestroyActivityItem extends ActivityLifecycleItem { /** Write to Parcel. */ @Override public void writeToParcel(Parcel dest, int flags) { + super.writeToParcel(dest, flags); dest.writeBoolean(mFinished); dest.writeInt(mConfigChanges); } /** Read from Parcel. */ private DestroyActivityItem(Parcel in) { + super(in); mFinished = in.readBoolean(); mConfigChanges = in.readInt(); } diff --git a/core/java/android/app/servertransaction/PauseActivityItem.java b/core/java/android/app/servertransaction/PauseActivityItem.java index 880fef73c6f2..70a4755f99af 100644 --- a/core/java/android/app/servertransaction/PauseActivityItem.java +++ b/core/java/android/app/servertransaction/PauseActivityItem.java @@ -114,6 +114,7 @@ public class PauseActivityItem extends ActivityLifecycleItem { /** Write to Parcel. */ @Override public void writeToParcel(Parcel dest, int flags) { + super.writeToParcel(dest, flags); dest.writeBoolean(mFinished); dest.writeBoolean(mUserLeaving); dest.writeInt(mConfigChanges); @@ -122,6 +123,7 @@ public class PauseActivityItem extends ActivityLifecycleItem { /** Read from Parcel. */ private PauseActivityItem(Parcel in) { + super(in); mFinished = in.readBoolean(); mUserLeaving = in.readBoolean(); mConfigChanges = in.readInt(); diff --git a/core/java/android/app/servertransaction/ResumeActivityItem.java b/core/java/android/app/servertransaction/ResumeActivityItem.java index 9249c6e8ed54..ed90f2cb1013 100644 --- a/core/java/android/app/servertransaction/ResumeActivityItem.java +++ b/core/java/android/app/servertransaction/ResumeActivityItem.java @@ -113,6 +113,7 @@ public class ResumeActivityItem extends ActivityLifecycleItem { /** Write to Parcel. */ @Override public void writeToParcel(Parcel dest, int flags) { + super.writeToParcel(dest, flags); dest.writeInt(mProcState); dest.writeBoolean(mUpdateProcState); dest.writeBoolean(mIsForward); @@ -120,6 +121,7 @@ public class ResumeActivityItem extends ActivityLifecycleItem { /** Read from Parcel. */ private ResumeActivityItem(Parcel in) { + super(in); mProcState = in.readInt(); mUpdateProcState = in.readBoolean(); mIsForward = in.readBoolean(); diff --git a/core/java/android/app/servertransaction/StopActivityItem.java b/core/java/android/app/servertransaction/StopActivityItem.java index 5c5c3041344f..b814d1ae1392 100644 --- a/core/java/android/app/servertransaction/StopActivityItem.java +++ b/core/java/android/app/servertransaction/StopActivityItem.java @@ -83,12 +83,14 @@ public class StopActivityItem extends ActivityLifecycleItem { /** Write to Parcel. */ @Override public void writeToParcel(Parcel dest, int flags) { + super.writeToParcel(dest, flags); dest.writeBoolean(mShowWindow); dest.writeInt(mConfigChanges); } /** Read from Parcel. */ private StopActivityItem(Parcel in) { + super(in); mShowWindow = in.readBoolean(); mConfigChanges = in.readInt(); } diff --git a/core/java/android/app/servertransaction/TransactionExecutor.java b/core/java/android/app/servertransaction/TransactionExecutor.java index 5b0ea6b1f9d4..78b393a831f9 100644 --- a/core/java/android/app/servertransaction/TransactionExecutor.java +++ b/core/java/android/app/servertransaction/TransactionExecutor.java @@ -33,6 +33,8 @@ import android.util.Slog; import com.android.internal.annotations.VisibleForTesting; +import java.io.PrintWriter; +import java.io.StringWriter; import java.util.List; /** @@ -122,6 +124,21 @@ public class TransactionExecutor { final IBinder token = transaction.getActivityToken(); final ActivityClientRecord r = mTransactionHandler.getActivityClient(token); + // TODO(b/71506345): Remove once root cause is found. + if (r == null) { + final StringWriter stringWriter = new StringWriter(); + final PrintWriter pw = new PrintWriter(stringWriter); + final String prefix = " "; + + pw.println("Lifecycle transaction does not have valid ActivityClientRecord."); + pw.println("Transaction:"); + transaction.dump(pw, prefix); + pw.println("Executor:"); + dump(pw, prefix); + + Slog.wtf(TAG, stringWriter.toString()); + } + // Cycle to the state right before the final requested state. cycleToPath(r, lifecycleItem.getTargetState(), true /* excludeLastState */); @@ -245,4 +262,9 @@ public class TransactionExecutor { private static void log(String message) { if (DEBUG_RESOLVER) Slog.d(TAG, message); } + + private void dump(PrintWriter pw, String prefix) { + pw.println(prefix + "mTransactionHandler:"); + mTransactionHandler.dump(pw, prefix + " "); + } } diff --git a/services/core/java/com/android/server/am/ActivityRecord.java b/services/core/java/com/android/server/am/ActivityRecord.java index b5fbee617fbd..b58d0afbfd85 100644 --- a/services/core/java/com/android/server/am/ActivityRecord.java +++ b/services/core/java/com/android/server/am/ActivityRecord.java @@ -372,6 +372,10 @@ final class ActivityRecord extends ConfigurationContainer implements AppWindowCo } } + String getLifecycleDescription(String reason) { + return "packageName=" + packageName + ", state=" + state + ", reason=" + reason; + } + void dump(PrintWriter pw, String prefix) { final long now = SystemClock.uptimeMillis(); pw.print(prefix); pw.print("packageName="); pw.print(packageName); @@ -1611,12 +1615,16 @@ final class ActivityRecord extends ConfigurationContainer implements AppWindowCo // If the activity is stopped or stopping, cycle to the paused state. if (state == STOPPED || state == STOPPING) { + // Capture reason before state change + final String reason = getLifecycleDescription("makeVisibleIfNeeded"); + // An activity must be in the {@link PAUSING} state for the system to validate // the move to {@link PAUSED}. state = PAUSING; service.mLifecycleManager.scheduleTransaction(app.thread, appToken, PauseActivityItem.obtain(finishing, false /* userLeaving */, - configChangeFlags, false /* dontReport */)); + configChangeFlags, false /* dontReport */) + .setDescription(reason)); } } catch (Exception e) { // Just skip on any failure; we'll make it visible when it next restarts. diff --git a/services/core/java/com/android/server/am/ActivityStack.java b/services/core/java/com/android/server/am/ActivityStack.java index a343965ab848..dbe5b6f80b9a 100644 --- a/services/core/java/com/android/server/am/ActivityStack.java +++ b/services/core/java/com/android/server/am/ActivityStack.java @@ -2639,7 +2639,9 @@ class ActivityStack extends ConfigurationContai next.clearOptionsLocked(); mService.mLifecycleManager.scheduleTransaction(next.app.thread, next.appToken, ResumeActivityItem.obtain(next.app.repProcState, - mService.isNextTransitionForward())); + mService.isNextTransitionForward()) + .setDescription(next.getLifecycleDescription( + "resumeTopActivityInnerLocked"))); if (DEBUG_STATES) Slog.d(TAG_STATES, "resumeTopActivityLocked: Resumed " + next); @@ -3419,7 +3421,8 @@ class ActivityStack extends ConfigurationContai EventLogTags.writeAmStopActivity( r.userId, System.identityHashCode(r), r.shortComponentName); mService.mLifecycleManager.scheduleTransaction(r.app.thread, r.appToken, - StopActivityItem.obtain(r.visible, r.configChangeFlags)); + StopActivityItem.obtain(r.visible, r.configChangeFlags) + .setDescription(r.getLifecycleDescription("stopActivityLocked"))); if (shouldSleepOrShutDownActivities()) { r.setSleeping(true); } @@ -4225,7 +4228,8 @@ class ActivityStack extends ConfigurationContai try { if (DEBUG_SWITCH) Slog.i(TAG_SWITCH, "Destroying: " + r); mService.mLifecycleManager.scheduleTransaction(r.app.thread, r.appToken, - DestroyActivityItem.obtain(r.finishing, r.configChangeFlags)); + DestroyActivityItem.obtain(r.finishing, r.configChangeFlags) + .setDescription(r.getLifecycleDescription("destroyActivityLocked"))); } catch (Exception e) { // We can just ignore exceptions here... if the process // has crashed, our death notification will clean things diff --git a/services/core/java/com/android/server/am/ActivityStackSupervisor.java b/services/core/java/com/android/server/am/ActivityStackSupervisor.java index b567303b3ae5..822ad6721582 100644 --- a/services/core/java/com/android/server/am/ActivityStackSupervisor.java +++ b/services/core/java/com/android/server/am/ActivityStackSupervisor.java @@ -1422,7 +1422,8 @@ public class ActivityStackSupervisor extends ConfigurationContainer implements D // Set desired final state. final ActivityLifecycleItem lifecycleItem; if (andResume) { - lifecycleItem = ResumeActivityItem.obtain(mService.isNextTransitionForward()); + lifecycleItem = ResumeActivityItem.obtain(mService.isNextTransitionForward()) + .setDescription(r.getLifecycleDescription("realStartActivityLocked")); } else { lifecycleItem = PauseActivityItem.obtain(); }