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

Commit 15e7a256 authored Jun 08, 2017 by Makoto Onuki

Enhance recent sync log in dumpsys content

- Add "Per Adapter History" section that has recent activities per adapter. Example:
  mxxxx@gmail.com/com.google u0 [com.android.calendar]
    2017-06-19 14:19:07 success Source=LOCAL Elapsed=0s Reason=10014 Extras=[upload=true ]
    2017-06-19 14:19:06 success Source=SERVER Elapsed=16s Reason=10014 Extras=[feed=#contacts@group.v.calendar.google.com ]
  mxxxx@gmail.com/com.google u0 [com.android.chrome]
    2017-06-19 13:26:25 canceled Source=POLL Elapsed=0s Reason=AccountsUpdated Extras=[initialize=true ]
  mxxxx@gmail.com/com.google u0 [com.android.contacts]

- Improve pending/periodic syncs with better formatting, and sort them in a sane order.

Bug: 38498544
Bug: 62391411
Test: manual test with "dumpsys content"
Change-Id: I947a9255230f27a7f438d648da324787fdf16f55

parent f69d450b

core/java/android/content/SyncStatusInfo.java

+51 −5

Original line number	Diff line number	Diff line
		@@ -24,7 +24,11 @@ import java.util.ArrayList;

		/** @hide */
		public class SyncStatusInfo implements Parcelable {
		static final int VERSION = 2;
		private static final String TAG = "Sync";

		static final int VERSION = 3;

		private static final int MAX_EVENT_COUNT = 10;

		public final int authorityId;
		public long totalElapsedTime;
		@@ -47,7 +51,8 @@ public class SyncStatusInfo implements Parcelable {
		// no race conditions when accessing this list
		private ArrayList<Long> periodicSyncTimes;

		private static final String TAG = "Sync";
		private final ArrayList<Long> mLastEventTimes = new ArrayList<>();
		private final ArrayList<String> mLastEvents = new ArrayList<>();

		public SyncStatusInfo(int authorityId) {
		this.authorityId = authorityId;
		@@ -92,6 +97,11 @@ public class SyncStatusInfo implements Parcelable {
		} else {
		parcel.writeInt(-1);
		}
		parcel.writeInt(mLastEventTimes.size());
		for (int i = 0; i < mLastEventTimes.size(); i++) {
		parcel.writeLong(mLastEventTimes.get(i));
		parcel.writeString(mLastEvents.get(i));
		}
		}

		public SyncStatusInfo(Parcel parcel) {
		@@ -117,15 +127,24 @@ public class SyncStatusInfo implements Parcelable {
		if (version == 1) {
		periodicSyncTimes = null;
		} else {
		int N = parcel.readInt();
		if (N < 0) {
		final int count = parcel.readInt();
		if (count < 0) {
		periodicSyncTimes = null;
		} else {
		periodicSyncTimes = new ArrayList<Long>();
		for (int i=0; i<N; i++) {
		for (int i = 0; i < count; i++) {
		periodicSyncTimes.add(parcel.readLong());
		}
		}
		if (version >= 3) {
		mLastEventTimes.clear();
		mLastEvents.clear();
		final int nEvents = parcel.readInt();
		for (int i = 0; i < nEvents; i++) {
		mLastEventTimes.add(parcel.readLong());
		mLastEvents.add(parcel.readString());
		}
		}
		}
		}

		@@ -149,6 +168,8 @@ public class SyncStatusInfo implements Parcelable {
		if (other.periodicSyncTimes != null) {
		periodicSyncTimes = new ArrayList<Long>(other.periodicSyncTimes);
		}
		mLastEventTimes.addAll(other.mLastEventTimes);
		mLastEvents.addAll(other.mLastEvents);
		}

		public void setPeriodicSyncTime(int index, long when) {
		@@ -172,6 +193,31 @@ public class SyncStatusInfo implements Parcelable {
		}
		}

		/** */
		public void addEvent(String message) {
		if (mLastEventTimes.size() >= MAX_EVENT_COUNT) {
		mLastEventTimes.remove(MAX_EVENT_COUNT - 1);
		mLastEvents.remove(MAX_EVENT_COUNT - 1);
		}
		mLastEventTimes.add(0, System.currentTimeMillis());
		mLastEvents.add(0, message);
		}

		/** */
		public int getEventCount() {
		return mLastEventTimes.size();
		}

		/** */
		public long getEventTime(int i) {
		return mLastEventTimes.get(i);
		}

		/** */
		public String getEvent(int i) {
		return mLastEvents.get(i);
		}

		public static final Creator<SyncStatusInfo> CREATOR = new Creator<SyncStatusInfo>() {
		public SyncStatusInfo createFromParcel(Parcel in) {
		return new SyncStatusInfo(in);

services/core/java/com/android/server/content/SyncManager.java

+167 −22

Original line number	Diff line number	Diff line
		@@ -74,7 +74,6 @@ import android.os.UserHandle;
		import android.os.UserManager;
		import android.os.WorkSource;
		import android.provider.Settings;
		import android.text.format.DateUtils;
		import android.text.format.Time;
		import android.util.EventLog;
		import android.util.Log;
		@@ -113,6 +112,7 @@ import java.util.Map;
		import java.util.Objects;
		import java.util.Random;
		import java.util.Set;
		import java.util.function.Predicate;

		/**
		* Implementation details:
		@@ -1761,10 +1761,7 @@ public class SyncManager {

		protected void dump(FileDescriptor fd, PrintWriter pw) {
		final IndentingPrintWriter ipw = new IndentingPrintWriter(pw, " ");
		dumpPendingSyncs(pw);
		dumpPeriodicSyncs(pw);
		dumpSyncState(ipw);
		dumpSyncHistory(ipw);
		dumpSyncAdapters(ipw);
		}

		@@ -1774,9 +1771,58 @@ public class SyncManager {
		return tobj.format("%Y-%m-%d %H:%M:%S");
		}

		private final static Comparator<SyncOperation> sOpDumpComparator = (op1, op2) -> {
		int res = Integer.compare(op1.target.userId, op2.target.userId);
		if (res != 0) return res;

		final Comparator<String> stringComparator = String.CASE_INSENSITIVE_ORDER;

		res = stringComparator.compare(op1.target.account.type, op2.target.account.type);
		if (res != 0) return res;

		res = stringComparator.compare(op1.target.account.name, op2.target.account.name);
		if (res != 0) return res;

		res = stringComparator.compare(op1.target.provider, op2.target.provider);
		if (res != 0) return res;

		res = Integer.compare(op1.reason, op2.reason);
		if (res != 0) return res;

		res = Long.compare(op1.periodMillis, op2.periodMillis);
		if (res != 0) return res;

		res = Long.compare(op1.expectedRuntime, op2.expectedRuntime);
		if (res != 0) return res;

		res = Long.compare(op1.jobId, op2.jobId);
		if (res != 0) return res;

		return 0;
		};

		private final static Comparator<SyncOperation> sOpRuntimeComparator = (op1, op2) -> {
		int res = Long.compare(op1.expectedRuntime, op2.expectedRuntime);
		if (res != 0) return res;

		return sOpDumpComparator.compare(op1, op2);
		};

		private static <T> int countIf(Collection<T> col, Predicate<T> p) {
		int ret = 0;
		for (T item : col) {
		if (p.test(item)) ret++;
		}
		return ret;
		}

		protected void dumpPendingSyncs(PrintWriter pw) {
		pw.println("Pending Syncs:");
		List<SyncOperation> pendingSyncs = getAllPendingSyncs();

		pw.print("Pending Syncs: ");
		pw.println(countIf(pendingSyncs, op -> !op.isPeriodic));

		Collections.sort(pendingSyncs, sOpRuntimeComparator);
		int count = 0;
		for (SyncOperation op: pendingSyncs) {
		if (!op.isPeriodic) {
		@@ -1784,13 +1830,16 @@ public class SyncManager {
		count++;
		}
		}
		pw.println("Total: " + count);
		pw.println();
		}

		protected void dumpPeriodicSyncs(PrintWriter pw) {
		pw.println("Periodic Syncs:");
		List<SyncOperation> pendingSyncs = getAllPendingSyncs();

		pw.print("Periodic Syncs: ");
		pw.println(countIf(pendingSyncs, op -> op.isPeriodic));

		Collections.sort(pendingSyncs, sOpDumpComparator);
		int count = 0;
		for (SyncOperation op: pendingSyncs) {
		if (op.isPeriodic) {
		@@ -1798,11 +1847,62 @@ public class SyncManager {
		count++;
		}
		}
		pw.println("Total: " + count);
		pw.println();
		}

		/**
		* Similar to {@link android.util.TimeUtils#formatDuration}, but it's more suitable and concise
		* for the sync manager dumpsys. (Don't add the leading + sign, don't show milliseconds.)
		*/
		public static StringBuilder formatDurationHMS(StringBuilder sb, long duration) {
		duration /= 1000;
		if (duration < 0) {
		sb.append('-');
		duration = -duration;
		}
		final long seconds = duration % 60;
		duration /= 60;

		final long minutes = duration % 60;
		duration /= 60;

		final long hours = duration % 24;
		duration /= 24;

		final long days = duration;

		boolean print = false;
		if (days > 0) {
		sb.append(days);
		sb.append('d');
		print = true;
		}
		print = printTwoDigitNumber(sb, hours, 'h', print);
		print = printTwoDigitNumber(sb, minutes, 'm', print);
		print = printTwoDigitNumber(sb, seconds, 's', print);
		if (!print) {
		sb.append("0s");
		}

		return sb;
		}

		private static boolean printTwoDigitNumber(StringBuilder sb, long value, char unit,
		boolean always) {
		if (!always && (value == 0)) {
		return false;
		}
		if (always && (value < 10)) {
		sb.append('0');
		}
		sb.append(value);
		sb.append(unit);
		return true;
		}

		protected void dumpSyncState(PrintWriter pw) {
		final StringBuilder sb = new StringBuilder();

		pw.print("data connected: "); pw.println(mDataConnectionIsConnected);
		pw.print("auto sync: ");
		List<UserInfo> users = getAllUsers();
		@@ -1828,13 +1928,16 @@ public class SyncManager {
		final long now = SystemClock.elapsedRealtime();
		pw.print("now: "); pw.print(now);
		pw.println(" (" + formatTime(System.currentTimeMillis()) + ")");
		pw.println(" (HH:MM:SS)");
		pw.print("uptime: "); pw.print(DateUtils.formatElapsedTime(now / 1000));
		pw.println(" (HH:MM:SS)");

		sb.setLength(0);
		pw.print("uptime: "); pw.print(formatDurationHMS(sb, now));
		pw.println();
		pw.print("time spent syncing: ");
		pw.print(DateUtils.formatElapsedTime(
		mSyncHandler.mSyncTimeTracker.timeSpentSyncing() / 1000));
		pw.print(" (HH:MM:SS), sync ");

		sb.setLength(0);
		pw.print(formatDurationHMS(sb,
		mSyncHandler.mSyncTimeTracker.timeSpentSyncing()));
		pw.print(", sync ");
		pw.print(mSyncHandler.mSyncTimeTracker.mLastWasSyncing ? "" : "not ");
		pw.println("in progress");

		@@ -1842,17 +1945,24 @@ public class SyncManager {
		pw.println("Active Syncs: " + mActiveSyncContexts.size());
		final PackageManager pm = mContext.getPackageManager();
		for (SyncManager.ActiveSyncContext activeSyncContext : mActiveSyncContexts) {
		final long durationInSeconds = (now - activeSyncContext.mStartTime) / 1000;
		final long durationInSeconds = (now - activeSyncContext.mStartTime);
		pw.print(" ");
		pw.print(DateUtils.formatElapsedTime(durationInSeconds));
		sb.setLength(0);
		pw.print(formatDurationHMS(sb, durationInSeconds));
		pw.print(" - ");
		pw.print(activeSyncContext.mSyncOperation.dump(pm, false));
		pw.println();
		}
		pw.println();

		dumpPendingSyncs(pw);
		dumpPeriodicSyncs(pw);

		// Join the installed sync adapter with the accounts list and emit for everything.
		pw.println();
		pw.println("Sync Status");

		final ArrayList<Pair<EndPoint, SyncStatusInfo>> statuses = new ArrayList<>();

		for (AccountAndUser account : accounts) {
		pw.printf("Account %s u%d %s\n",
		account.account.name, account.userId, account.account.type);
		@@ -1872,7 +1982,7 @@ public class SyncManager {
		"Tot", // 9
		"Time", // 10
		"Last Sync", // 11
		"Etc" // 12
		"Backoff" // 12
		);

		final List<RegisteredServicesCache.ServiceInfo<SyncAdapterType>> sorted =
		@@ -1899,11 +2009,14 @@ public class SyncManager {
		account.userId));
		SyncStorageEngine.AuthorityInfo settings = syncAuthoritySyncStatus.first;
		SyncStatusInfo status = syncAuthoritySyncStatus.second;
		statuses.add(Pair.create(settings.target, status));
		String authority = settings.target.provider;
		if (authority.length() > 50) {
		authority = authority.substring(authority.length() - 50);
		}
		table.set(row, 0, authority, settings.syncable, settings.enabled);

		sb.setLength(0);
		table.set(row, 4,
		status.numSourceLocal,
		status.numSourcePoll,
		@@ -1911,7 +2024,7 @@ public class SyncManager {
		status.numSourceServer,
		status.numSourceUser,
		status.numSyncs,
		DateUtils.formatElapsedTime(status.totalElapsedTime / 1000));
		formatDurationHMS(sb, status.totalElapsedTime));

		int row1 = row;
		if (settings.delayUntil > now) {
		@@ -1938,6 +2051,34 @@ public class SyncManager {
		}
		table.writeTo(pw);
		}

		dumpSyncHistory(pw);

		pw.println();
		pw.println("Per Adapter History");

		for (int i = 0; i < statuses.size(); i++) {
		final Pair<EndPoint, SyncStatusInfo> event = statuses.get(i);

		pw.print(" ");
		pw.print(event.first.account.name);
		pw.print('/');
		pw.print(event.first.account.type);
		pw.print(" u");
		pw.print(event.first.userId);
		pw.print(" [");
		pw.print(event.first.provider);
		pw.print("]");
		pw.println();

		for (int j = 0; j < event.second.getEventCount(); j++) {
		pw.print(" ");
		pw.print(formatTime(event.second.getEventTime(j)));
		pw.print(' ');
		pw.print(event.second.getEvent(j));
		pw.println();
		}
		}
		}

		private void dumpTimeSec(PrintWriter pw, long time) {
		@@ -3403,7 +3544,7 @@ public class SyncManager {
		}

		static class PrintTable {
		private ArrayList<Object[]> mTable = Lists.newArrayList();
		private ArrayList<String[]> mTable = Lists.newArrayList();
		private final int mCols;

		PrintTable(int cols) {
		@@ -3416,13 +3557,17 @@ public class SyncManager {
		" columns. can't set " + values.length + " at column " + col);
		}
		for (int i = mTable.size(); i <= row; i++) {
		final Object[] list = new Object[mCols];
		final String[] list = new String[mCols];
		mTable.add(list);
		for (int j = 0; j < mCols; j++) {
		list[j] = "";
		}
		}
		System.arraycopy(values, 0, mTable.get(row), col, values.length);
		final String[] rowArray = mTable.get(row);
		for (int i = 0; i < values.length; i++) {
		final Object value = values[i];
		rowArray[col + i] = (value == null) ? "" : value.toString();
		}
		}

		void writeTo(PrintWriter out) {

services/core/java/com/android/server/content/SyncOperation.java

+31 −21

Original line number	Diff line number	Diff line
		@@ -18,10 +18,11 @@ package com.android.server.content;

		import android.accounts.Account;
		import android.app.job.JobInfo;
		import android.content.pm.PackageManager;
		import android.content.ContentResolver;
		import android.content.pm.PackageManager;
		import android.os.Bundle;
		import android.os.PersistableBundle;
		import android.os.SystemClock;
		import android.os.UserHandle;
		import android.util.Slog;

		@@ -350,38 +351,47 @@ public class SyncOperation {
		return dump(null, true);
		}

		String dump(PackageManager pm, boolean useOneLine) {
		String dump(PackageManager pm, boolean shorter) {
		StringBuilder sb = new StringBuilder();
		sb.append("JobId: ").append(jobId)
		.append(", ")
		sb.append("JobId=").append(jobId)
		.append(" ")
		.append(target.account.name)
		.append(" u")
		.append(target.userId).append(" (")
		.append("/")
		.append(target.account.type)
		.append(")")
		.append(", ")
		.append(" u")
		.append(target.userId)
		.append(" [")
		.append(target.provider)
		.append(", ");
		.append("] ");
		sb.append(SyncStorageEngine.SOURCES[syncSource]);
		if (expectedRuntime != 0) {
		sb.append(" ExpectedIn=");
		SyncManager.formatDurationHMS(sb,
		(expectedRuntime - SystemClock.elapsedRealtime()));
		}
		if (extras.getBoolean(ContentResolver.SYNC_EXTRAS_EXPEDITED, false)) {
		sb.append(", EXPEDITED");
		sb.append(" EXPEDITED");
		}
		sb.append(", reason: ");
		sb.append(" Reason=");
		sb.append(reasonToString(pm, reason));
		if (isPeriodic) {
		sb.append(", period: " + periodMillis).append(", flexMillis: " + flexMillis);
		}
		if (!useOneLine) {
		sb.append("\n ");
		sb.append("owningUid=");
		sb.append(" (period=");
		SyncManager.formatDurationHMS(sb, periodMillis);
		sb.append(" flex=");
		SyncManager.formatDurationHMS(sb, flexMillis);
		sb.append(")");
		}
		if (!shorter) {
		sb.append(" Owner={");
		UserHandle.formatUid(sb, owningUid);
		sb.append(" owningPackage=");
		sb.append(" ");
		sb.append(owningPackage);
		}
		if (!useOneLine && !extras.keySet().isEmpty()) {
		sb.append("\n ");
		sb.append("}");
		if (!extras.keySet().isEmpty()) {
		sb.append(" ");
		extrasToStringBuilder(extras, sb);
		}
		}
		return sb.toString();
		}

		@@ -434,7 +444,7 @@ public class SyncOperation {
		return extras.getBoolean(ContentResolver.SYNC_EXTRAS_IGNORE_SETTINGS, false);
		}

		private static void extrasToStringBuilder(Bundle bundle, StringBuilder sb) {
		static void extrasToStringBuilder(Bundle bundle, StringBuilder sb) {
		sb.append("[");
		for (String key : bundle.keySet()) {
		sb.append(key).append("=").append(bundle.get(key)).append(" ");

services/core/java/com/android/server/content/SyncStorageEngine.java

+10 −0

Original line number	Diff line number	Diff line
		@@ -1183,6 +1183,16 @@ public class SyncStorageEngine extends Handler {
		ds.failureCount++;
		ds.failureTime += elapsedTime;
		}
		final StringBuilder event = new StringBuilder();
		event.append("" + resultMessage + " Source=" + SyncStorageEngine.SOURCES[item.source]
		+ " Elapsed=");
		SyncManager.formatDurationHMS(event, elapsedTime);
		event.append(" Reason=");
		event.append(SyncOperation.reasonToString(null, item.reason));
		event.append(" Extras=");
		SyncOperation.extrasToStringBuilder(item.extras, event);

		status.addEvent(event.toString());

		if (writeStatusNow) {
		writeStatusLocked();

services/tests/servicestests/src/com/android/server/content/ObserverNodeTest.java

+7 −1

Original line number	Diff line number	Diff line
		@@ -21,16 +21,22 @@ import java.util.ArrayList;
		import android.database.ContentObserver;
		import android.net.Uri;
		import android.os.Handler;
		import android.os.Looper;
		import android.os.UserHandle;
		import android.test.AndroidTestCase;
		import android.test.suitebuilder.annotation.SmallTest;

		import com.android.server.content.ContentService.ObserverCall;
		import com.android.server.content.ContentService.ObserverNode;

		/**
		* bit FrameworksServicesTests:com.android.server.content.ObserverNodeTest
		*/
		@SmallTest
		public class ObserverNodeTest extends AndroidTestCase {
		static class TestObserver extends ContentObserver {
		public TestObserver() {
		super(new Handler());
		super(new Handler(Looper.getMainLooper()));
		}
		}