Bug 1727261 - Timeout Sqlite transaction async functions to properly roll back... (0e517f8c) · Commits · The Tor Project / Applications / Tor Browser

toolkit/components/telemetry/Scalars.yaml

+19 −0

Original line number	Diff line number	Diff line
		@@ -3080,6 +3080,25 @@ navigator.storage:
		- 'main'
		- 'content'

		mozstorage:
		sqlitejsm_transaction_timeout:
		bug_numbers:
		- 1727261
		description: >
		Collection of javascript modules that created a Sqlite.jsm transaction
		taking too long and timing out. This can be used to identify and optimize
		those modules transactions.
		expires: never
		keyed: true
		kind: uint
		notification_emails:
		- mak@mozilla.com
		release_channel_collection: opt-out
		products:
		- 'firefox'
		record_in_processes:
		- 'main'

		telemetry:
		accumulate_unknown_histogram_keys:
		bug_numbers:

toolkit/modules/Sqlite.jsm

+57 −27

Original line number	Diff line number	Diff line
		@@ -6,11 +6,6 @@

		var EXPORTED_SYMBOLS = ["Sqlite"];

		// The maximum time to wait before considering a transaction stuck and rejecting
		// it. (Note that the minimum amount of time we wait is 20% less than this, see
		// the `_getTimeoutPromise` method on `ConnectionData` for details).
		const TRANSACTIONS_QUEUE_TIMEOUT_MS = 300000; // 5 minutes

		const { XPCOMUtils } = ChromeUtils.import(
		"resource://gre/modules/XPCOMUtils.jsm"
		);
		@@ -304,10 +299,10 @@ function ConnectionData(connection, identifier, options = {}) {
		})
		);

		// We avoid creating a timer every transaction that exists solely as a safety
		// check (e.g. one that never should fire) by reusing it if it's sufficiently
		// close to when the previous promise was created (see bug 1442353 and
		// `_getTimeoutPromise` for more info).
		// We avoid creating a timer for every transaction, because in most cases they
		// are not canceled and they are only used as a timeout.
		// Instead the timer is reused when it's sufficiently close to the previous
		// creation time (see `_getTimeoutPromise` for more info).
		this._timeoutPromise = null;
		// The last timestamp when we should consider using `this._timeoutPromise`.
		this._timeoutPromiseExpires = 0;
		@@ -605,6 +600,14 @@ ConnectionData.prototype = Object.freeze({
		},

		executeTransaction(func, type) {
		// Identify the caller for debugging purposes.
		let caller = new Error().stack
		.split("\n", 3)
		.pop()
		.match(/^([^@]+@).\/([^\/:]+)[:0-9]$/);
		caller = caller[1] + caller[2];
		this._log.debug(`Transaction (type ${type}) requested by: ${caller}`);

		if (type == OpenedConnection.prototype.TRANSACTION_DEFAULT) {
		type = this.defaultTransactionType;
		} else if (!OpenedConnection.TRANSACTION_TYPES.includes(type)) {
		@@ -612,7 +615,11 @@ ConnectionData.prototype = Object.freeze({
		}
		this.ensureOpen();

		this._log.debug("Beginning transaction");
		// If a transaction yields on a never resolved promise, or is mistakenly
		// nested, it could hang the transactions queue forever. Thus we timeout
		// the execution after a meaningful amount of time, to ensure in any case
		// we'll proceed after a while.
		let timeoutPromise = this._getTimeoutPromise();

		let promise = this._transactionQueue.then(() => {
		if (this._closeRequested) {
		@@ -631,6 +638,7 @@ ConnectionData.prototype = Object.freeze({
		// We catch errors in statement execution to detect nested transactions.
		try {
		await this.execute("BEGIN " + type + " TRANSACTION");
		this._log.debug(`Begin transaction`);
		this._initiatedTransaction = true;
		} catch (ex) {
		// Unfortunately, if we are wrapping an existing connection, a
		@@ -654,7 +662,7 @@ ConnectionData.prototype = Object.freeze({

		let result;
		try {
		result = await func();
		result = await Promise.race([func(), timeoutPromise]);
		} catch (ex) {
		// It's possible that the exception has been caused by trying to
		// close the connection in the middle of a transaction.
		@@ -664,11 +672,31 @@ ConnectionData.prototype = Object.freeze({
		ex
		);
		} else {
		this._log.error("Error during transaction. Rolling back", ex);
		// Otherwise the function didn't resolve before the timeout, or
		// generated an unexpected error. Then we rollback.
		if (ex.becauseTimedOut) {
		let caller_module = caller.split(":", 1)[0];
		Services.telemetry.keyedScalarAdd(
		"mozstorage.sqlitejsm_transaction_timeout",
		caller_module,
		1
		);
		this._log.error(
		`The transaction requested by ${caller} timed out. Rolling back`,
		ex
		);
		} else {
		this._log.error(
		`Error during transaction requested by ${caller}. Rolling back`,
		ex
		);
		}
		// If we began a transaction, we must rollback it.
		if (this._initiatedTransaction) {
		try {
		await this.execute("ROLLBACK TRANSACTION");
		this._initiatedTransaction = false;
		this._log.debug(`Roll back transaction`);
		} catch (inner) {
		this._log.error("Could not roll back transaction", inner);
		}
		@@ -692,6 +720,7 @@ ConnectionData.prototype = Object.freeze({
		if (this._initiatedTransaction) {
		try {
		await this.execute("COMMIT TRANSACTION");
		this._log.debug(`Commit transaction`);
		} catch (ex) {
		this._log.warn("Error committing transaction", ex);
		throw ex;
		@@ -704,11 +733,6 @@ ConnectionData.prototype = Object.freeze({
		}
		})();

		// If a transaction yields on a never resolved promise, or is mistakenly
		// nested, it could hang the transactions queue forever. Thus we timeout
		// the execution after a meaningful amount of time, to ensure in any case
		// we'll proceed after a while.
		let timeoutPromise = this._getTimeoutPromise();
		return Promise.race([transactionPromise, timeoutPromise]);
		});
		// Atomically update the queue before anyone else has a chance to enqueue
		@@ -947,10 +971,12 @@ ConnectionData.prototype = Object.freeze({
		);
		},

		// Returns a promise that will resolve after a time comprised between 80% of
		// `TRANSACTIONS_QUEUE_TIMEOUT_MS` and `TRANSACTIONS_QUEUE_TIMEOUT_MS`. Use
		// this promise instead of creating several individual timers to reduce the
		// overhead due to timers (see bug 1442353).
		/**
		* Returns a promise that will resolve after a time comprised between 80% of
		* `TRANSACTIONS_TIMEOUT_MS` and `TRANSACTIONS_TIMEOUT_MS`. Use
		* this method instead of creating several individual timers that may survive
		* longer than necessary.
		*/
		_getTimeoutPromise() {
		if (this._timeoutPromise && Cu.now() <= this._timeoutPromiseExpires) {
		return this._timeoutPromise;
		@@ -961,16 +987,16 @@ ConnectionData.prototype = Object.freeze({
		if (this._timeoutPromise == timeoutPromise) {
		this._timeoutPromise = null;
		}
		reject(
		new Error(
		let e = new Error(
		"Transaction timeout, most likely caused by unresolved pending work."
		)
		);
		}, TRANSACTIONS_QUEUE_TIMEOUT_MS);
		e.becauseTimedOut = true;
		reject(e);
		}, Sqlite.TRANSACTIONS_TIMEOUT_MS);
		});
		this._timeoutPromise = timeoutPromise;
		this._timeoutPromiseExpires =
		Cu.now() + TRANSACTIONS_QUEUE_TIMEOUT_MS * 0.2;
		Cu.now() + Sqlite.TRANSACTIONS_TIMEOUT_MS * 0.2;
		return this._timeoutPromise;
		},
		});
		@@ -1693,6 +1719,10 @@ OpenedConnection.prototype = Object.freeze({
		});

		var Sqlite = {
		// The maximum time to wait before considering a transaction stuck and
		// issuing a ROLLBACK, see `executeTransaction`. Could be modified by tests.
		TRANSACTIONS_TIMEOUT_MS: 300000, // 5 minutes

		openConnection,
		cloneStorageConnection,
		wrapStorageConnection,

toolkit/modules/tests/xpcshell/test_sqlite.js

+48 −0

Original line number	Diff line number	Diff line
		@@ -11,6 +11,9 @@ const { FileUtils } = ChromeUtils.import(
		"resource://gre/modules/FileUtils.jsm"
		);
		const { Sqlite } = ChromeUtils.import("resource://gre/modules/Sqlite.jsm");
		const { TelemetryTestUtils } = ChromeUtils.import(
		"resource://testing-common/TelemetryTestUtils.jsm"
		);

		function sleep(ms) {
		return new Promise(resolve => {
		@@ -562,6 +565,51 @@ add_task(async function test_wrapped_connection_transaction() {
		await c.asyncClose();
		});

		add_task(async function test_transaction_timeout() {
		// Lower the transactions timeout for the test.
		let defaultTimeout = Sqlite.TRANSACTIONS_TIMEOUT_MS;
		Sqlite.TRANSACTIONS_TIMEOUT_MS = 500;
		Services.telemetry.clearScalars();
		let myResolve = () => {};
		try {
		let c = await getDummyDatabase("transaction_timeout");
		Assert.ok(!c.transactionInProgress, "Should not be in a transaction");
		let promise = c.executeTransaction(async function transaction(conn) {
		// Make a change, we'll later check it is undone by ROLLBACK.
		await conn.execute(
		"CREATE TABLE test (id INTEGER PRIMARY KEY AUTOINCREMENT)"
		);
		Assert.ok(c.transactionInProgress, "Should be in a transaction");
		// Return a never fulfilled promise.
		await new Promise(resolve => {
		// Keep this alive regardless GC, and clean it up in finally.
		myResolve = resolve;
		});
		});

		await Assert.rejects(
		promise,
		/Transaction timeout, most likely caused by unresolved pending work./,
		"A transaction timeout should reject it"
		);

		let rows = await c.execute("SELECT * FROM dirs");
		Assert.equal(rows.length, 0, "Changes should have been rolled back");
		await c.close();

		let scalars = TelemetryTestUtils.getProcessScalars("parent", true, true);
		TelemetryTestUtils.assertKeyedScalar(
		scalars,
		"mozstorage.sqlitejsm_transaction_timeout",
		"test_transaction_timeout@test_sqlite.js",
		1
		);
		} finally {
		Sqlite.TRANSACTIONS_TIMEOUT_MS = defaultTimeout;
		myResolve();
		}
		});

		add_task(async function test_shrink_memory() {
		let c = await getDummyDatabase("shrink_memory");