MDL-60857 core_search: Improve cron log progress information

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);

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);
             }

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;
+    }
+
 }

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