Process queuedWork on main thread and add logging (a211bc1a) · Commits · e / os / android_frameworks_base

core/java/android/app/QueuedWork.java

+68 −16

Original line number	Diff line number	Diff line
		@@ -46,13 +46,23 @@ import java.util.LinkedList;
		*/
		public class QueuedWork {
		private static final String LOG_TAG = QueuedWork.class.getSimpleName();
		private static final boolean DEBUG = true;

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

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

		/**
		* 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.
		*/
		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<>();
		@@ -78,7 +88,7 @@ public class QueuedWork {
		synchronized (sLock) {
		if (sHandler == null) {
		HandlerThread handlerThread = new HandlerThread("queued-work-looper",
		Process.THREAD_PRIORITY_BACKGROUND);
		Process.THREAD_PRIORITY_FOREGROUND);
		handlerThread.start();

		sHandler = new QueuedWorkHandler(handlerThread.getLooper());
		@@ -125,19 +135,32 @@ public class QueuedWork {
		* after Service command handling, etc. (so async work is never lost)
		*/
		public static void waitToFinish() {
		long startTime = 0;
		boolean hadMessages = false;

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

		Handler handler = getHandler();

		synchronized (sLock) {
		if (handler.hasMessages(QueuedWorkHandler.MSG_RUN)) {
		// Force the delayed work to be processed now
		// Delayed work will be processed at processPendingWork() below
		handler.removeMessages(QueuedWorkHandler.MSG_RUN);
		handler.sendEmptyMessage(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;
		@@ -155,6 +178,14 @@ public class QueuedWork {
		} finally {
		sCanDelay = true;
		}

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

		if (waitTime > 0 \|\| hadMessages) {
		Log.d(LOG_TAG, "waited " + waitTime + " ms");
		}
		}
		}

		/**
		@@ -186,26 +217,47 @@ public class QueuedWork {
		}
		}

		private static class QueuedWorkHandler extends Handler {
		static final int MSG_RUN = 1;
		private static void processPendingWork() {
		long startTime = 0;

		QueuedWorkHandler(Looper looper) {
		super(looper);
		if (DEBUG) {
		startTime = System.currentTimeMillis();
		}

		public void handleMessage(Message msg) {
		if (msg.what == MSG_RUN) {
		synchronized (sProcessingWork) {
		LinkedList<Runnable> work;

		synchronized (sWork) {
		synchronized (sLock) {
		work = (LinkedList<Runnable>) sWork.clone();
		sWork.clear();

		// Remove all msg-s as all work will be processed now
		removeMessages(MSG_RUN);
		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");
		}
		}
		}
		}

		work.forEach(Runnable::run);
		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();
		}
		}
		}

core/java/android/app/SharedPreferencesImpl.java

+96 −17

Original line number	Diff line number	Diff line
		@@ -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,6 +407,12 @@ 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");
		}
		}
		};

		@@ -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,10 +610,6 @@ final class SharedPreferencesImpl implements SharedPreferences {
		}
		}

		if (DEBUG) {
		Log.d(TAG, "queued " + mcr.memoryStateGeneration + " -> " + mFile.getName());
		}

		QueuedWork.queue(writeToDiskRunnable, !isFromSyncCommit);
		}

		@@ -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);
		}
		}