Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: Track dirty table writes and long transactions #42345

Merged
merged 2 commits into from
Jan 12, 2024
Merged

feat: Track dirty table writes and long transactions #42345

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
3e60092
feat: Add logging for transaction time
juliusknorr Dec 16, 2023
c17c42a
feat: First attempt to track dirty tables after writes and switch bac…
juliusknorr Dec 15, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
61 changes: 61 additions & 0 deletions lib/private/DB/Connection.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -79,6 +79,10 @@ class Connection extends PrimaryReadReplicaConnection {
/** @var DbDataCollector|null */
protected $dbDataCollector = null;

protected ?float $transactionActiveSince = null;

protected $tableDirtyWrites = [];

/**
* Initializes a new instance of the Connection class.
*
Expand Down Expand Up @@ -255,13 +259,35 @@ public function prepare($sql, $limit = null, $offset = null): Statement {
* @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++;
$this->logQueryToFile($sql);
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
*/
Expand All @@ -288,6 +314,9 @@ public function executeUpdate(string $sql, array $params = [], array $types = []
* @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++;
Expand All @@ -306,6 +335,7 @@ protected function logQueryToFile(string $sql): void {
// 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', ''),
Expand Down Expand Up @@ -618,4 +648,35 @@ protected function performConnect(?string $connectionName = null): bool {
}
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) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this will be true very often. should we use a lower threshold like 10ms?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

microtime will actually return seconds if true is passed on as a parameter so a float is returned. So this would only log if greater 1 second

$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) {
Altahrim marked this conversation as resolved.
Show resolved Hide resolved
$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;
}
}
Loading