From ffbea7e4fc5a8582ded40fb0f738cd5cf8855ef3 Mon Sep 17 00:00:00 2001 From: Srdjan Date: Mon, 30 May 2022 17:52:17 +1000 Subject: [PATCH] MDL-74681 lib/dml: moodle_read_slave_trait: written table timestamping Moved written table timestamping from query_start() to query_end(): We are adjusting table last written times at the end of transaction. That does not apply to immediate database writes that are not performed within transaction. This change is to set last written time after the query has finished for such writes, rather than before it started. That way long write operations cannot spill over the latency parameter. --- lib/dml/moodle_read_slave_trait.php | 32 ++++++++----- lib/dml/pgsql_native_moodle_database.php | 21 +++++--- lib/dml/tests/dml_mysqli_read_slave_test.php | 2 +- lib/dml/tests/dml_pgsql_read_slave_test.php | 2 +- lib/dml/tests/dml_read_slave_test.php | 48 +++++++++++++++++-- .../fixtures/read_slave_moodle_database.php | 6 ++- .../fixtures/test_moodle_read_slave_trait.php | 2 + 7 files changed, 90 insertions(+), 23 deletions(-) diff --git a/lib/dml/moodle_read_slave_trait.php b/lib/dml/moodle_read_slave_trait.php index 2e99699d9de..7f06e5efb8d 100644 --- a/lib/dml/moodle_read_slave_trait.php +++ b/lib/dml/moodle_read_slave_trait.php @@ -272,6 +272,25 @@ trait moodle_read_slave_trait { $this->select_db_handle($type, $sql); } + /** + * This should be called immediately after each db query. It does a clean up of resources. + * + * @param mixed $result The db specific result obtained from running a query. + * @return void + */ + protected function query_end($result) { + if ($this->written) { + // Adjust the written time. + array_walk($this->written, function (&$val) { + if ($val === true) { + $val = microtime(true); + } + }); + } + + parent::query_end($result); + } + /** * Select appropriate db handle - readwrite or readonly * @param int $type type of query @@ -323,15 +342,7 @@ trait moodle_read_slave_trait { if (isset($this->written[$tablename])) { $now = $now ?: microtime(true); - // Paranoid check. - if ($this->written[$tablename] === true) { - debugging( - "$tablename last written set to true outside transaction - should not happen!", - DEBUG_DEVELOPER - ); - $this->written[$tablename] = $now; - return false; - } + if ($now - $this->written[$tablename] < $this->slavelatency) { return false; } @@ -342,9 +353,8 @@ trait moodle_read_slave_trait { return true; case SQL_QUERY_INSERT: case SQL_QUERY_UPDATE: - $now = $this->transactions ? true : microtime(true); foreach ($this->table_names($sql) as $tablename) { - $this->written[$tablename] = $now; + $this->written[$tablename] = true; } return false; case SQL_QUERY_STRUCTURE: diff --git a/lib/dml/pgsql_native_moodle_database.php b/lib/dml/pgsql_native_moodle_database.php index dd5095002c4..81143e3f53c 100644 --- a/lib/dml/pgsql_native_moodle_database.php +++ b/lib/dml/pgsql_native_moodle_database.php @@ -41,6 +41,7 @@ class pgsql_native_moodle_database extends moodle_database { select_db_handle as read_slave_select_db_handle; can_use_readonly as read_slave_can_use_readonly; query_start as read_slave_query_start; + query_end as read_slave_query_end; } /** @var array $dbhcursor keep track of open cursors */ @@ -184,12 +185,20 @@ class pgsql_native_moodle_database extends moodle_database { } ob_start(); - if (empty($this->dboptions['dbpersist'])) { - $this->pgsql = pg_connect($connection, PGSQL_CONNECT_FORCE_NEW); - } else { - $this->pgsql = pg_pconnect($connection, PGSQL_CONNECT_FORCE_NEW); + // It seems that pg_connect() handles some errors differently. + // For example, name resolution error will raise an exception, and non-existing + // database or wrong credentials will just return false. + // We need to cater for both. + try { + if (empty($this->dboptions['dbpersist'])) { + $this->pgsql = pg_connect($connection, PGSQL_CONNECT_FORCE_NEW); + } else { + $this->pgsql = pg_pconnect($connection, PGSQL_CONNECT_FORCE_NEW); + } + $dberr = ob_get_contents(); + } catch (\Exception $e) { + $dberr = $e->getMessage(); } - $dberr = ob_get_contents(); ob_end_clean(); $status = $this->pgsql ? pg_connection_status($this->pgsql) : false; @@ -326,7 +335,7 @@ class pgsql_native_moodle_database extends moodle_database { // reset original debug level error_reporting($this->last_error_reporting); try { - parent::query_end($result); + $this->read_slave_query_end($result); if ($this->savepointpresent and $this->last_type != SQL_QUERY_AUX and $this->last_type != SQL_QUERY_SELECT) { $res = @pg_query($this->pgsql, "RELEASE SAVEPOINT moodle_pg_savepoint; SAVEPOINT moodle_pg_savepoint"); if ($res) { diff --git a/lib/dml/tests/dml_mysqli_read_slave_test.php b/lib/dml/tests/dml_mysqli_read_slave_test.php index 60924169de4..e415957a0d8 100644 --- a/lib/dml/tests/dml_mysqli_read_slave_test.php +++ b/lib/dml/tests/dml_mysqli_read_slave_test.php @@ -21,7 +21,6 @@ * @category dml * @copyright 2018 Srdjan Janković, Catalyst IT * @license http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later - * @coversDefaultClass \mysqli_native_moodle_database */ namespace core; @@ -37,6 +36,7 @@ require_once(__DIR__.'/fixtures/read_slave_moodle_database_mock_mysqli.php'); * @category dml * @copyright 2018 Catalyst IT * @license http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later + * @covers \mysqli_native_moodle_database */ class dml_mysqli_read_slave_test extends \base_testcase { /** diff --git a/lib/dml/tests/dml_pgsql_read_slave_test.php b/lib/dml/tests/dml_pgsql_read_slave_test.php index 1ad15bf77f8..d98b51a83d3 100644 --- a/lib/dml/tests/dml_pgsql_read_slave_test.php +++ b/lib/dml/tests/dml_pgsql_read_slave_test.php @@ -21,7 +21,6 @@ * @category dml * @copyright 2018 Srdjan Janković, Catalyst IT * @license http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later - * @coversDefaultClass \pgsql_native_moodle_database */ namespace core; @@ -37,6 +36,7 @@ require_once(__DIR__.'/fixtures/read_slave_moodle_database_mock_pgsql.php'); * @category dml * @copyright 2018 Catalyst IT * @license http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later + * @covers \pgsql_native_moodle_database */ class dml_pgsql_read_slave_test extends \base_testcase { /** diff --git a/lib/dml/tests/dml_read_slave_test.php b/lib/dml/tests/dml_read_slave_test.php index f9b5b070a94..88e294e26a6 100644 --- a/lib/dml/tests/dml_read_slave_test.php +++ b/lib/dml/tests/dml_read_slave_test.php @@ -21,7 +21,6 @@ * @category dml * @copyright 2018 Srdjan Janković, Catalyst IT * @license http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later - * @coversDefaultClass \moodle_temptables */ namespace core; @@ -39,13 +38,12 @@ require_once(__DIR__.'/../../tests/fixtures/event_fixtures.php'); * @category dml * @copyright 2018 Catalyst IT * @license http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later + * @covers \moodle_read_slave_trait */ class dml_read_slave_test extends \base_testcase { /** @var float */ static private $dbreadonlylatency = 0.8; - /** @var float */ - static private $defaultlatency = 1; /** * Instantiates a test database interface object. @@ -335,6 +333,50 @@ class dml_read_slave_test extends \base_testcase { } } + /** + * Test readonly handle is not used immediately after update + * Test last written time is adjusted post-write, + * so the latency parameter is applied properly. + * + * @return void + * @covers ::can_use_readonly + * @covers ::query_end + */ + public function test_long_update(): void { + $DB = $this->new_db(true); + + $this->assertNull($DB->get_dbhwrite()); + + $skip = false; + + list($sql, $params, $ptype) = $DB->fix_sql_params("UPDATE {table} SET a = 1 WHERE id = 1"); + $DB->with_query_start_end($sql, $params, SQL_QUERY_UPDATE, function ($dbh) use (&$now) { + sleep(1); + $now = microtime(true); + }); + + // This condition should always evaluate true, however we need to + // safeguard from an unaccounted delay that can break this test. + if (microtime(true) - $now < self::$dbreadonlylatency) { + // Not enough time passed, use rw handle. + $handle = $DB->get_records_sql("SELECT * FROM {table}"); + $this->assertEquals('test_rw::test:test', $handle); + + // Make sure enough time passes. + sleep(1); + } else { + $skip = true; + } + + // Exceeded latency time, use ro handle. + $handle = $DB->get_records_sql("SELECT * FROM {table}"); + $this->assert_readonly_handle($handle); + + if ($skip) { + $this->markTestSkipped("Delay too long to test write handle immediately after transaction"); + } + } + /** * Test readonly handle is not used with events * when the latency parameter is applied properly. diff --git a/lib/dml/tests/fixtures/read_slave_moodle_database.php b/lib/dml/tests/fixtures/read_slave_moodle_database.php index db41bd977d2..7659854c7b3 100644 --- a/lib/dml/tests/fixtures/read_slave_moodle_database.php +++ b/lib/dml/tests/fixtures/read_slave_moodle_database.php @@ -93,11 +93,15 @@ class read_slave_moodle_database extends test_moodle_database { * @param string $sql * @param array $params * @param int $querytype + * @param ?callable $callback * @return string $handle handle property */ - private function with_query_start_end($sql, array $params = null, $querytype) { + public function with_query_start_end($sql, array $params = null, $querytype, $callback = null) { $this->query_start($sql, $params, $querytype); $ret = $this->handle; + if ($callback) { + call_user_func($callback, $ret); + } $this->query_end(null); return $ret; } diff --git a/lib/dml/tests/fixtures/test_moodle_read_slave_trait.php b/lib/dml/tests/fixtures/test_moodle_read_slave_trait.php index 087e6e94f4c..6172c3c174e 100644 --- a/lib/dml/tests/fixtures/test_moodle_read_slave_trait.php +++ b/lib/dml/tests/fixtures/test_moodle_read_slave_trait.php @@ -48,6 +48,7 @@ trait test_moodle_read_slave_trait { $ro = fopen("php://memory", 'r+'); fputs($ro, 'ro'); + $this->prefix = 'test_'; // Default, not to leave empty. $this->wantreadslave = true; $this->dbhwrite = $rw; $this->dbhreadonly = $ro; @@ -107,6 +108,7 @@ trait test_moodle_read_slave_trait { * @param mixed $result */ public function query_end($result) { + parent::query_end($result); $this->set_db_handle($this->dbhwrite); }