From 82735dec4da08d9fa3dc5a15a986141d00fe1c8e Mon Sep 17 00:00:00 2001 From: sam marshall Date: Mon, 23 Oct 2017 18:09:10 +0100 Subject: [PATCH] MDL-60555 core_search: Change unit tests to use fake time Using real time caused rare failures. I've changed it to use fake measurement for the indexing timeouts, which were unit-tested. --- search/classes/engine.php | 2 +- search/classes/manager.php | 42 ++++++++++++++----- search/tests/fixtures/mock_search_engine.php | 4 +- .../tests/fixtures/testable_core_search.php | 10 +++++ search/tests/manager_test.php | 11 +++++ 5 files changed, 56 insertions(+), 13 deletions(-) diff --git a/search/classes/engine.php b/search/classes/engine.php index de5fff2534c..a3eed8dafe8 100644 --- a/search/classes/engine.php +++ b/search/classes/engine.php @@ -220,7 +220,7 @@ abstract class engine { // Stop if we have exceeded the time limit (and there are still more items). Always // do at least one second's worth of documents otherwise it will never make progress. if ($lastindexeddoc !== $firstindexeddoc && - !empty($options['stopat']) && microtime(true) >= $options['stopat']) { + !empty($options['stopat']) && manager::get_current_time() >= $options['stopat']) { $partial = true; break; } diff --git a/search/classes/manager.php b/search/classes/manager.php index ea9510807d1..8760bf46d9f 100644 --- a/search/classes/manager.php +++ b/search/classes/manager.php @@ -97,6 +97,13 @@ class manager { */ protected $engine = null; + /** + * Note: This should be removed once possible (see MDL-60644). + * + * @var float Fake current time for use in PHPunit tests + */ + protected static $phpunitfaketime = 0; + /** * Constructor, use \core_search\manager::instance instead to get a class instance. * @@ -669,7 +676,7 @@ class manager { }); // Decide time to stop. - $stopat = microtime(true) + $timelimit; + $stopat = self::get_current_time() + $timelimit; } foreach ($searchareas as $areaid => $searcharea) { @@ -680,7 +687,7 @@ class manager { $this->engine->area_index_starting($searcharea, $fullindex); $indexingstart = time(); - $elapsed = microtime(true); + $elapsed = self::get_current_time(); // This is used to store this component config. list($componentconfigname, $varname) = $searcharea->get_config_var_name(); @@ -730,7 +737,7 @@ class manager { } if ($numdocs > 0) { - $elapsed = round((microtime(true) - $elapsed), 3); + $elapsed = round((self::get_current_time() - $elapsed), 3); $progress->output('Processed ' . $numrecords . ' records containing ' . $numdocs . ' documents, in ' . $elapsed . ' seconds' . ($partial ? ' (not complete)' : '') . '.', 1); @@ -760,7 +767,7 @@ class manager { $progress->output('Engine reported error.'); } - if ($timelimit && (microtime(true) >= $stopat)) { + if ($timelimit && (self::get_current_time() >= $stopat)) { $progress->output('Stopping indexing due to time limit.'); break; } @@ -803,7 +810,7 @@ class manager { // Work out time to stop, if limited. if ($timelimit) { // Decide time to stop. - $stopat = microtime(true) + $timelimit; + $stopat = self::get_current_time() + $timelimit; } // No PHP time limit. @@ -840,7 +847,7 @@ class manager { $progress->output('Processing area: ' . $searcharea->get_visible_name()); - $elapsed = microtime(true); + $elapsed = self::get_current_time(); // Get the recordset of all documents from the area for this context. $recordset = $searcharea->get_document_recordset($referencestarttime, $context); @@ -881,7 +888,7 @@ class manager { } if ($numdocs > 0) { - $elapsed = round((microtime(true) - $elapsed), 3); + $elapsed = round((self::get_current_time() - $elapsed), 3); $progress->output('Processed ' . $numrecords . ' records containing ' . $numdocs . ' documents, in ' . $elapsed . ' seconds' . ($partial ? ' (not complete)' : '') . '.', 1); @@ -895,7 +902,7 @@ class manager { $progress->output('Engine reported error.', 1); } - if ($partial && $timelimit && (microtime(true) >= $stopat)) { + if ($partial && $timelimit && (self::get_current_time() >= $stopat)) { $progress->output('Stopping indexing due to time limit.'); break; } @@ -1107,7 +1114,7 @@ class manager { } $complete = false; - $before = microtime(true); + $before = self::get_current_time(); if ($timelimit) { $stopat = $before + $timelimit; } @@ -1125,7 +1132,7 @@ class manager { // Calculate remaining time. $remainingtime = 0; - $beforeindex = microtime(true); + $beforeindex = self::get_current_time(); if ($timelimit) { $remainingtime = $stopat - $beforeindex; } @@ -1143,7 +1150,7 @@ class manager { $progress, $request->partialarea, $request->partialtime); // Work out shared part of message. - $endmessage = $contextname . ' (' . round(microtime(true) - $beforeindex, 1) . 's)'; + $endmessage = $contextname . ' (' . round(self::get_current_time() - $beforeindex, 1) . 's)'; // Update database table and continue/stop as appropriate. if ($result->complete) { @@ -1163,4 +1170,17 @@ class manager { } } + /** + * Gets current time for use in search system. + * + * Note: This should be replaced with generic core functionality once possible (see MDL-60644). + * + * @return float Current time in seconds (with decimals) + */ + public static function get_current_time() { + if (PHPUNIT_TEST && self::$phpunitfaketime) { + return self::$phpunitfaketime; + } + return microtime(true); + } } diff --git a/search/tests/fixtures/mock_search_engine.php b/search/tests/fixtures/mock_search_engine.php index ad63e84bd7a..35ea923f9a3 100644 --- a/search/tests/fixtures/mock_search_engine.php +++ b/search/tests/fixtures/mock_search_engine.php @@ -25,6 +25,8 @@ namespace mock_search; * @license http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later */ +use core_search\manager; + defined('MOODLE_INTERNAL') || die; class engine extends \core_search\engine { @@ -45,7 +47,7 @@ class engine extends \core_search\engine { public function add_document($document, $fileindexing = false) { if ($this->adddelay) { - usleep($this->adddelay); + \testable_core_search::fake_current_time(manager::get_current_time() + $this->adddelay); } $this->added[] = $document; return true; diff --git a/search/tests/fixtures/testable_core_search.php b/search/tests/fixtures/testable_core_search.php index 941453155e6..65ae8ce3962 100644 --- a/search/tests/fixtures/testable_core_search.php +++ b/search/tests/fixtures/testable_core_search.php @@ -108,4 +108,14 @@ class testable_core_search extends \core_search\manager { return parent::is_search_area($classname); } + /** + * Fakes the current time for PHPunit. Turns off faking time if called with default parameter. + * + * Note: This should be replaced with core functionality once possible (see MDL-60644). + * + * @param float $faketime Current time + */ + public static function fake_current_time($faketime = 0.0) { + static::$phpunitfaketime = $faketime; + } } diff --git a/search/tests/manager_test.php b/search/tests/manager_test.php index 8db3d7bae1e..6ad9121f498 100644 --- a/search/tests/manager_test.php +++ b/search/tests/manager_test.php @@ -46,6 +46,12 @@ class search_manager_testcase extends advanced_testcase { $this->mycoursesareaid = \core_search\manager::generate_areaid('core_course', 'mycourse'); } + protected function tearDown() { + // Stop it from faking time in the search manager (if set by test). + testable_core_search::fake_current_time(); + parent::tearDown(); + } + public function test_search_enabled() { $this->resetAfterTest(); @@ -220,6 +226,9 @@ class search_manager_testcase extends advanced_testcase { // Make the search engine delay while indexing each document. $search->get_engine()->set_add_delay(1.2); + // Use fake time, starting from now. + testable_core_search::fake_current_time(time()); + // Index with a limit of 2 seconds - it should index 2 of the documents (after the second // one, it will have taken 2.4 seconds so it will stop). $search->index(false, 2); @@ -235,6 +244,7 @@ class search_manager_testcase extends advanced_testcase { // Wait to next second (so as to not reindex the label more than once, as it will now // be timed before the indexing run). $this->waitForSecond(); + testable_core_search::fake_current_time(time()); // Next index with 1 second limit should do the label and not the forum - the logic is, // if it spent ages indexing an area last time, do that one last on next run. @@ -850,6 +860,7 @@ class search_manager_testcase extends advanced_testcase { // Do the processing again with a time limit and indexing delay. The time limit is too // small; because of the way the logic works, this means it will index 2 activities. + testable_core_search::fake_current_time(time()); $search->get_engine()->set_add_delay(0.2); $search->process_index_requests(0.1, $progress); $out = $progress->get_buffer();