From 3e60092b7d0e051f1384fcae172b9e4f1b30c137 Mon Sep 17 00:00:00 2001
From: Julius Härtl <jus@bitgrid.net>
Date: Sat, 16 Dec 2023 13:08:33 +0100
Subject: feat: Add logging for transaction time
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Signed-off-by: Julius Härtl <jus@bitgrid.net>
---
 lib/private/DB/Connection.php | 34 ++++++++++++++++++++++++++++++++++
 1 file changed, 34 insertions(+)

(limited to 'lib/private/DB')

diff --git a/lib/private/DB/Connection.php b/lib/private/DB/Connection.php
index e3fda3e464f..1ea2eda9d01 100644
--- a/lib/private/DB/Connection.php
+++ b/lib/private/DB/Connection.php
@@ -79,6 +79,8 @@ class Connection extends PrimaryReadReplicaConnection {
 	/** @var DbDataCollector|null */
 	protected $dbDataCollector = null;
 
+	protected ?float $transactionActiveSince = null;
+
 	/**
 	 * Initializes a new instance of the Connection class.
 	 *
@@ -306,6 +308,7 @@ class Connection extends PrimaryReadReplicaConnection {
 			// FIXME:  Improve to log the actual target db host
 			$isPrimary = $this->connections['primary'] === $this->_conn;
 			$prefix .= ' ' . ($isPrimary === true ? 'primary' : 'replica') . ' ';
+			$prefix .= ' ' . $this->getTransactionNestingLevel() . ' ';
 
 			file_put_contents(
 				$this->systemConfig->getValue('query_log_file', ''),
@@ -618,4 +621,35 @@ class Connection extends PrimaryReadReplicaConnection {
 		}
 		return $result;
 	}
+
+	public function beginTransaction() {
+		if (!$this->inTransaction()) {
+			$this->transactionActiveSince = microtime(true);
+		}
+		return parent::beginTransaction();
+	}
+
+	public function commit() {
+		$result = parent::commit();
+		if ($this->getTransactionNestingLevel() === 0) {
+			$timeTook = microtime(true) - $this->transactionActiveSince;
+			$this->transactionActiveSince = null;
+			if ($timeTook > 1) {
+				$this->logger->warning('Transaction took longer than 1s: ' . $timeTook, ['exception' => new \Exception('Long running transaction')]);
+			}
+		}
+		return $result;
+	}
+
+	public function rollBack() {
+		$result = parent::rollBack();
+		if ($this->getTransactionNestingLevel() === 0) {
+			$timeTook = microtime(true) - $this->transactionActiveSince;
+			$this->transactionActiveSince = null;
+			if ($timeTook > 1) {
+				$this->logger->warning('Transaction rollback took longer than 1s: ' . $timeTook, ['exception' => new \Exception('Long running transaction rollback')]);
+			}
+		}
+		return $result;
+	}
 }
-- 
cgit v1.2.3


From c17c42a0b246aee4417bbc1cac20cc8ff1d52a18 Mon Sep 17 00:00:00 2001
From: Julius Härtl <jus@bitgrid.net>
Date: Fri, 15 Dec 2023 21:52:31 +0100
Subject: feat: First attempt to track dirty tables after writes and switch
 back to replicas if reads go to other tables
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Signed-off-by: Julius Härtl <jus@bitgrid.net>

debug: error log

Signed-off-by: Julius Härtl <jus@bitgrid.net>
---
 lib/private/DB/Connection.php | 27 +++++++++++++++++++++++++++
 1 file changed, 27 insertions(+)

(limited to 'lib/private/DB')

diff --git a/lib/private/DB/Connection.php b/lib/private/DB/Connection.php
index 1ea2eda9d01..a5f41cc66c9 100644
--- a/lib/private/DB/Connection.php
+++ b/lib/private/DB/Connection.php
@@ -81,6 +81,8 @@ class Connection extends PrimaryReadReplicaConnection {
 
 	protected ?float $transactionActiveSince = null;
 
+	protected $tableDirtyWrites = [];
+
 	/**
 	 * Initializes a new instance of the Connection class.
 	 *
@@ -257,6 +259,18 @@ class Connection extends PrimaryReadReplicaConnection {
 	 * @throws \Doctrine\DBAL\Exception
 	 */
 	public function executeQuery(string $sql, array $params = [], $types = [], QueryCacheProfile $qcp = null): Result {
+		$tables = $this->getQueriedTables($sql);
+		if (count(array_intersect($this->tableDirtyWrites, $tables)) === 0 && !$this->isTransactionActive()) {
+			// No tables read that could have been written already in the same request and no transaction active
+			// so we can switch back to the replica for reading as long as no writes happen that switch back to the primary
+			// We cannot log here as this would log too early in the server boot process
+			$this->ensureConnectedToReplica();
+		} else {
+			// Read to a table that was previously written to
+			// While this might not necessarily mean that we did a read after write it is an indication for a code path to check
+			$this->logger->debug('dirty table reads: ' . $sql, ['tables' => $this->tableDirtyWrites, 'reads' => $tables, 'exception' => new \Exception()]);
+		}
+
 		$sql = $this->replaceTablePrefix($sql);
 		$sql = $this->adapter->fixupStatement($sql);
 		$this->queriesExecuted++;
@@ -264,6 +278,16 @@ class Connection extends PrimaryReadReplicaConnection {
 		return parent::executeQuery($sql, $params, $types, $qcp);
 	}
 
+	/**
+	 * Helper function to get the list of tables affected by a given query
+	 * used to track dirty tables that received a write with the current request
+	 */
+	private function getQueriedTables(string $sql): array {
+		$re = '/(\*PREFIX\*\w+)/mi';
+		preg_match_all($re, $sql, $matches);
+		return array_map([$this, 'replaceTablePrefix'], $matches[0] ?? []);
+	}
+
 	/**
 	 * @throws Exception
 	 */
@@ -290,6 +314,9 @@ class Connection extends PrimaryReadReplicaConnection {
 	 * @throws \Doctrine\DBAL\Exception
 	 */
 	public function executeStatement($sql, array $params = [], array $types = []): int {
+		$tables = $this->getQueriedTables($sql);
+		$this->tableDirtyWrites = array_unique(array_merge($this->tableDirtyWrites, $tables));
+		$this->logger->debug('dirty table writes: ' . $sql, ['tables' => $this->tableDirtyWrites]);
 		$sql = $this->replaceTablePrefix($sql);
 		$sql = $this->adapter->fixupStatement($sql);
 		$this->queriesExecuted++;
-- 
cgit v1.2.3