Log histogram of fsync times of sharedPreferences (e64a5210) · Commits · e / os / android_frameworks_base

core/java/android/app/QueuedWork.java

+20 −8

Original line number	Original line	Diff line number	Diff line
	@@ -24,6 +24,7 @@ import android.os.Process;
	import android.util.Log;		import android.util.Log;

	import com.android.internal.annotations.GuardedBy;		import com.android.internal.annotations.GuardedBy;
			import com.android.internal.util.ExponentiallyBucketedHistogram;

	import java.util.LinkedList;		import java.util.LinkedList;

	@@ -46,11 +47,14 @@ import java.util.LinkedList;
	*/		*/
	public class QueuedWork {		public class QueuedWork {
	private static final String LOG_TAG = QueuedWork.class.getSimpleName();		private static final String LOG_TAG = QueuedWork.class.getSimpleName();
	private static final boolean DEBUG = true;		private static final boolean DEBUG = false;

	/** Delay for delayed runnables, as big as possible but low enough to be barely perceivable */		/** Delay for delayed runnables, as big as possible but low enough to be barely perceivable */
	private static final long DELAY = 100;		private static final long DELAY = 100;

			/** If a {@link #waitToFinish()} takes more than {@value #MAX_WAIT_TIME_MILLIS} ms, warn */
			private static final long MAX_WAIT_TIME_MILLIS = 512;

	/** Lock for this class */		/** Lock for this class */
	private static final Object sLock = new Object();		private static final Object sLock = new Object();

	@@ -79,6 +83,13 @@ public class QueuedWork {
	@GuardedBy("sLock")		@GuardedBy("sLock")
	private static boolean sCanDelay = true;		private static boolean sCanDelay = true;

			/** Time (and number of instances) waited for work to get processed */
			@GuardedBy("sLock")
			private final static ExponentiallyBucketedHistogram
			mWaitTimes = new ExponentiallyBucketedHistogram(
			16);
			private static int mNumWaits = 0;

	/**		/**
	* Lazily create a handler on a separate thread.		* Lazily create a handler on a separate thread.
	*		*
	@@ -135,13 +146,9 @@ public class QueuedWork {
	* after Service command handling, etc. (so async work is never lost)		* after Service command handling, etc. (so async work is never lost)
	*/		*/
	public static void waitToFinish() {		public static void waitToFinish() {
	long startTime = 0;		long startTime = System.currentTimeMillis();
	boolean hadMessages = false;		boolean hadMessages = false;

	if (DEBUG) {
	startTime = System.currentTimeMillis();
	}

	Handler handler = getHandler();		Handler handler = getHandler();

	synchronized (sLock) {		synchronized (sLock) {
	@@ -179,11 +186,16 @@ public class QueuedWork {
	sCanDelay = true;		sCanDelay = true;
	}		}

	if (DEBUG) {		synchronized (sLock) {
	long waitTime = System.currentTimeMillis() - startTime;		long waitTime = System.currentTimeMillis() - startTime;

	if (waitTime > 0 \|\| hadMessages) {		if (waitTime > 0 \|\| hadMessages) {
	Log.d(LOG_TAG, "waited " + waitTime + " ms");		mWaitTimes.add(Long.valueOf(waitTime).intValue());
			mNumWaits++;

			if (DEBUG \|\| mNumWaits % 1024 == 0 \|\| waitTime > MAX_WAIT_TIME_MILLIS) {
			mWaitTimes.log(LOG_TAG, "waited: ");
			}
	}		}
	}		}
	}		}

core/java/android/app/SharedPreferencesImpl.java

+30 −15

Original line number	Original line	Diff line number	Diff line
	@@ -28,6 +28,7 @@ import android.util.Log;
	import com.google.android.collect.Maps;		import com.google.android.collect.Maps;

	import com.android.internal.annotations.GuardedBy;		import com.android.internal.annotations.GuardedBy;
			import com.android.internal.util.ExponentiallyBucketedHistogram;
	import com.android.internal.util.XmlUtils;		import com.android.internal.util.XmlUtils;

	import dalvik.system.BlockGuard;		import dalvik.system.BlockGuard;
	@@ -53,9 +54,12 @@ import libcore.io.IoUtils;

	final class SharedPreferencesImpl implements SharedPreferences {		final class SharedPreferencesImpl implements SharedPreferences {
	private static final String TAG = "SharedPreferencesImpl";		private static final String TAG = "SharedPreferencesImpl";
	private static final boolean DEBUG = true;		private static final boolean DEBUG = false;
	private static final Object CONTENT = new Object();		private static final Object CONTENT = new Object();

			/** If a fsync takes more than {@value #MAX_FSYNC_DURATION_MILLIS} ms, warn */
			private static final long MAX_FSYNC_DURATION_MILLIS = 256;

	// Lock ordering rules:		// Lock ordering rules:
	// - acquire SharedPreferencesImpl.mLock before EditorImpl.mLock		// - acquire SharedPreferencesImpl.mLock before EditorImpl.mLock
	// - acquire mWritingToDiskLock before EditorImpl.mLock		// - acquire mWritingToDiskLock before EditorImpl.mLock
	@@ -93,6 +97,11 @@ final class SharedPreferencesImpl implements SharedPreferences {
	@GuardedBy("mWritingToDiskLock")		@GuardedBy("mWritingToDiskLock")
	private long mDiskStateGeneration;		private long mDiskStateGeneration;

			/** Time (and number of instances) of file-system sync requests */
			@GuardedBy("mWritingToDiskLock")
			private final ExponentiallyBucketedHistogram mSyncTimes = new ExponentiallyBucketedHistogram(16);
			private int mNumSync = 0;

	SharedPreferencesImpl(File file, int mode) {		SharedPreferencesImpl(File file, int mode) {
	mFile = file;		mFile = file;
	mBackupFile = makeBackupFile(file);		mBackupFile = makeBackupFile(file);
	@@ -719,15 +728,11 @@ final class SharedPreferencesImpl implements SharedPreferences {
	}		}
	XmlUtils.writeMapXml(mcr.mapToWriteToDisk, str);		XmlUtils.writeMapXml(mcr.mapToWriteToDisk, str);

	if (DEBUG) {
	writeTime = System.currentTimeMillis();		writeTime = System.currentTimeMillis();
	}

	FileUtils.sync(str);		FileUtils.sync(str);

	if (DEBUG) {
	fsyncTime = System.currentTimeMillis();		fsyncTime = System.currentTimeMillis();
	}

	str.close();		str.close();
	ContextImpl.setFilePermissionsFromMode(mFile.getPath(), mMode, 0);		ContextImpl.setFilePermissionsFromMode(mFile.getPath(), mMode, 0);
	@@ -761,6 +766,7 @@ final class SharedPreferencesImpl implements SharedPreferences {

	mcr.setDiskWriteResult(true, true);		mcr.setDiskWriteResult(true, true);

			if (DEBUG) {
	Log.d(TAG, "write: " + (existsTime - startTime) + "/"		Log.d(TAG, "write: " + (existsTime - startTime) + "/"
	+ (backupExistsTime - startTime) + "/"		+ (backupExistsTime - startTime) + "/"
	+ (outputStreamCreateTime - startTime) + "/"		+ (outputStreamCreateTime - startTime) + "/"
	@@ -769,6 +775,15 @@ final class SharedPreferencesImpl implements SharedPreferences {
	+ (setPermTime - startTime) + "/"		+ (setPermTime - startTime) + "/"
	+ (fstatTime - startTime) + "/"		+ (fstatTime - startTime) + "/"
	+ (deleteTime - startTime));		+ (deleteTime - startTime));
			}

			long fsyncDuration = fsyncTime - writeTime;
			mSyncTimes.add(Long.valueOf(fsyncDuration).intValue());
			mNumSync++;

			if (DEBUG \|\| mNumSync % 1024 == 0 \|\| fsyncDuration > MAX_FSYNC_DURATION_MILLIS) {
			mSyncTimes.log(TAG, "Time required to fsync " + mFile + ": ");
			}

	return;		return;
	} catch (XmlPullParserException e) {		} catch (XmlPullParserException e) {

core/java/com/android/internal/util/ExponentiallyBucketedHistogram.java

0 → 100644

+97 −0

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

			import android.annotation.IntRange;
			import android.annotation.NonNull;
			import android.annotation.Nullable;
			import android.util.Log;

			import java.util.Arrays;

			/**
			* A histogram for positive integers where each bucket is twice the size of the previous one.
			*/
			public class ExponentiallyBucketedHistogram {
			@NonNull
			private final int[] mData;

			/**
			* Create a new histogram.
			*
			* @param numBuckets The number of buckets. The highest bucket is for all value >=
			* 2<sup>numBuckets - 1</sup>
			*/
			public ExponentiallyBucketedHistogram(@IntRange(from = 1, to = 31) int numBuckets) {
			numBuckets = Preconditions.checkArgumentInRange(numBuckets, 1, 31, "numBuckets");

			mData = new int[numBuckets];
			}

			/**
			* Add a new value to the histogram.
			*
			* All values <= 0 are in the first bucket. The last bucket contains all values >=
			* 2<sup>numBuckets - 1</sup>
			*
			* @param value The value to add
			*/
			public void add(int value) {
			if (value <= 0) {
			mData[0]++;
			} else {
			mData[Math.min(mData.length - 1, 32 - Integer.numberOfLeadingZeros(value))]++;
			}
			}

			/**
			* Clear all data from the histogram
			*/
			public void reset() {
			Arrays.fill(mData, 0);
			}

			/**
			* Write the histogram to the log.
			*
			* @param tag The tag to use when logging
			* @param prefix A custom prefix that is printed in front of the histogram
			*/
			public void log(@NonNull String tag, @Nullable CharSequence prefix) {
			StringBuilder builder = new StringBuilder(prefix);
			builder.append('[');

			for (int i = 0; i < mData.length; i++) {
			if (i != 0) {
			builder.append(", ");
			}

			if (i < mData.length - 1) {
			builder.append("<");
			builder.append(1 << i);
			} else {
			builder.append(">=");
			builder.append(1 << (i - 1));
			}

			builder.append(": ");
			builder.append(mData[i]);
			}
			builder.append("]");

			Log.d(tag, builder.toString());
			}
			}