Merge changes from topic 'revert-anr-revert'

* changes:
  Process queuedWork on main thread and add logging
  Revert accidential merge 492a058d58
This commit is contained in:
Philip P. Moltmann
2017-02-15 21:37:30 +00:00
committed by Android (Google) Code Review
3 changed files with 316 additions and 74 deletions

View File

@@ -16,86 +16,249 @@
package android.app;
import java.util.concurrent.ConcurrentLinkedQueue;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import android.os.Handler;
import android.os.HandlerThread;
import android.os.Looper;
import android.os.Message;
import android.os.Process;
import android.util.Log;
import com.android.internal.annotations.GuardedBy;
import java.util.LinkedList;
/**
* Internal utility class to keep track of process-global work that's
* outstanding and hasn't been finished yet.
* Internal utility class to keep track of process-global work that's outstanding and hasn't been
* finished yet.
*
* This was created for writing SharedPreference edits out
* asynchronously so we'd have a mechanism to wait for the writes in
* Activity.onPause and similar places, but we may use this mechanism
* for other things in the future.
* New work will be {@link #queue queued}.
*
* It is possible to add 'finisher'-runnables that are {@link #waitToFinish guaranteed to be run}.
* This is used to make sure the work has been finished.
*
* This was created for writing SharedPreference edits out asynchronously so we'd have a mechanism
* to wait for the writes in Activity.onPause and similar places, but we may use this mechanism for
* other things in the future.
*
* The queued asynchronous work is performed on a separate, dedicated thread.
*
* @hide
*/
public class QueuedWork {
private static final String LOG_TAG = QueuedWork.class.getSimpleName();
private static final boolean DEBUG = true;
// The set of Runnables that will finish or wait on any async
// activities started by the application.
private static final ConcurrentLinkedQueue<Runnable> sPendingWorkFinishers =
new ConcurrentLinkedQueue<Runnable>();
/** Delay for delayed runnables, as big as possible but low enough to be barely perceivable */
private static final long DELAY = 100;
private static ExecutorService sSingleThreadExecutor = null; // lazy, guarded by class
/** Lock for this class */
private static final Object sLock = new Object();
/**
* Returns a single-thread Executor shared by the entire process,
* creating it if necessary.
* Used to make sure that only one thread is processing work items at a time. This means that
* they are processed in the order added.
*
* This is separate from {@link #sLock} as this is held the whole time while work is processed
* and we do not want to stall the whole class.
*/
public static ExecutorService singleThreadExecutor() {
synchronized (QueuedWork.class) {
if (sSingleThreadExecutor == null) {
// TODO: can we give this single thread a thread name?
sSingleThreadExecutor = Executors.newSingleThreadExecutor();
private static Object sProcessingWork = new Object();
/** Finishers {@link #addFinisher added} and not yet {@link #removeFinisher removed} */
@GuardedBy("sLock")
private static final LinkedList<Runnable> sFinishers = new LinkedList<>();
/** {@link #getHandler() Lazily} created handler */
@GuardedBy("sLock")
private static Handler sHandler = null;
/** Work queued via {@link #queue} */
@GuardedBy("sLock")
private static final LinkedList<Runnable> sWork = new LinkedList<>();
/** If new work can be delayed or not */
@GuardedBy("sLock")
private static boolean sCanDelay = true;
/**
* Lazily create a handler on a separate thread.
*
* @return the handler
*/
private static Handler getHandler() {
synchronized (sLock) {
if (sHandler == null) {
HandlerThread handlerThread = new HandlerThread("queued-work-looper",
Process.THREAD_PRIORITY_FOREGROUND);
handlerThread.start();
sHandler = new QueuedWorkHandler(handlerThread.getLooper());
}
return sSingleThreadExecutor;
return sHandler;
}
}
/**
* Add a runnable to finish (or wait for) a deferred operation
* started in this context earlier. Typically finished by e.g.
* an Activity#onPause. Used by SharedPreferences$Editor#startCommit().
* Add a finisher-runnable to wait for {@link #queue asynchronously processed work}.
*
* Note that this doesn't actually start it running. This is just
* a scratch set for callers doing async work to keep updated with
* what's in-flight. In the common case, caller code
* (e.g. SharedPreferences) will pretty quickly call remove()
* after an add(). The only time these Runnables are run is from
* waitToFinish(), below.
* Used by SharedPreferences$Editor#startCommit().
*
* Note that this doesn't actually start it running. This is just a scratch set for callers
* doing async work to keep updated with what's in-flight. In the common case, caller code
* (e.g. SharedPreferences) will pretty quickly call remove() after an add(). The only time
* these Runnables are run is from {@link #waitToFinish}.
*
* @param finisher The runnable to add as finisher
*/
public static void add(Runnable finisher) {
sPendingWorkFinishers.add(finisher);
}
public static void remove(Runnable finisher) {
sPendingWorkFinishers.remove(finisher);
public static void addFinisher(Runnable finisher) {
synchronized (sLock) {
sFinishers.add(finisher);
}
}
/**
* Finishes or waits for async operations to complete.
* (e.g. SharedPreferences$Editor#startCommit writes)
* Remove a previously {@link #addFinisher added} finisher-runnable.
*
* Is called from the Activity base class's onPause(), after
* BroadcastReceiver's onReceive, after Service command handling,
* etc. (so async work is never lost)
* @param finisher The runnable to remove.
*/
public static void removeFinisher(Runnable finisher) {
synchronized (sLock) {
sFinishers.remove(finisher);
}
}
/**
* Trigger queued work to be processed immediately. The queued work is processed on a separate
* thread asynchronous. While doing that run and process all finishers on this thread. The
* finishers can be implemented in a way to check weather the queued work is finished.
*
* Is called from the Activity base class's onPause(), after BroadcastReceiver's onReceive,
* after Service command handling, etc. (so async work is never lost)
*/
public static void waitToFinish() {
Runnable toFinish;
while ((toFinish = sPendingWorkFinishers.poll()) != null) {
toFinish.run();
long startTime = 0;
boolean hadMessages = false;
if (DEBUG) {
startTime = System.currentTimeMillis();
}
Handler handler = getHandler();
synchronized (sLock) {
if (handler.hasMessages(QueuedWorkHandler.MSG_RUN)) {
// Delayed work will be processed at processPendingWork() below
handler.removeMessages(QueuedWorkHandler.MSG_RUN);
if (DEBUG) {
hadMessages = true;
Log.d(LOG_TAG, "waiting");
}
}
// We should not delay any work as this might delay the finishers
sCanDelay = false;
}
processPendingWork();
try {
while (true) {
Runnable finisher;
synchronized (sLock) {
finisher = sFinishers.poll();
}
if (finisher == null) {
break;
}
finisher.run();
}
} finally {
sCanDelay = true;
}
if (DEBUG) {
long waitTime = System.currentTimeMillis() - startTime;
if (waitTime > 0 || hadMessages) {
Log.d(LOG_TAG, "waited " + waitTime + " ms");
}
}
}
/**
* Returns true if there is pending work to be done. Note that the
* result is out of data as soon as you receive it, so be careful how you
* use it.
* Queue a work-runnable for processing asynchronously.
*
* @param work The new runnable to process
* @param shouldDelay If the message should be delayed
*/
public static void queue(Runnable work, boolean shouldDelay) {
Handler handler = getHandler();
synchronized (sLock) {
sWork.add(work);
if (shouldDelay && sCanDelay) {
handler.sendEmptyMessageDelayed(QueuedWorkHandler.MSG_RUN, DELAY);
} else {
handler.sendEmptyMessage(QueuedWorkHandler.MSG_RUN);
}
}
}
/**
* @return True iff there is any {@link #queue async work queued}.
*/
public static boolean hasPendingWork() {
return !sPendingWorkFinishers.isEmpty();
synchronized (sLock) {
return !sWork.isEmpty();
}
}
private static void processPendingWork() {
long startTime = 0;
if (DEBUG) {
startTime = System.currentTimeMillis();
}
synchronized (sProcessingWork) {
LinkedList<Runnable> work;
synchronized (sLock) {
work = (LinkedList<Runnable>) sWork.clone();
sWork.clear();
// Remove all msg-s as all work will be processed now
getHandler().removeMessages(QueuedWorkHandler.MSG_RUN);
}
if (work.size() > 0) {
for (Runnable w : work) {
w.run();
}
if (DEBUG) {
Log.d(LOG_TAG, "processing " + work.size() + " items took " +
+(System.currentTimeMillis() - startTime) + " ms");
}
}
}
}
private static class QueuedWorkHandler extends Handler {
static final int MSG_RUN = 1;
QueuedWorkHandler(Looper looper) {
super(looper);
}
public void handleMessage(Message msg) {
if (msg.what == MSG_RUN) {
processPendingWork();
}
}
}
}

View File

@@ -53,7 +53,7 @@ import libcore.io.IoUtils;
final class SharedPreferencesImpl implements SharedPreferences {
private static final String TAG = "SharedPreferencesImpl";
private static final boolean DEBUG = false;
private static final boolean DEBUG = true;
private static final Object CONTENT = new Object();
// Lock ordering rules:
@@ -318,6 +318,7 @@ final class SharedPreferencesImpl implements SharedPreferences {
@GuardedBy("mWritingToDiskLock")
volatile boolean writeToDiskResult = false;
boolean wasWritten = false;
private MemoryCommitResult(long memoryStateGeneration, @Nullable List<String> keysModified,
@Nullable Set<OnSharedPreferenceChangeListener> listeners,
@@ -328,7 +329,8 @@ final class SharedPreferencesImpl implements SharedPreferences {
this.mapToWriteToDisk = mapToWriteToDisk;
}
void setDiskWriteResult(boolean result) {
void setDiskWriteResult(boolean wasWritten, boolean result) {
this.wasWritten = wasWritten;
writeToDiskResult = result;
writtenToDiskLatch.countDown();
}
@@ -396,6 +398,8 @@ final class SharedPreferencesImpl implements SharedPreferences {
}
public void apply() {
final long startTime = System.currentTimeMillis();
final MemoryCommitResult mcr = commitToMemory();
final Runnable awaitCommit = new Runnable() {
public void run() {
@@ -403,15 +407,21 @@ final class SharedPreferencesImpl implements SharedPreferences {
mcr.writtenToDiskLatch.await();
} catch (InterruptedException ignored) {
}
if (DEBUG && mcr.wasWritten) {
Log.d(TAG, mFile.getName() + ":" + mcr.memoryStateGeneration
+ " applied after " + (System.currentTimeMillis() - startTime)
+ " ms");
}
}
};
QueuedWork.add(awaitCommit);
QueuedWork.addFinisher(awaitCommit);
Runnable postWriteRunnable = new Runnable() {
public void run() {
awaitCommit.run();
QueuedWork.remove(awaitCommit);
QueuedWork.removeFinisher(awaitCommit);
}
};
@@ -503,13 +513,26 @@ final class SharedPreferencesImpl implements SharedPreferences {
}
public boolean commit() {
long startTime = 0;
if (DEBUG) {
startTime = System.currentTimeMillis();
}
MemoryCommitResult mcr = commitToMemory();
SharedPreferencesImpl.this.enqueueDiskWrite(
mcr, null /* sync write on this thread okay */);
try {
mcr.writtenToDiskLatch.await();
} catch (InterruptedException e) {
return false;
} finally {
if (DEBUG) {
Log.d(TAG, mFile.getName() + ":" + mcr.memoryStateGeneration
+ " committed after " + (System.currentTimeMillis() - startTime)
+ " ms");
}
}
notifyListeners(mcr);
return mcr.writeToDiskResult;
@@ -587,11 +610,7 @@ final class SharedPreferencesImpl implements SharedPreferences {
}
}
if (DEBUG) {
Log.d(TAG, "added " + mcr.memoryStateGeneration + " -> " + mFile.getName());
}
QueuedWork.singleThreadExecutor().execute(writeToDiskRunnable);
QueuedWork.queue(writeToDiskRunnable, !isFromSyncCommit);
}
private static FileOutputStream createFileOutputStream(File file) {
@@ -619,8 +638,31 @@ final class SharedPreferencesImpl implements SharedPreferences {
// Note: must hold mWritingToDiskLock
private void writeToFile(MemoryCommitResult mcr, boolean isFromSyncCommit) {
long startTime = 0;
long existsTime = 0;
long backupExistsTime = 0;
long outputStreamCreateTime = 0;
long writeTime = 0;
long fsyncTime = 0;
long setPermTime = 0;
long fstatTime = 0;
long deleteTime = 0;
if (DEBUG) {
startTime = System.currentTimeMillis();
}
boolean fileExists = mFile.exists();
if (DEBUG) {
existsTime = System.currentTimeMillis();
// Might not be set, hence init them to a default value
backupExistsTime = existsTime;
}
// Rename the current file so it may be used as a backup during the next read
if (mFile.exists()) {
if (fileExists) {
boolean needsWrite = false;
// Only need to write if the disk state is older than this commit
@@ -639,18 +681,21 @@ final class SharedPreferencesImpl implements SharedPreferences {
}
if (!needsWrite) {
if (DEBUG) {
Log.d(TAG, "skipped " + mcr.memoryStateGeneration + " -> " + mFile.getName());
}
mcr.setDiskWriteResult(true);
mcr.setDiskWriteResult(false, true);
return;
}
if (!mBackupFile.exists()) {
boolean backupFileExists = mBackupFile.exists();
if (DEBUG) {
backupExistsTime = System.currentTimeMillis();
}
if (!backupFileExists) {
if (!mFile.renameTo(mBackupFile)) {
Log.e(TAG, "Couldn't rename file " + mFile
+ " to backup file " + mBackupFile);
mcr.setDiskWriteResult(false);
mcr.setDiskWriteResult(false, false);
return;
}
} else {
@@ -663,19 +708,34 @@ final class SharedPreferencesImpl implements SharedPreferences {
// from the backup.
try {
FileOutputStream str = createFileOutputStream(mFile);
if (DEBUG) {
outputStreamCreateTime = System.currentTimeMillis();
}
if (str == null) {
mcr.setDiskWriteResult(false);
mcr.setDiskWriteResult(false, false);
return;
}
XmlUtils.writeMapXml(mcr.mapToWriteToDisk, str);
if (DEBUG) {
writeTime = System.currentTimeMillis();
}
FileUtils.sync(str);
if (DEBUG) {
Log.d(TAG, "wrote " + mcr.memoryStateGeneration + " -> " + mFile.getName());
fsyncTime = System.currentTimeMillis();
}
str.close();
ContextImpl.setFilePermissionsFromMode(mFile.getPath(), mMode, 0);
if (DEBUG) {
setPermTime = System.currentTimeMillis();
}
try {
final StructStat stat = Os.stat(mFile.getPath());
synchronized (mLock) {
@@ -685,12 +745,30 @@ final class SharedPreferencesImpl implements SharedPreferences {
} catch (ErrnoException e) {
// Do nothing
}
if (DEBUG) {
fstatTime = System.currentTimeMillis();
}
// Writing was successful, delete the backup file if there is one.
mBackupFile.delete();
if (DEBUG) {
deleteTime = System.currentTimeMillis();
}
mDiskStateGeneration = mcr.memoryStateGeneration;
mcr.setDiskWriteResult(true);
mcr.setDiskWriteResult(true, true);
Log.d(TAG, "write: " + (existsTime - startTime) + "/"
+ (backupExistsTime - startTime) + "/"
+ (outputStreamCreateTime - startTime) + "/"
+ (writeTime - startTime) + "/"
+ (fsyncTime - startTime) + "/"
+ (setPermTime - startTime) + "/"
+ (fstatTime - startTime) + "/"
+ (deleteTime - startTime));
return;
} catch (XmlPullParserException e) {
@@ -698,12 +776,13 @@ final class SharedPreferencesImpl implements SharedPreferences {
} catch (IOException e) {
Log.w(TAG, "writeToFile: Got exception:", e);
}
// Clean up an unsuccessfully written file
if (mFile.exists()) {
if (!mFile.delete()) {
Log.e(TAG, "Couldn't clean up partially-written file " + mFile);
}
}
mcr.setDiskWriteResult(false);
mcr.setDiskWriteResult(false, false);
}
}

View File

@@ -211,16 +211,16 @@ public abstract class BroadcastReceiver {
// of the list to finish the broadcast, so we don't block this
// thread (which may be the main thread) to have it finished.
//
// Note that we don't need to use QueuedWork.add() with the
// Note that we don't need to use QueuedWork.addFinisher() with the
// runnable, since we know the AM is waiting for us until the
// executor gets to it.
QueuedWork.singleThreadExecutor().execute( new Runnable() {
QueuedWork.queue(new Runnable() {
@Override public void run() {
if (ActivityThread.DEBUG_BROADCAST) Slog.i(ActivityThread.TAG,
"Finishing broadcast after work to component " + mToken);
sendFinished(mgr);
}
});
}, false);
} else {
if (ActivityThread.DEBUG_BROADCAST) Slog.i(ActivityThread.TAG,
"Finishing broadcast to component " + mToken);