Merge "Revert "Report long database transactions"" into main (251d74d8) · Commits · e / os / android_frameworks_base

core/java/android/database/sqlite/SQLiteConnection.java

+65 −216

Original line number	Diff line number	Diff line
		@@ -34,22 +34,17 @@ import android.util.Log;
		import android.util.LruCache;
		import android.util.Pair;
		import android.util.Printer;
		import com.android.internal.util.RingBuffer;
		import dalvik.system.BlockGuard;
		import dalvik.system.CloseGuard;

		import java.io.File;
		import java.io.IOException;
		import java.lang.ref.Reference;
		import java.nio.file.FileSystems;
		import java.nio.file.Files;
		import java.nio.file.Path;
		import java.time.Instant;
		import java.time.ZoneId;
		import java.time.format.DateTimeFormatter;
		import java.text.SimpleDateFormat;
		import java.util.ArrayList;
		import java.util.Date;
		import java.util.Locale;
		import java.util.Map;
		import java.util.function.BinaryOperator;
		import java.util.function.UnaryOperator;
		@@ -190,7 +185,7 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		SQLiteDatabaseConfiguration configuration,
		int connectionId, boolean primaryConnection) {
		mPool = pool;
		mRecentOperations = new OperationLog();
		mRecentOperations = new OperationLog(mPool);
		mConfiguration = new SQLiteDatabaseConfiguration(configuration);
		mConnectionId = connectionId;
		mIsPrimaryConnection = primaryConnection;
		@@ -312,16 +307,6 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		}
		}

		/** Record the start of a transaction for logging and debugging. */
		void recordBeginTransaction(String mode) {
		mRecentOperations.beginTransaction(mode);
		}

		/** Record the end of a transaction for logging and debugging. */
		void recordEndTransaction(boolean successful) {
		mRecentOperations.endTransaction(successful);
		}

		private void setPageSize() {
		if (!mConfiguration.isInMemoryDb() && !mIsReadOnlyConnection) {
		final long newValue = SQLiteGlobal.getDefaultPageSize();
		@@ -1352,7 +1337,6 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		}
		printer.println(" isPrimaryConnection: " + mIsPrimaryConnection);
		printer.println(" onlyAllowReadOnlyOperations: " + mOnlyAllowReadOnlyOperations);
		printer.println(" totalLongOperations: " + mRecentOperations.getTotalLongOperations());

		mRecentOperations.dump(printer);

		@@ -1611,39 +1595,51 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		}
		}

		private final class OperationLog {
		private static final class OperationLog {
		private static final int MAX_RECENT_OPERATIONS = 20;
		private static final int COOKIE_GENERATION_SHIFT = 8;
		private static final int COOKIE_INDEX_MASK = 0xff;

		// Operations over 2s are long. Save the last ten.
		private static final long LONG_OPERATION_THRESHOLD_MS = 2_000;
		private static final int MAX_LONG_OPERATIONS = 10;

		private final Operation[] mOperations = new Operation[MAX_RECENT_OPERATIONS];
		private int mIndex = -1;
		private int mGeneration = 0;
		private final Operation mTransaction = new Operation();
		private int mIndex;
		private int mGeneration;
		private final SQLiteConnectionPool mPool;
		private long mResultLong = Long.MIN_VALUE;
		private String mResultString;

		private final RingBuffer<Operation> mLongOperations =
		new RingBuffer<>(()->{return new Operation();},
		(n) ->{return new Operation[n];},
		MAX_LONG_OPERATIONS);
		private int mTotalLongOperations = 0;
		OperationLog(SQLiteConnectionPool pool) {
		mPool = pool;
		}

		public int beginOperation(String kind, String sql, Object[] bindArgs) {
		mResultLong = Long.MIN_VALUE;
		mResultString = null;

		synchronized (mOperations) {
		Operation operation = newOperationLocked();
		final int index = (mIndex + 1) % MAX_RECENT_OPERATIONS;
		Operation operation = mOperations[index];
		if (operation == null) {
		operation = new Operation();
		mOperations[index] = operation;
		} else {
		operation.mFinished = false;
		operation.mException = null;
		if (operation.mBindArgs != null) {
		operation.mBindArgs.clear();
		}
		}
		operation.mStartWallTime = System.currentTimeMillis();
		operation.mStartTime = SystemClock.uptimeMillis();
		operation.mKind = kind;
		operation.mSql = sql;
		operation.mPath = mPool.getPath();
		operation.mResultLong = Long.MIN_VALUE;
		operation.mResultString = null;
		if (bindArgs != null) {
		if (operation.mBindArgs == null) {
		operation.mBindArgs = new ArrayList<Object>();
		} else {
		operation.mBindArgs.clear();
		}
		for (int i = 0; i < bindArgs.length; i++) {
		final Object arg = bindArgs[i];
		@@ -1655,44 +1651,16 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		}
		}
		}
		operation.mCookie = newOperationCookieLocked(index);
		if (Trace.isTagEnabled(Trace.TRACE_TAG_DATABASE)) {
		Trace.asyncTraceBegin(Trace.TRACE_TAG_DATABASE, operation.getTraceMethodName(),
		operation.mCookie);
		}
		mIndex = index;
		return operation.mCookie;
		}
		}

		public void beginTransaction(String kind) {
		synchronized (mOperations) {
		Operation operation = newOperationLocked();
		operation.mKind = kind;
		mTransaction.copyFrom(operation);

		if (Trace.isTagEnabled(Trace.TRACE_TAG_DATABASE)) {
		Trace.asyncTraceBegin(Trace.TRACE_TAG_DATABASE, operation.getTraceMethodName(),
		operation.mCookie);
		}
		}
		}

		/**
		* Fetch a new operation from the ring buffer. The operation is properly initialized.
		* This advances mIndex to point to the next element.
		*/
		private Operation newOperationLocked() {
		final int index = (mIndex + 1) % MAX_RECENT_OPERATIONS;
		Operation operation = mOperations[index];
		if (operation == null) {
		mOperations[index] = new Operation();
		operation = mOperations[index];
		}
		operation.start();
		operation.mCookie = newOperationCookieLocked(index);
		mIndex = index;
		return operation;
		}

		public void failOperation(int cookie, Exception ex) {
		synchronized (mOperations) {
		final Operation operation = getOperationLocked(cookie);
		@@ -1716,20 +1684,6 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		}
		}

		public boolean endTransaction(boolean success) {
		synchronized (mOperations) {
		mTransaction.mResultLong = success ? 1 : 0;
		final long execTime = finishOperationLocked(mTransaction);
		final Operation operation = getOperationLocked(mTransaction.mCookie);
		if (operation != null) {
		operation.copyFrom(mTransaction);
		}
		mTransaction.setEmpty();
		return NoPreloadHolder.DEBUG_LOG_SLOW_QUERIES
		&& SQLiteDebug.shouldLogSlowQuery(execTime);
		}
		}

		public void logOperation(int cookie, String detail) {
		synchronized (mOperations) {
		logOperationLocked(cookie, detail);
		@@ -1751,7 +1705,9 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		Trace.asyncTraceEnd(Trace.TRACE_TAG_DATABASE, operation.getTraceMethodName(),
		operation.mCookie);
		}
		final long execTime = finishOperationLocked(operation);
		operation.mEndTime = SystemClock.uptimeMillis();
		operation.mFinished = true;
		final long execTime = operation.mEndTime - operation.mStartTime;
		mPool.onStatementExecuted(execTime);
		return NoPreloadHolder.DEBUG_LOG_SLOW_QUERIES && SQLiteDebug.shouldLogSlowQuery(
		execTime);
		@@ -1776,22 +1732,10 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		return generation << COOKIE_GENERATION_SHIFT \| index;
		}

		/** Close out the operation and return the elapsed time. */
		private long finishOperationLocked(Operation operation) {
		operation.mEndTime = SystemClock.uptimeMillis();
		operation.mFinished = true;
		final long elapsed = operation.mEndTime - operation.mStartTime;
		if (elapsed > LONG_OPERATION_THRESHOLD_MS) {
		mLongOperations.getNextSlot().copyFrom(operation);
		mTotalLongOperations++;
		}
		return elapsed;
		}

		private Operation getOperationLocked(int cookie) {
		final int index = cookie & COOKIE_INDEX_MASK;
		final Operation operation = mOperations[index];
		return (operation != null && operation.mCookie == cookie) ? operation : null;
		return operation.mCookie == cookie ? operation : null;
		}

		public String describeCurrentOperation() {
		@@ -1806,87 +1750,48 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		}
		}

		/**
		* Dump an Operation if it is not in the recent operations list. Return 1 if the
		* operation was dumped and 0 if not.
		*/
		private int dumpIfNotRecentLocked(Printer pw, Operation op, int counter) {
		if (op == null \|\| op.isEmpty() \|\| getOperationLocked(op.mCookie) != null) {
		return 0;
		}
		pw.println(op.describe(counter));
		return 1;
		}

		private void dumpRecentLocked(Printer printer) {
		public void dump(Printer printer) {
		synchronized (mOperations) {
		printer.println(" Most recently executed operations:");
		int index = mIndex;
		if (index == 0) {
		printer.println(" <none>");
		return;
		}

		// Operations are dumped in order of most recent first.
		int counter = 0;
		int n = 0;
		Operation operation = mOperations[index];
		if (operation != null) {
		// Note: SimpleDateFormat is not thread-safe, cannot be compile-time created,
		// and is relatively expensive to create during preloading. This method is only
		// used when dumping a connection, which is a rare (mainly error) case.
		SimpleDateFormat opDF = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
		int n = 0;
		do {
		printer.println(operation.describe(counter));
		StringBuilder msg = new StringBuilder();
		msg.append(" ").append(n).append(": [");
		String formattedStartTime = opDF.format(new Date(operation.mStartWallTime));
		msg.append(formattedStartTime);
		msg.append("] ");
		operation.describe(msg, false); // Never dump bingargs in a bugreport
		printer.println(msg.toString());

		if (index > 0) {
		index -= 1;
		} else {
		index = MAX_RECENT_OPERATIONS - 1;
		}
		n++;
		counter++;
		n += 1;
		operation = mOperations[index];
		} while (operation != null && n < MAX_RECENT_OPERATIONS);
		counter += dumpIfNotRecentLocked(printer, mTransaction, counter);
		}
		}

		private void dumpLongLocked(Printer printer) {
		printer.println(" Operations exceeding " + LONG_OPERATION_THRESHOLD_MS + "ms:");
		if (mLongOperations.isEmpty()) {
		} else {
		printer.println(" <none>");
		return;
		}
		Operation[] longOps = mLongOperations.toArray();
		for (int i = 0; i < longOps.length; i++) {
		if (longOps[i] != null) {
		printer.println(longOps[i].describe(i));
		}
		}
		}

		public long getTotalLongOperations() {
		return mTotalLongOperations;
		}

		public void dump(Printer printer) {
		synchronized (mOperations) {
		dumpRecentLocked(printer);
		dumpLongLocked(printer);
		}
		}
		}

		private final class Operation {
		private static final class Operation {
		// Trim all SQL statements to 256 characters inside the trace marker.
		// This limit gives plenty of context while leaving space for other
		// entries in the trace buffer (and ensures atrace doesn't truncate the
		// marker for us, potentially losing metadata in the process).
		private static final int MAX_TRACE_METHOD_NAME_LEN = 256;

		// The reserved start time that indicates the Operation is empty.
		private static final long EMPTY_OPERATION = -1;

		// The formatter for the timestamp.
		private static final DateTimeFormatter sDateTime =
		DateTimeFormatter.ofPattern("MM-dd HH:mm:ss.SSS", Locale.US);

		public long mStartWallTime; // in System.currentTimeMillis()
		public long mStartTime; // in SystemClock.uptimeMillis();
		public long mEndTime; // in SystemClock.uptimeMillis();
		@@ -1896,58 +1801,16 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		public boolean mFinished;
		public Exception mException;
		public int mCookie;
		public String mPath;
		public long mResultLong; // MIN_VALUE means "value not set".
		public String mResultString;

		/** Reset the object to begin a new operation. */
		void start() {
		mStartWallTime = System.currentTimeMillis();
		mStartTime = SystemClock.uptimeMillis();
		mEndTime = Long.MIN_VALUE;
		mKind = null;
		mSql = null;
		if (mBindArgs != null) mBindArgs.clear();
		mFinished = false;
		mException = null;
		mCookie = -1;
		mResultLong = Long.MIN_VALUE;
		mResultString = null;
		}

		/**
		* Initialize from the source object. This is meant to clone the object for use in a
		* transaction operation. To that end, the local bind args are set to null.
		*/
		void copyFrom(Operation r) {
		mStartWallTime = r.mStartWallTime;
		mStartTime = r.mStartTime;
		mEndTime = r.mEndTime;
		mKind = r.mKind;
		mSql = r.mSql;
		mBindArgs = null;
		mFinished = r.mFinished;
		mException = r.mException;
		mCookie = r.mCookie;
		mResultLong = r.mResultLong;
		mResultString = r.mResultString;
		}

		/** Mark the operation empty. */
		void setEmpty() {
		mStartWallTime = EMPTY_OPERATION;
		}

		/** Return true if the operation is empty. */
		boolean isEmpty() {
		return mStartWallTime == EMPTY_OPERATION;
		}

		public void describe(StringBuilder msg, boolean allowDetailedLog) {
		msg.append(mKind);
		if (mFinished) {
		msg.append(" took ").append(mEndTime - mStartTime).append("ms");
		} else {
		msg.append(" started ").append(SystemClock.uptimeMillis() - mStartTime)
		msg.append(" started ").append(System.currentTimeMillis() - mStartWallTime)
		.append("ms ago");
		}
		msg.append(" - ").append(getStatus());
		@@ -1976,7 +1839,7 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		}
		msg.append("]");
		}
		msg.append(", path=").append(mPool.getPath());
		msg.append(", path=").append(mPath);
		if (mException != null) {
		msg.append(", exception=\"").append(mException.getMessage()).append("\"");
		}
		@@ -1988,21 +1851,6 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		}
		}

		/**
		* Convert a wall-clock time in milliseconds to logcat format.
		*/
		private String timeString(long millis) {
		return sDateTime.withZone(ZoneId.systemDefault()).format(Instant.ofEpochMilli(millis));
		}

		public String describe(int n) {
		final StringBuilder msg = new StringBuilder();
		final String start = timeString(mStartWallTime);
		msg.append(" ").append(n).append(": [").append(start).append("] ");
		describe(msg, false); // Never dump bingargs in a bugreport
		return msg.toString();
		}

		private String getStatus() {
		if (!mFinished) {
		return "running";
		@@ -2016,6 +1864,7 @@ public final class SQLiteConnection implements CancellationSignal.OnCancelListen
		return methodName.substring(0, MAX_TRACE_METHOD_NAME_LEN);
		return methodName;
		}

		}

		/**

core/java/android/database/sqlite/SQLiteConnectionPool.java

+1 −1

Original line number	Diff line number	Diff line
		@@ -1175,7 +1175,7 @@ public final class SQLiteConnectionPool implements Closeable {
		+ ", isLegacyCompatibilityWalEnabled=" + isCompatibilityWalEnabled
		+ ", journalMode=" + TextUtils.emptyIfNull(mConfiguration.resolveJournalMode())
		+ ", syncMode=" + TextUtils.emptyIfNull(mConfiguration.resolveSyncMode()));
		printer.println(" IsReadOnlyDatabase: " + mConfiguration.isReadOnlyDatabase());
		printer.println(" IsReadOnlyDatabase=" + mConfiguration.isReadOnlyDatabase());

		if (isCompatibilityWalEnabled) {
		printer.println(" Compatibility WAL enabled: wal_syncmode="

core/java/android/database/sqlite/SQLiteSession.java

+0 −11

Original line number	Diff line number	Diff line
		@@ -312,15 +312,6 @@ public final class SQLiteSession {
		cancellationSignal);
		}

		private String modeString(int transactionMode) {
		switch (transactionMode) {
		case TRANSACTION_MODE_IMMEDIATE: return "TRANSACTION-IMMEDIATE";
		case TRANSACTION_MODE_EXCLUSIVE: return "TRANSACTION-EXCLUSIVE";
		case TRANSACTION_MODE_DEFERRED: return "TRANSACTION-DEFERRED";
		default: return "TRANSACTION";
		}
		}

		private void beginTransactionUnchecked(int transactionMode,
		SQLiteTransactionListener transactionListener, int connectionFlags,
		CancellationSignal cancellationSignal) {
		@@ -330,7 +321,6 @@ public final class SQLiteSession {

		if (mTransactionStack == null) {
		acquireConnection(null, connectionFlags, cancellationSignal); // might throw
		mConnection.recordBeginTransaction(modeString(transactionMode));
		}
		try {
		// Set up the transaction such that we can back out safely
		@@ -475,7 +465,6 @@ public final class SQLiteSession {
		mConnection.execute("ROLLBACK;", null, cancellationSignal); // might throw
		}
		} finally {
		mConnection.recordEndTransaction(successful);
		releaseConnection(); // might throw
		}
		}

core/tests/coretests/src/android/database/sqlite/SQLiteDatabaseTest.java

+0 −138

Original line number	Diff line number	Diff line
		@@ -31,7 +31,6 @@ import android.platform.test.flag.junit.CheckFlagsRule;
		import android.platform.test.flag.junit.DeviceFlagsValueProvider;
		import android.test.AndroidTestCase;
		import android.util.Log;
		import android.util.Printer;

		import androidx.test.filters.SmallTest;
		import androidx.test.platform.app.InstrumentationRegistry;
		@@ -47,15 +46,12 @@ import java.io.File;
		import java.util.ArrayList;
		import java.util.Collections;
		import java.util.List;
		import java.util.Vector;
		import java.util.concurrent.Executor;
		import java.util.concurrent.ExecutorService;
		import java.util.concurrent.Executors;
		import java.util.concurrent.Phaser;
		import java.util.concurrent.Semaphore;
		import java.util.concurrent.TimeUnit;
		import java.util.regex.Matcher;
		import java.util.regex.Pattern;

		@RunWith(AndroidJUnit4.class)
		@SmallTest
		@@ -407,138 +403,4 @@ public class SQLiteDatabaseTest {
		}
		assertFalse(allowed);
		}

		/** Dumpsys information about a single database. */

		/**
		* Collect and parse dumpsys output. This is not a full parser. It is only enough to support
		* the unit tests.
		*/
		private static class Dumpsys {
		// Regular expressions for parsing the output. Reportedly, regular expressions are
		// expensive, so these are created only if a dumpsys object is created.
		private static final Object sLock = new Object();
		static Pattern mPool;
		static Pattern mConnection;
		static Pattern mEntry;
		static Pattern mSingleWord;
		static Pattern mNone;

		// The raw strings read from dumpsys. Once loaded, this list never changes.
		final ArrayList<String> mRaw = new ArrayList<>();

		// Parsed dumpsys. This contains only the bits that are being tested.
		static class Connection {
		ArrayList<String> mRecent = new ArrayList<>();
		ArrayList<String> mLong = new ArrayList<>();
		}
		static class Database {
		String mPath;
		ArrayList<Connection> mConnection = new ArrayList<>();
		}
		ArrayList<Database> mDatabase;
		ArrayList<String> mConcurrent;

		Dumpsys() {
		SQLiteDebug.dump(
		new Printer() { public void println(String x) { mRaw.add(x); } },
		new String[0]);
		parse();
		}

		/** Parse the raw text. Return true if no errors were detected. */
		boolean parse() {
		initialize();

		// Reset the parsed information. This method may be called repeatedly.
		mDatabase = new ArrayList<>();
		mConcurrent = new ArrayList<>();

		Database current = null;
		Connection connection = null;
		Matcher matcher;
		for (int i = 0; i < mRaw.size(); i++) {
		final String line = mRaw.get(i);
		matcher = mPool.matcher(line);
		if (matcher.lookingAt()) {
		current = new Database();
		mDatabase.add(current);
		current.mPath = matcher.group(1);
		continue;
		}
		matcher = mConnection.matcher(line);
		if (matcher.lookingAt()) {
		connection = new Connection();
		current.mConnection.add(connection);
		continue;
		}

		if (line.contains("Most recently executed operations")) {
		i += readTable(connection.mRecent, i, mEntry);
		continue;
		}

		if (line.contains("Operations exceeding 2000ms")) {
		i += readTable(connection.mLong, i, mEntry);
		continue;
		}
		if (line.contains("Concurrently opened database files")) {
		i += readTable(mConcurrent, i, mSingleWord);
		continue;
		}
		}
		return true;
		}

		/**
		* Read a series of lines following a header. Return the number of lines read. The input
		* line number is the number of the header.
		*/
		private int readTable(List<String> s, int header, Pattern p) {
		// Special case: if the first line is "<none>" then there are no more lines to the
		// table.
		if (lookingAt(header+1, mNone)) return 1;

		int i;
		for (i = header + 1; i < mRaw.size() && lookingAt(i, p); i++) {
		s.add(mRaw.get(i).trim());
		}
		return i - header;
		}

		/** Return true if the n'th raw line matches the pattern. */
		boolean lookingAt(int n, Pattern p) {
		return p.matcher(mRaw.get(n)).lookingAt();
		}

		/** Compile the regular expressions the first time. */
		private static void initialize() {
		synchronized (sLock) {
		if (mPool != null) return;
		mPool = Pattern.compile("Connection pool for (\\S+):");
		mConnection = Pattern.compile("\\s+Connection #(\\d+):");
		mEntry = Pattern.compile("\\s+(\\d+): ");
		mSingleWord = Pattern.compile(" (\\S+)$");
		mNone = Pattern.compile("\\s+<none>$");
		}
		}
		}

		@Test
		public void testDumpsys() throws Exception {
		Dumpsys dumpsys = new Dumpsys();

		assertEquals(1, dumpsys.mDatabase.size());
		// Note: cannot test mConcurrent because that attribute is not hermitic with respect to
		// the tests.

		Dumpsys.Database db = dumpsys.mDatabase.get(0);

		// Work with normalized paths.
		String wantPath = mDatabaseFile.toPath().toRealPath().toString();
		String realPath = new File(db.mPath).toPath().toRealPath().toString();
		assertEquals(wantPath, realPath);

		assertEquals(1, db.mConnection.size());
		}
		}