Merge "Log histogram of fsync times of sharedPreferences"
diff --git a/core/java/android/app/QueuedWork.java b/core/java/android/app/QueuedWork.java
index 9c5c338..56338f5 100644
--- a/core/java/android/app/QueuedWork.java
+++ b/core/java/android/app/QueuedWork.java
@@ -25,6 +25,7 @@
import android.util.Log;
import com.android.internal.annotations.GuardedBy;
+import com.android.internal.util.ExponentiallyBucketedHistogram;
import java.util.LinkedList;
@@ -47,11 +48,14 @@
*/
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 @@
@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 @@
* 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 @@
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: ");
+ }
}
}
}
diff --git a/core/java/android/app/SharedPreferencesImpl.java b/core/java/android/app/SharedPreferencesImpl.java
index 11ba7ee..7a608f3 100644
--- a/core/java/android/app/SharedPreferencesImpl.java
+++ b/core/java/android/app/SharedPreferencesImpl.java
@@ -28,6 +28,7 @@
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 @@
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 @@
@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 @@
}
XmlUtils.writeMapXml(mcr.mapToWriteToDisk, str);
- if (DEBUG) {
- writeTime = System.currentTimeMillis();
- }
+ writeTime = System.currentTimeMillis();
FileUtils.sync(str);
- if (DEBUG) {
- fsyncTime = System.currentTimeMillis();
- }
+ fsyncTime = System.currentTimeMillis();
str.close();
ContextImpl.setFilePermissionsFromMode(mFile.getPath(), mMode, 0);
@@ -761,14 +766,24 @@
mcr.setDiskWriteResult(true, true);
- Log.d(TAG, "write: " + (existsTime - startTime) + "/"
- + (backupExistsTime - startTime) + "/"
- + (outputStreamCreateTime - startTime) + "/"
- + (writeTime - startTime) + "/"
- + (fsyncTime - startTime) + "/"
- + (setPermTime - startTime) + "/"
- + (fstatTime - startTime) + "/"
- + (deleteTime - startTime));
+ if (DEBUG) {
+ Log.d(TAG, "write: " + (existsTime - startTime) + "/"
+ + (backupExistsTime - startTime) + "/"
+ + (outputStreamCreateTime - startTime) + "/"
+ + (writeTime - startTime) + "/"
+ + (fsyncTime - startTime) + "/"
+ + (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) {
diff --git a/core/java/com/android/internal/util/ExponentiallyBucketedHistogram.java b/core/java/com/android/internal/util/ExponentiallyBucketedHistogram.java
new file mode 100644
index 0000000..dc9f3f4
--- /dev/null
+++ b/core/java/com/android/internal/util/ExponentiallyBucketedHistogram.java
@@ -0,0 +1,97 @@
+/*
+ * 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());
+ }
+}