diff --git a/search/classes/engine.php b/search/classes/engine.php index a3eed8dafe8..52a7ab8d102 100644 --- a/search/classes/engine.php +++ b/search/classes/engine.php @@ -215,6 +215,7 @@ abstract class engine { $lastindexeddoc = 0; $firstindexeddoc = 0; $partial = false; + $lastprogress = manager::get_current_time(); foreach ($iterator as $document) { // Stop if we have exceeded the time limit (and there are still more items). Always @@ -250,6 +251,17 @@ abstract class engine { $firstindexeddoc = $lastindexeddoc; } $numrecords++; + + // If indexing the area takes a long time, periodically output progress information. + if (isset($options['progress'])) { + $now = manager::get_current_time(); + if ($now - $lastprogress >= manager::DISPLAY_INDEXING_PROGRESS_EVERY) { + $lastprogress = $now; + // The first date format is the same used in cron_trace_time_and_memory(). + $options['progress']->output(date('H:i:s', $now) . ': Done to ' . userdate( + $lastindexeddoc, get_string('strftimedatetimeshort', 'langconfig')), 1); + } + } } return array($numrecords, $numdocs, $numdocsignored, $lastindexeddoc, $partial); diff --git a/search/classes/manager.php b/search/classes/manager.php index fc5a7188e10..0e25dec9163 100644 --- a/search/classes/manager.php +++ b/search/classes/manager.php @@ -77,6 +77,16 @@ class manager { */ const NO_OWNER_ID = 0; + /** + * @var float If initial query takes longer than N seconds, this will be shown in cron log. + */ + const DISPLAY_LONG_QUERY_TIME = 5.0; + + /** + * @var float Adds indexing progress within one search area to cron log every N seconds. + */ + const DISPLAY_INDEXING_PROGRESS_EVERY = 30.0; + /** * @var \core_search\base[] Enabled search areas. */ @@ -715,6 +725,11 @@ class manager { // Getting the recordset from the area. $recordset = $searcharea->get_recordset_by_timestamp($referencestarttime); + $initialquerytime = self::get_current_time() - $elapsed; + if ($initialquerytime > self::DISPLAY_LONG_QUERY_TIME) { + $progress->output('Initial query took ' . round($initialquerytime, 1) . + ' seconds.', 1); + } // Pass get_document as callback. $fileindexing = $this->engine->file_indexing_enabled() && $searcharea->uses_file_indexing(); @@ -722,6 +737,7 @@ class manager { if ($timelimit) { $options['stopat'] = $stopat; } + $options['progress'] = $progress; $iterator = new skip_future_documents_iterator(new \core\dml\recordset_walk( $recordset, array($searcharea, 'get_document'), $options)); $result = $this->engine->add_documents($iterator, $searcharea, $options); @@ -737,10 +753,16 @@ class manager { } if ($numdocs > 0) { - $elapsed = round((self::get_current_time() - $elapsed), 3); + $elapsed = round((self::get_current_time() - $elapsed), 1); + + $partialtext = ''; + if ($partial) { + $partialtext = ' (not complete; done to ' . userdate($lastindexeddoc, + get_string('strftimedatetimeshort', 'langconfig')) . ')'; + } + $progress->output('Processed ' . $numrecords . ' records containing ' . $numdocs . - ' documents, in ' . $elapsed . ' seconds' . - ($partial ? ' (not complete)' : '') . '.', 1); + ' documents, in ' . $elapsed . ' seconds' . $partialtext . '.', 1); } else { $progress->output('No new documents to index.', 1); } diff --git a/search/tests/fixtures/mock_search_area.php b/search/tests/fixtures/mock_search_area.php index 1ed17d3402e..778fe35ed48 100644 --- a/search/tests/fixtures/mock_search_area.php +++ b/search/tests/fixtures/mock_search_area.php @@ -29,6 +29,9 @@ defined('MOODLE_INTERNAL') || die; class mock_search_area extends \core_search\base { + /** @var float If set, waits when doing the indexing query (seconds) */ + protected $indexingdelay = 0; + /** * Multiple context level so we can test get_areas_user_accesses. * @var int[] @@ -47,6 +50,11 @@ class mock_search_area extends \core_search\base { public function get_recordset_by_timestamp($modifiedfrom = 0) { global $DB; + if ($this->indexingdelay) { + \testable_core_search::fake_current_time( + \core_search\manager::get_current_time() + $this->indexingdelay); + } + $sql = "SELECT * FROM {temp_mock_search_area} WHERE timemodified >= ? ORDER BY timemodified ASC"; return $DB->get_recordset_sql($sql, array($modifiedfrom)); } @@ -126,4 +134,14 @@ class mock_search_area extends \core_search\base { public function get_visible_name($lazyload = false) { return 'Mock search area'; } + + /** + * Sets a fake delay to simulate time taken doing the indexing query. + * + * @param float $seconds Delay in seconds for each time indexing query is called + */ + public function set_indexing_delay($seconds) { + $this->indexingdelay = $seconds; + } + } diff --git a/search/tests/manager_test.php b/search/tests/manager_test.php index 95fa82c1f47..36113ddf6e0 100644 --- a/search/tests/manager_test.php +++ b/search/tests/manager_test.php @@ -280,6 +280,90 @@ class search_manager_testcase extends advanced_testcase { $this->assertFalse(get_config($componentname, $varname . '_partial')); } + /** + * Tests the progress display while indexing. + * + * This tests the different logic about displaying progress for slow/fast and + * complete/incomplete processing. + */ + public function test_index_progress() { + $this->resetAfterTest(); + $generator = $this->getDataGenerator(); + + // Set up the fake search area. + $search = testable_core_search::instance(); + $area = new \core_mocksearch\search\mock_search_area(); + $search->add_search_area('whatever', $area); + $searchgenerator = $generator->get_plugin_generator('core_search'); + $searchgenerator->setUp(); + + // Add records with specific time modified values. + $time = strtotime('2017-11-01 01:00'); + for ($i = 0; $i < 8; $i ++) { + $searchgenerator->create_record((object)['timemodified' => $time]); + $time += 60; + } + + // Simulate slow progress on indexing and initial query. + $now = strtotime('2017-11-11 01:00'); + \testable_core_search::fake_current_time($now); + $area->set_indexing_delay(10.123); + $search->get_engine()->set_add_delay(15.789); + + // Run search indexing and check output. + $progress = new progress_trace_buffer(new text_progress_trace(), false); + $search->index(false, 75, $progress); + $out = $progress->get_buffer(); + $progress->reset_buffer(); + + // Check for the standard text. + $this->assertContains('Processing area: Mock search area', $out); + $this->assertContains('Stopping indexing due to time limit', $out); + + // Check for initial query performance indication. + $this->assertContains('Initial query took 10.1 seconds.', $out); + + // Check for the two (approximately) every-30-seconds messages. + $this->assertContains('01:00:41: Done to 1/11/17, 01:01', $out); + $this->assertContains('01:01:13: Done to 1/11/17, 01:03', $out); + + // Check for the 'not complete' indicator showing when it was done until. + $this->assertContains('Processed 5 records containing 5 documents, in 89.1 seconds ' . + '(not complete; done to 1/11/17, 01:04)', $out); + + // Make the initial query delay less than 5 seconds, so it won't appear. Make the documents + // quicker, so that the 30-second delay won't be needed. + $area->set_indexing_delay(4.9); + $search->get_engine()->set_add_delay(1); + + // Run search indexing (still partial) and check output. + $progress = new progress_trace_buffer(new text_progress_trace(), false); + $search->index(false, 5, $progress); + $out = $progress->get_buffer(); + $progress->reset_buffer(); + + $this->assertContains('Processing area: Mock search area', $out); + $this->assertContains('Stopping indexing due to time limit', $out); + $this->assertNotContains('Initial query took', $out); + $this->assertNotContains(': Done to', $out); + $this->assertContains('Processed 2 records containing 2 documents, in 6.9 seconds ' . + '(not complete; done to 1/11/17, 01:05).', $out); + + // Run the remaining items to complete it. + $progress = new progress_trace_buffer(new text_progress_trace(), false); + $search->index(false, 100, $progress); + $out = $progress->get_buffer(); + $progress->reset_buffer(); + + $this->assertContains('Processing area: Mock search area', $out); + $this->assertNotContains('Stopping indexing due to time limit', $out); + $this->assertNotContains('Initial query took', $out); + $this->assertNotContains(': Done to', $out); + $this->assertContains('Processed 3 records containing 3 documents, in 7.9 seconds.', $out); + + $searchgenerator->tearDown(); + } + /** * Tests that documents with modified time in the future are NOT indexed (as this would cause * a problem by preventing it from indexing other documents modified between now and the future