Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 53459a70 authored by Dianne Hackborn's avatar Dianne Hackborn
Browse files

Maybe fix issue #10797796: IllegalStateException in ProcessState...

...caused runtime restart

There were some situations where the package list could be set
with process stats when it shouldn't.  Not sure if this is causing
the problem, since there is no repro.

Also some improvements to debug output -- new commands to clear
all stats, print full details of stats, and print a one-day
summary (which should match what the UI shows).

Change-Id: I9581db4059d7bb094f79f2fe06c1ccff3e1a4e74
parent 463850e0
Loading
Loading
Loading
Loading
+1 −0
Original line number Diff line number Diff line
@@ -22,5 +22,6 @@ import com.android.internal.app.ProcessStats;

interface IProcessStats {
    byte[] getCurrentStats(out List<ParcelFileDescriptor> historic);
    ParcelFileDescriptor getStatsOverTime(long minTime);
    int getCurrentMemoryState();
}
+51 −45
Original line number Diff line number Diff line
@@ -166,7 +166,7 @@ public final class ProcessStats implements Parcelable {
    static final String CSV_SEP = "\t";

    // Current version of the parcel format.
    private static final int PARCEL_VERSION = 11;
    private static final int PARCEL_VERSION = 12;
    // In-memory Parcel magic number, used to detect attempts to unmarshall bad data
    private static final int MAGIC = 0x50535453;

@@ -1076,10 +1076,8 @@ public final class ProcessStats implements Parcelable {
        return table;
    }

    private void writeCompactedLongArray(Parcel out, long[] array) {
        final int N = array.length;
        out.writeInt(N);
        for (int i=0; i<N; i++) {
    private void writeCompactedLongArray(Parcel out, long[] array, int num) {
        for (int i=0; i<num; i++) {
            long val = array[i];
            if (val < 0) {
                Slog.w(TAG, "Time val negative: " + val);
@@ -1096,16 +1094,17 @@ public final class ProcessStats implements Parcelable {
        }
    }

    private void readCompactedLongArray(Parcel in, int version, long[] array) {
    private void readCompactedLongArray(Parcel in, int version, long[] array, int num) {
        if (version <= 10) {
            in.readLongArray(array);
            return;
        }
        final int N = in.readInt();
        if (N != array.length) {
            throw new RuntimeException("bad array lengths");
        final int alen = array.length;
        if (num > alen) {
            throw new RuntimeException("bad array lengths: got " + num + " array is " + alen);
        }
        for (int i=0; i<N; i++) {
        int i;
        for (i=0; i<num; i++) {
            int val = in.readInt();
            if (val >= 0) {
                array[i] = val;
@@ -1114,6 +1113,10 @@ public final class ProcessStats implements Parcelable {
                array[i] = (((long)~val)<<32) | bottom;
            }
        }
        while (i < alen) {
            array[i] = 0;
            i++;
        }
    }

    private void writeCommonString(Parcel out, String name) {
@@ -1203,19 +1206,17 @@ public final class ProcessStats implements Parcelable {
        out.writeInt(mLongs.size());
        out.writeInt(mNextLong);
        for (int i=0; i<(mLongs.size()-1); i++) {
            writeCompactedLongArray(out, mLongs.get(i));
            long[] array = mLongs.get(i);
            writeCompactedLongArray(out, array, array.length);
        }
        long[] lastLongs = mLongs.get(mLongs.size() - 1);
        for (int i=0; i<mNextLong; i++) {
            out.writeLong(lastLongs[i]);
            if (DEBUG) Slog.d(TAG, "Writing last long #" + i + ": " + lastLongs[i]);
        }
        writeCompactedLongArray(out, lastLongs, mNextLong);

        if (mMemFactor != STATE_NOTHING) {
            mMemFactorDurations[mMemFactor] += now - mStartTime;
            mStartTime = now;
        }
        writeCompactedLongArray(out, mMemFactorDurations);
        writeCompactedLongArray(out, mMemFactorDurations, mMemFactorDurations.length);

        out.writeInt(NPROC);
        for (int ip=0; ip<NPROC; ip++) {
@@ -1276,23 +1277,25 @@ public final class ProcessStats implements Parcelable {
        return true;
    }

    static byte[] readFully(InputStream stream) throws IOException {
    static byte[] readFully(InputStream stream, int[] outLen) throws IOException {
        int pos = 0;
        int avail = stream.available();
        byte[] data = new byte[avail];
        final int initialAvail = stream.available();
        byte[] data = new byte[initialAvail > 0 ? (initialAvail+1) : 16384];
        while (true) {
            int amt = stream.read(data, pos, data.length-pos);
            //Log.i("foo", "Read " + amt + " bytes at " + pos
            //        + " of avail " + data.length);
            if (amt <= 0) {
                //Log.i("foo", "**** FINISHED READING: pos=" + pos
                //        + " len=" + data.length);
            if (DEBUG) Slog.i("foo", "Read " + amt + " bytes at " + pos
                    + " of avail " + data.length);
            if (amt < 0) {
                if (DEBUG) Slog.i("foo", "**** FINISHED READING: pos=" + pos
                        + " len=" + data.length);
                outLen[0] = pos;
                return data;
            }
            pos += amt;
            avail = stream.available();
            if (avail > data.length-pos) {
                byte[] newData = new byte[pos+avail];
            if (pos >= data.length) {
                byte[] newData = new byte[pos+16384];
                if (DEBUG) Slog.i(TAG, "Copying " + pos + " bytes to new array len "
                        + newData.length);
                System.arraycopy(data, 0, newData, 0, pos);
                data = newData;
            }
@@ -1301,9 +1304,10 @@ public final class ProcessStats implements Parcelable {

    public void read(InputStream stream) {
        try {
            byte[] raw = readFully(stream);
            int[] len = new int[1];
            byte[] raw = readFully(stream, len);
            Parcel in = Parcel.obtain();
            in.unmarshall(raw, 0, raw.length);
            in.unmarshall(raw, 0, len[0]);
            in.setDataPosition(0);
            stream.close();

@@ -1358,17 +1362,14 @@ public final class ProcessStats implements Parcelable {
            while (i >= mLongs.size()) {
                mLongs.add(new long[LONGS_SIZE]);
            }
            readCompactedLongArray(in, version, mLongs.get(i));
            readCompactedLongArray(in, version, mLongs.get(i), LONGS_SIZE);
        }
        long[] longs = new long[LONGS_SIZE];
        mNextLong = NEXTLONG;
        for (int i=0; i<NEXTLONG; i++) {
            longs[i] = in.readLong();
            if (DEBUG) Slog.d(TAG, "Reading last long #" + i + ": " + longs[i]);
        }
        readCompactedLongArray(in, version, longs, NEXTLONG);
        mLongs.add(longs);

        readCompactedLongArray(in, version, mMemFactorDurations);
        readCompactedLongArray(in, version, mMemFactorDurations, mMemFactorDurations.length);

        int NPROC = in.readInt();
        if (NPROC < 0) {
@@ -1669,7 +1670,8 @@ public final class ProcessStats implements Parcelable {
        return ss;
    }

    public void dumpLocked(PrintWriter pw, String reqPackage, long now, boolean dumpAll) {
    public void dumpLocked(PrintWriter pw, String reqPackage, long now, boolean dumpSummary,
            boolean dumpAll) {
        long totalTime = dumpSingleTime(null, null, mMemFactorDurations, mMemFactor,
                mStartTime, now);
        ArrayMap<String, SparseArray<PackageState>> pkgMap = mPackages.getMap();
@@ -1693,7 +1695,7 @@ public final class ProcessStats implements Parcelable {
                    pw.print("  * "); pw.print(pkgName); pw.print(" / ");
                            UserHandle.formatUid(pw, uid); pw.println(":");
                }
                if (dumpAll) {
                if (!dumpSummary || dumpAll) {
                    for (int iproc=0; iproc<NPROCS; iproc++) {
                        ProcessState proc = pkgState.mProcesses.valueAt(iproc);
                        pw.print("      Process ");
@@ -1730,16 +1732,16 @@ public final class ProcessStats implements Parcelable {
                    ServiceState svc = pkgState.mServices.valueAt(isvc);
                    dumpServiceStats(pw, "        ", "          ", "    ", "Running", svc,
                            svc.mRunCount, ServiceState.SERVICE_RUN, svc.mRunState,
                            svc.mRunStartTime, now, totalTime, dumpAll);
                            svc.mRunStartTime, now, totalTime, !dumpSummary || dumpAll);
                    dumpServiceStats(pw, "        ", "          ", "    ", "Started", svc,
                            svc.mStartedCount, ServiceState.SERVICE_STARTED, svc.mStartedState,
                            svc.mStartedStartTime, now, totalTime, dumpAll);
                            svc.mStartedStartTime, now, totalTime, !dumpSummary || dumpAll);
                    dumpServiceStats(pw, "        ", "          ", "      ", "Bound", svc,
                            svc.mBoundCount, ServiceState.SERVICE_BOUND, svc.mBoundState,
                            svc.mBoundStartTime, now, totalTime, dumpAll);
                            svc.mBoundStartTime, now, totalTime, !dumpSummary || dumpAll);
                    dumpServiceStats(pw, "        ", "          ", "  ", "Executing", svc,
                            svc.mExecCount, ServiceState.SERVICE_EXEC, svc.mExecState,
                            svc.mExecStartTime, now, totalTime, dumpAll);
                            svc.mExecStartTime, now, totalTime, !dumpSummary || dumpAll);
                    if (dumpAll) {
                        pw.print("        mActive="); pw.println(svc.mActive);
                    }
@@ -1783,8 +1785,12 @@ public final class ProcessStats implements Parcelable {
            }

            pw.println();
            if (dumpSummary) {
                pw.println("Summary:");
                dumpSummaryLocked(pw, reqPackage, now);
            } else {
                dumpTotalsLocked(pw, now);
            }
        } else {
            pw.println();
            dumpTotalsLocked(pw, now);
@@ -2514,7 +2520,7 @@ public final class ProcessStats implements Parcelable {
        private ProcessState pullFixedProc(ArrayMap<String, ProcessState> pkgList, int index) {
            ProcessState proc = pkgList.valueAt(index);
            if (mDead && proc.mCommonProcess != proc) {
                // Somehow we try to continue to use a process state that is dead, because
                // Somehow we are contining to use a process state that is dead, because
                // it was not being told it was active during the last commit.  We can recover
                // from this by generating a fresh new state, but this is bad because we
                // are losing whatever data we had in the old process state.
+14 −6
Original line number Diff line number Diff line
@@ -407,9 +407,9 @@ final class ProcessRecord {
    }

    public void makeInactive(ProcessStatsService tracker) {
        if (thread != null) {
        thread = null;
        final ProcessStats.ProcessState origBase = baseProcessTracker;
        if (origBase != null) {
            if (origBase != null) {
                origBase.setState(ProcessStats.STATE_NOTHING,
                        tracker.getMemFactorLocked(), SystemClock.uptimeMillis(), pkgList);
@@ -567,8 +567,16 @@ final class ProcessRecord {
     */
    public boolean addPackage(String pkg, ProcessStatsService tracker) {
        if (!pkgList.containsKey(pkg)) {
            pkgList.put(pkg, baseProcessTracker != null
                    ? tracker.getProcessStateLocked(pkg, info.uid, processName) : null);
            if (baseProcessTracker != null) {
                ProcessStats.ProcessState state = tracker.getProcessStateLocked(
                        pkg, info.uid, processName);
                pkgList.put(pkg, state);
                if (state != baseProcessTracker) {
                    state.makeActive();
                }
            } else {
                pkgList.put(pkg, null);
            }
            return true;
        }
        return false;
@@ -610,7 +618,7 @@ final class ProcessRecord {
                ProcessStats.ProcessState ps = tracker.getProcessStateLocked(
                        info.packageName, info.uid, processName);
                pkgList.put(info.packageName, ps);
                if (thread != null && ps != baseProcessTracker) {
                if (ps != baseProcessTracker) {
                    ps.makeActive();
                }
            }
+134 −10
Original line number Diff line number Diff line
@@ -30,6 +30,7 @@ import android.util.ArrayMap;
import android.util.AtomicFile;
import android.util.Slog;
import android.util.SparseArray;
import android.util.TimeUtils;
import com.android.internal.app.IProcessStats;
import com.android.internal.app.ProcessStats;
import com.android.internal.os.BackgroundThread;
@@ -39,6 +40,7 @@ import java.io.FileDescriptor;
import java.io.FileInputStream;
import java.io.FileOutputStream;
import java.io.IOException;
import java.io.InputStream;
import java.io.PrintWriter;
import java.util.ArrayList;
import java.util.Collections;
@@ -313,7 +315,8 @@ public final class ProcessStatsService extends IProcessStats.Stub {
        return true;
    }

    private ArrayList<String> getCommittedFiles(int minNum, boolean inclAll) {
    private ArrayList<String> getCommittedFiles(int minNum, boolean inclCurrent,
            boolean inclCheckedIn) {
        File[] files = mBaseDir.listFiles();
        if (files == null || files.length <= minNum) {
            return null;
@@ -325,11 +328,11 @@ public final class ProcessStatsService extends IProcessStats.Stub {
            File file = files[i];
            String fileStr = file.getPath();
            if (DEBUG) Slog.d(TAG, "Collecting: " + fileStr);
            if (!inclAll && fileStr.endsWith(STATE_FILE_CHECKIN_SUFFIX)) {
            if (!inclCheckedIn && fileStr.endsWith(STATE_FILE_CHECKIN_SUFFIX)) {
                if (DEBUG) Slog.d(TAG, "Skipping: already checked in");
                continue;
            }
            if (fileStr.equals(currentFile)) {
            if (!inclCurrent && fileStr.equals(currentFile)) {
                if (DEBUG) Slog.d(TAG, "Skipping: current stats");
                continue;
            }
@@ -340,7 +343,7 @@ public final class ProcessStatsService extends IProcessStats.Stub {
    }

    public void trimHistoricStatesWriteLocked() {
        ArrayList<String> filesArray = getCommittedFiles(MAX_HISTORIC_STATES, true);
        ArrayList<String> filesArray = getCommittedFiles(MAX_HISTORIC_STATES, false, true);
        if (filesArray == null) {
            return;
        }
@@ -409,6 +412,8 @@ public final class ProcessStatsService extends IProcessStats.Stub {
    }

    public byte[] getCurrentStats(List<ParcelFileDescriptor> historic) {
        mAm.mContext.enforceCallingOrSelfPermission(
                android.Manifest.permission.PACKAGE_USAGE_STATS, null);
        Parcel current = Parcel.obtain();
        mWriteLock.lock();
        try {
@@ -417,7 +422,7 @@ public final class ProcessStatsService extends IProcessStats.Stub {
                mProcessStats.writeToParcel(current, 0);
            }
            if (historic != null) {
                ArrayList<String> files = getCommittedFiles(0, true);
                ArrayList<String> files = getCommittedFiles(0, false, true);
                if (files != null) {
                    for (int i=files.size()-1; i>=0; i--) {
                        try {
@@ -436,6 +441,76 @@ public final class ProcessStatsService extends IProcessStats.Stub {
        return current.marshall();
    }

    public ParcelFileDescriptor getStatsOverTime(long minTime) {
        mAm.mContext.enforceCallingOrSelfPermission(
                android.Manifest.permission.PACKAGE_USAGE_STATS, null);
        mWriteLock.lock();
        try {
            Parcel current = Parcel.obtain();
            long curTime;
            synchronized (mAm) {
                mProcessStats.mTimePeriodEndRealtime = SystemClock.elapsedRealtime();
                mProcessStats.writeToParcel(current, 0);
                curTime = mProcessStats.mTimePeriodEndRealtime
                        - mProcessStats.mTimePeriodStartRealtime;
            }
            if (curTime < minTime) {
                // Need to add in older stats to reach desired time.
                ArrayList<String> files = getCommittedFiles(0, false, true);
                if (files.size() > 0) {
                    current.setDataPosition(0);
                    ProcessStats stats = ProcessStats.CREATOR.createFromParcel(current);
                    current.recycle();
                    int i = 0;
                    while (i < files.size() && (stats.mTimePeriodEndRealtime
                            - stats.mTimePeriodStartRealtime) < minTime) {
                        AtomicFile file = new AtomicFile(new File(files.get(i)));
                        i++;
                        ProcessStats moreStats = new ProcessStats(false);
                        readLocked(moreStats, file);
                        if (moreStats.mReadError == null) {
                            stats.add(moreStats);
                            StringBuilder sb = new StringBuilder();
                            sb.append("Added stats: ");
                            sb.append(moreStats.mTimePeriodStartClockStr);
                            sb.append(", over ");
                            TimeUtils.formatDuration(moreStats.mTimePeriodEndRealtime
                                    - moreStats.mTimePeriodStartRealtime, sb);
                            Slog.i(TAG, sb.toString());
                        } else {
                            Slog.w(TAG, "Failure reading " + files.get(i) + "; "
                                    + moreStats.mReadError);
                            continue;
                        }
                    }
                    current = Parcel.obtain();
                    stats.writeToParcel(current, 0);
                }
            }
            final byte[] outData = current.marshall();
            current.recycle();
            final ParcelFileDescriptor[] fds = ParcelFileDescriptor.createPipe();
            Thread thr = new Thread("ProcessStats pipe output") {
                public void run() {
                    FileOutputStream fout = new ParcelFileDescriptor.AutoCloseOutputStream(fds[1]);
                    try {
                        fout.write(outData);
                        fout.close();
                    } catch (IOException e) {
                        Slog.w(TAG, "Failure writing pipe", e);
                    }
                }
            };
            thr.start();
            return fds[0];
        } catch (IOException e) {
            Slog.w(TAG, "Failed building output pipe", e);
        } finally {
            mWriteLock.unlock();
        }
        return null;
    }

    public int getCurrentMemoryState() {
        synchronized (mAm) {
            return mLastMemOnlyState;
@@ -445,7 +520,8 @@ public final class ProcessStatsService extends IProcessStats.Stub {
    static private void dumpHelp(PrintWriter pw) {
        pw.println("Process stats (procstats) dump options:");
        pw.println("    [--checkin|-c|--csv] [--csv-screen] [--csv-proc] [--csv-mem]");
        pw.println("    [--details] [--current] [--commit] [--reset] [--write] [-h] [<package.name>]");
        pw.println("    [--details] [--full-details] [--current] [--one-day]");
        pw.println("    [--commit] [--reset] [--clear] [--write] [-h] [<package.name>]");
        pw.println("  --checkin: perform a checkin: print and delete old committed states.");
        pw.println("  --c: print only state in checkin format.");
        pw.println("  --csv: output data suitable for putting in a spreadsheet.");
@@ -454,9 +530,12 @@ public final class ProcessStatsService extends IProcessStats.Stub {
        pw.println("  --csv-proc: pers, top, fore, vis, precept, backup,");
        pw.println("    service, home, prev, cached");
        pw.println("  --details: dump all execution details, not just summary.");
        pw.println("  --full-details: dump only detail information, for all saved state.");
        pw.println("  --current: only dump current state.");
        pw.println("  --one-day: dump stats aggregated across about one day.");
        pw.println("  --commit: commit current stats to disk and reset to start new stats.");
        pw.println("  --reset: reset current stats, without committing.");
        pw.println("  --clear: clear all stats; does both --reset and deletes old stats.");
        pw.println("  --write: write current in-memory stats to disk.");
        pw.println("  --read: replace current stats with last-written stats.");
        pw.println("  -a: print everything.");
@@ -481,7 +560,9 @@ public final class ProcessStatsService extends IProcessStats.Stub {
        boolean isCsv = false;
        boolean currentOnly = false;
        boolean dumpDetails = false;
        boolean dumpFullDetails = false;
        boolean dumpAll = false;
        boolean oneDay = false;
        String reqPackage = null;
        boolean csvSepScreenStats = false;
        int[] csvScreenStats = new int[] { ProcessStats.ADJ_SCREEN_OFF, ProcessStats.ADJ_SCREEN_ON};
@@ -549,6 +630,10 @@ public final class ProcessStatsService extends IProcessStats.Stub {
                    csvSepProcStats = sep[0];
                } else if ("--details".equals(arg)) {
                    dumpDetails = true;
                } else if ("--full-details".equals(arg)) {
                    dumpFullDetails = true;
                } else if ("--one-day".equals(arg)) {
                    oneDay = true;
                } else if ("--current".equals(arg)) {
                    currentOnly = true;
                } else if ("--commit".equals(arg)) {
@@ -564,6 +649,18 @@ public final class ProcessStatsService extends IProcessStats.Stub {
                        pw.println("Process stats reset.");
                    }
                    return;
                } else if ("--clear".equals(arg)) {
                    synchronized (mAm) {
                        mProcessStats.resetSafely();
                        ArrayList<String> files = getCommittedFiles(0, true, true);
                        if (files != null) {
                            for (int fi=0; fi<files.size(); fi++) {
                                (new File(files.get(fi))).delete();
                            }
                        }
                        pw.println("All process stats cleared.");
                    }
                    return;
                } else if ("--write".equals(arg)) {
                    synchronized (mAm) {
                        writeStateSyncLocked();
@@ -653,13 +750,36 @@ public final class ProcessStatsService extends IProcessStats.Stub {
                */
            }
            return;
        } else if (oneDay) {
            ParcelFileDescriptor pfd = getStatsOverTime(24*60*60*1000);
            if (pfd == null) {
                pw.println("Unable to build stats!");
                return;
            }
            ProcessStats stats = new ProcessStats(false);
            InputStream stream = new ParcelFileDescriptor.AutoCloseInputStream(pfd);
            stats.read(stream);
            if (stats.mReadError != null) {
                pw.print("Failure reading: "); pw.println(stats.mReadError);
                return;
            }
            if (isCompact) {
                stats.dumpCheckinLocked(pw, reqPackage);
            } else {
                if (dumpDetails || dumpFullDetails) {
                    stats.dumpLocked(pw, reqPackage, now, !dumpFullDetails, dumpAll);
                } else {
                    stats.dumpSummaryLocked(pw, reqPackage, now);
                }
            }
            return;
        }

        boolean sepNeeded = false;
        if (!currentOnly || isCheckin) {
            mWriteLock.lock();
            try {
                ArrayList<String> files = getCommittedFiles(0, !isCheckin);
                ArrayList<String> files = getCommittedFiles(0, false, !isCheckin);
                if (files != null) {
                    for (int i=0; i<files.size(); i++) {
                        if (DEBUG) Slog.d(TAG, "Retrieving state: " + files.get(i));
@@ -693,8 +813,12 @@ public final class ProcessStatsService extends IProcessStats.Stub {
                                // Don't really need to lock because we uniquely own this object.
                                // Always dump summary here, dumping all details is just too
                                // much crud.
                                if (dumpFullDetails) {
                                    mProcessStats.dumpLocked(pw, reqPackage, now, false, false);
                                } else {
                                    processStats.dumpSummaryLocked(pw, reqPackage, now);
                                }
                            }
                            if (isCheckin) {
                                // Rename file suffix to mark that it has checked in.
                                file.getBaseFile().renameTo(new File(
@@ -719,8 +843,8 @@ public final class ProcessStatsService extends IProcessStats.Stub {
                        pw.println();
                        pw.println("CURRENT STATS:");
                    }
                    if (dumpDetails) {
                        mProcessStats.dumpLocked(pw, reqPackage, now, dumpAll);
                    if (dumpDetails || dumpFullDetails) {
                        mProcessStats.dumpLocked(pw, reqPackage, now, !dumpFullDetails, dumpAll);
                        if (dumpAll) {
                            pw.print("  mFile="); pw.println(mFile.getBaseFile());
                        }