diff --git a/core/java/android/app/QueuedWork.java b/core/java/android/app/QueuedWork.java index 6ee4780591710..a38fd4387e903 100644 --- a/core/java/android/app/QueuedWork.java +++ b/core/java/android/app/QueuedWork.java @@ -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 sPendingWorkFinishers = - new ConcurrentLinkedQueue(); + /** 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 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 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 work; + + synchronized (sLock) { + work = (LinkedList) 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(); + } + } } - } diff --git a/core/java/android/app/SharedPreferencesImpl.java b/core/java/android/app/SharedPreferencesImpl.java index 3bb7019c212d5..11ba7eec97458 100644 --- a/core/java/android/app/SharedPreferencesImpl.java +++ b/core/java/android/app/SharedPreferencesImpl.java @@ -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 keysModified, @Nullable Set 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); } } diff --git a/core/java/android/content/BroadcastReceiver.java b/core/java/android/content/BroadcastReceiver.java index 485d0784b7660..c3d6606089cb3 100644 --- a/core/java/android/content/BroadcastReceiver.java +++ b/core/java/android/content/BroadcastReceiver.java @@ -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);