Issue #2716073 by moonray: Improve cron logging

core/lib/Drupal/Core/Cron.php

@@ -2,6 +2,7 @@
 
 namespace Drupal\Core;
 
+use Drupal\Component\Utility\Timer;
 use Drupal\Core\Extension\ModuleHandlerInterface;
 use Drupal\Core\Queue\QueueWorkerManagerInterface;
 use Drupal\Core\Queue\RequeueException;
@@ -192,8 +193,25 @@ protected function processQueues() {
    * Invokes any cron handlers implementing hook_cron.
    */
   protected function invokeCronHandlers() {
+    $module_previous = '';
+
     // Iterate through the modules calling their cron handlers (if any):
     foreach ($this->moduleHandler->getImplementations('cron') as $module) {
+
+      if (!$module_previous) {
+        $this->logger->notice('Starting execution of @module_cron().', [
+          '@module' => $module,
+        ]);
+      }
+      else {
+        $this->logger->notice('Starting execution of @module_cron(), execution of @module_previous_cron() took @time.', [
+          '@module' => $module,
+          '@module_previous' => $module_previous,
+          '@time' => Timer::read('cron_' . $module_previous) . 'ms',
+        ]);
+      }
+      Timer::start('cron_' . $module);
+
       // Do not let an exception thrown by one module disturb another.
       try {
         $this->moduleHandler->invoke($module, 'cron');
@@ -201,6 +219,9 @@ protected function invokeCronHandlers() {
       catch (\Exception $e) {
         watchdog_exception('cron', $e);
       }
+
+      Timer::stop('cron_' . $module);
+      $module_previous = $module;
     }
   }
 

core/modules/dblog/src/Tests/DbLogTest.php

@@ -114,12 +114,23 @@ private function verifyCron($row_limit) {
     $count = db_query('SELECT COUNT(wid) FROM {watchdog}')->fetchField();
     $this->assertTrue($count > $row_limit, format_string('Dblog row count of @count exceeds row limit of @limit', array('@count' => $count, '@limit' => $row_limit)));
 
+    // Get last ID to compare against; log entries get deleted, so we can't
+    // reliably add the number of newly created log entries to the current count
+    // to measure number of log entries created by cron.
+    $last_id = db_query('SELECT MAX(wid) FROM {watchdog}')->fetchField();
+
     // Run a cron job.
     $this->cronRun();
-    // Verify that the database log row count equals the row limit plus one
-    // because cron adds a record after it runs.
-    $count = db_query('SELECT COUNT(wid) FROM {watchdog}')->fetchField();
-    $this->assertTrue($count == $row_limit + 1, format_string('Dblog row count of @count equals row limit of @limit plus one', array('@count' => $count, '@limit' => $row_limit)));
+
+    // Get last ID after cron was run.
+    $current_id = db_query('SELECT MAX(wid) FROM {watchdog}')->fetchField();
+
+    // Get the number of enabled modules. Cron adds a log entry for each module.
+    $list = \Drupal::moduleHandler()->getImplementations('cron');
+    $module_count = count($list);
+
+    $count = $current_id - $last_id;
+    $this->assertTrue(($current_id - $last_id) == $module_count + 1, format_string('Cron added @count of @expected new log entries', array('@count' => $count, '@expected' => $module_count + 1)));
   }
 
   /**