Merge "Log histogram of fsync times of sharedPreferences" (ef98cead) · Commits · e / os / android_frameworks_base

core/java/android/app/QueuedWork.java

+20 −8

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

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

		import java.util.LinkedList;

		@@ -47,11 +48,14 @@ import java.util.LinkedList;
		*/
		public class QueuedWork {
		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 */
		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 */
		private static final Object sLock = new Object();

		@@ -80,6 +84,13 @@ public class QueuedWork {
		@GuardedBy("sLock")
		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.
		*
		@@ -136,13 +147,9 @@ public class QueuedWork {
		* after Service command handling, etc. (so async work is never lost)
		*/
		public static void waitToFinish() {
		long startTime = 0;
		long startTime = System.currentTimeMillis();
		boolean hadMessages = false;

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

		Handler handler = getHandler();

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

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

		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	Diff line number	Diff line
		@@ -28,6 +28,7 @@ import android.util.Log;
		import com.google.android.collect.Maps;

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

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

		final class SharedPreferencesImpl implements SharedPreferences {
		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();

		/** 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:
		// - acquire SharedPreferencesImpl.mLock before EditorImpl.mLock
		// - acquire mWritingToDiskLock before EditorImpl.mLock
		@@ -93,6 +97,11 @@ final class SharedPreferencesImpl implements SharedPreferences {
		@GuardedBy("mWritingToDiskLock")
		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) {
		mFile = file;
		mBackupFile = makeBackupFile(file);
		@@ -719,15 +728,11 @@ final class SharedPreferencesImpl implements SharedPreferences {
		}
		XmlUtils.writeMapXml(mcr.mapToWriteToDisk, str);

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

		FileUtils.sync(str);

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

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

		mcr.setDiskWriteResult(true, true);

		if (DEBUG) {
		Log.d(TAG, "write: " + (existsTime - startTime) + "/"
		+ (backupExistsTime - startTime) + "/"
		+ (outputStreamCreateTime - startTime) + "/"
		@@ -769,6 +775,15 @@ final class SharedPreferencesImpl implements SharedPreferences {
		+ (setPermTime - startTime) + "/"
		+ (fstatTime - 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;
		} catch (XmlPullParserException e) {

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

0 → 100644

+97 −0

Original line number	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());
		}
		}