diff --git a/lib/upgradelib.php b/lib/upgradelib.php index c5703cfe0ce..304d712cfb0 100644 --- a/lib/upgradelib.php +++ b/lib/upgradelib.php @@ -169,18 +169,45 @@ class plugin_misplaced_exception extends moodle_exception { class core_upgrade_time { /** @var float Time at start of current upgrade (plugin/system) */ protected static $before; - /** @var float Time at end of last savepoint */ - protected static $lastsavepoint; + /** @var float Time at end of last recorded savepoint or detail */ + protected static $lastdetail; /** @var bool Flag to indicate whether we are recording timestamps or not. */ protected static $isrecording = false; + /** @var bool Flag indicates whether this is an installation (=no savepoints) */ + protected static $installation = false; + + /** @var float For details, only show if they take longer than a second. */ + const THRESHOLD = 1.0; /** * Records current time at the start of the current upgrade item, e.g. plugin. + * + * @param bool $installation True if this is an installation (of this item) not upgrade */ - public static function record_start() { + public static function record_start(bool $installation = false): void { self::$before = microtime(true); - self::$lastsavepoint = self::$before; + self::$lastdetail = self::$before; self::$isrecording = true; + self::$installation = $installation; + } + + /** + * Records the end of the current upgrade item. + * + * @param bool $verbose If true, displays output + */ + public static function record_end(bool $verbose = true): void { + global $OUTPUT; + + if ($verbose) { + $duration = self::get_elapsed(); + $message = get_string('successduration', '', format_float($duration, 2)); + $notification = new \core\output\notification($message, \core\output\notification::NOTIFY_SUCCESS); + $notification->set_show_closebutton(false); + echo $OUTPUT->render($notification); + } + + self::$isrecording = false; } /** @@ -189,18 +216,43 @@ class core_upgrade_time { * @param float $version Version number (may have decimals, or not) */ public static function record_savepoint($version) { + // Skip savepoints during installation because there is always exactly one and it's not + // interesting. + if (self::$installation) { + return; + } + // We show the time taken by each savepoint even if it's quick, because it could be useful + // just to see the list of upgrade steps completed, so pass $showalways = true. + self::record_detail($version, true); + } + + /** + * Records time taken by a detail of the install process. Time is only displayed if longer than + * threshold, and if in developer debug mode. + * + * @param string $detail Text e.g. file or function name + * @param bool $showalways If true, shows time even if quick + */ + public static function record_detail(string $detail, bool $showalways = false): void { global $CFG, $OUTPUT; - // In developer debug mode we show a notification after each individual save point. + // In developer debug mode we show a notification after each detail. if ($CFG->debugdeveloper && self::$isrecording) { + // Calculate time taken since previous detail. $time = microtime(true); + $duration = $time - self::$lastdetail; - $notification = new \core\output\notification($version . ': ' . - get_string('successduration', '', format_float($time - self::$lastsavepoint, 2)), - \core\output\notification::NOTIFY_SUCCESS); - $notification->set_show_closebutton(false); - echo $OUTPUT->render($notification); - self::$lastsavepoint = $time; + // Display the time if significant, and always for savepoints. + if ($duration > self::THRESHOLD || $showalways) { + $notification = new \core\output\notification($detail . ': ' . + get_string('successduration', '', format_float($duration, 2)), + \core\output\notification::NOTIFY_SUCCESS); + $notification->set_show_closebutton(false); + echo $OUTPUT->render($notification); + } + + // Record the time. + self::$lastdetail = $time; } } @@ -568,6 +620,46 @@ function upgrade_stale_php_files_present(): bool { return false; } +/** + * After upgrading a module, block, or generic plugin, various parts of the system need to be + * informed. + * + * @param string $component Frankenstyle component or 'moodle' for core + * @param string $messageplug Set to the name of a message plugin if this is one + * @param bool $coreinstall Set to true if this is the core install + */ +function upgrade_component_updated(string $component, string $messageplug = '', + bool $coreinstall = false): void { + if (!$coreinstall) { + update_capabilities($component); + core_upgrade_time::record_detail('update_capabilities'); + } + log_update_descriptions($component); + core_upgrade_time::record_detail('log_update_descriptions'); + external_update_descriptions($component); + core_upgrade_time::record_detail('external_update_descriptions'); + \core\task\manager::reset_scheduled_tasks_for_component($component); + core_upgrade_time::record_detail('\core\task\manager::reset_scheduled_tasks_for_component'); + \core_analytics\manager::update_default_models_for_component($component); + core_upgrade_time::record_detail('\core_analytics\manager::update_default_models_for_component'); + message_update_providers($component); + core_upgrade_time::record_detail('message_update_providers'); + \core\message\inbound\manager::update_handlers_for_component($component); + core_upgrade_time::record_detail('\core\message\inbound\manager::update_handlers_for_component'); + if ($messageplug !== '') { + // Ugly hack! + message_update_processors($messageplug); + core_upgrade_time::record_detail('message_update_processors'); + } + if ($component !== 'moodle') { + // This one is not run for core upgrades. + upgrade_plugin_mnet_functions($component); + core_upgrade_time::record_detail('upgrade_plugin_mnet_functions'); + } + core_tag_area::reset_definitions_for_component($component); + core_upgrade_time::record_detail('core_tag_area::reset_definitions_for_component'); +} + /** * Upgrade plugins * @param string $type The type of plugins that should be updated (e.g. 'enrol', 'qtype') @@ -644,18 +736,7 @@ function upgrade_plugins($type, $startcallback, $endcallback, $verbose) { $startcallback($component, true, $verbose); $recover_install_function(); unset_config('installrunning', $plugin->fullname); - update_capabilities($component); - log_update_descriptions($component); - external_update_descriptions($component); - \core\task\manager::reset_scheduled_tasks_for_component($component); - \core_analytics\manager::update_default_models_for_component($component); - message_update_providers($component); - \core\message\inbound\manager::update_handlers_for_component($component); - if ($type === 'message') { - message_update_processors($plug); - } - upgrade_plugin_mnet_functions($component); - core_tag_area::reset_definitions_for_component($component); + upgrade_component_updated($component, $type === 'message' ? $plug : ''); $endcallback($component, true, $verbose); } } @@ -668,6 +749,7 @@ function upgrade_plugins($type, $startcallback, $endcallback, $verbose) { /// Install tables if defined if (file_exists($fullplug.'/db/install.xml')) { $DB->get_manager()->install_from_xmldb_file($fullplug.'/db/install.xml'); + core_upgrade_time::record_detail('install.xml'); } /// store version @@ -680,21 +762,11 @@ function upgrade_plugins($type, $startcallback, $endcallback, $verbose) { $post_install_function = 'xmldb_'.$plugin->fullname.'_install'; $post_install_function(); unset_config('installrunning', $plugin->fullname); + core_upgrade_time::record_detail('install.php'); } /// Install various components - update_capabilities($component); - log_update_descriptions($component); - external_update_descriptions($component); - \core\task\manager::reset_scheduled_tasks_for_component($component); - \core_analytics\manager::update_default_models_for_component($component); - message_update_providers($component); - \core\message\inbound\manager::update_handlers_for_component($component); - if ($type === 'message') { - message_update_processors($plug); - } - upgrade_plugin_mnet_functions($component); - core_tag_area::reset_definitions_for_component($component); + upgrade_component_updated($component, $type === 'message' ? $plug : ''); $endcallback($component, true, $verbose); } else if ($installedversion < $plugin->version) { // upgrade @@ -706,6 +778,7 @@ function upgrade_plugins($type, $startcallback, $endcallback, $verbose) { $newupgrade_function = 'xmldb_'.$plugin->fullname.'_upgrade'; $result = $newupgrade_function($installedversion); + core_upgrade_time::record_detail('upgrade.php'); } else { $result = true; } @@ -717,19 +790,7 @@ function upgrade_plugins($type, $startcallback, $endcallback, $verbose) { } /// Upgrade various components - update_capabilities($component); - log_update_descriptions($component); - external_update_descriptions($component); - \core\task\manager::reset_scheduled_tasks_for_component($component); - \core_analytics\manager::update_default_models_for_component($component); - message_update_providers($component); - \core\message\inbound\manager::update_handlers_for_component($component); - if ($type === 'message') { - // Ugly hack! - message_update_processors($plug); - } - upgrade_plugin_mnet_functions($component); - core_tag_area::reset_definitions_for_component($component); + upgrade_component_updated($component, $type === 'message' ? $plug : ''); $endcallback($component, false, $verbose); } else if ($installedversion > $plugin->version) { @@ -825,15 +886,7 @@ function upgrade_plugins_modules($startcallback, $endcallback, $verbose) { $recover_install_function(); unset_config('installrunning', $module->name); // Install various components too - update_capabilities($component); - log_update_descriptions($component); - external_update_descriptions($component); - \core\task\manager::reset_scheduled_tasks_for_component($component); - \core_analytics\manager::update_default_models_for_component($component); - message_update_providers($component); - \core\message\inbound\manager::update_handlers_for_component($component); - upgrade_plugin_mnet_functions($component); - core_tag_area::reset_definitions_for_component($component); + upgrade_component_updated($component); $endcallback($component, true, $verbose); } } @@ -844,9 +897,11 @@ function upgrade_plugins_modules($startcallback, $endcallback, $verbose) { /// Execute install.xml (XMLDB) - must be present in all modules $DB->get_manager()->install_from_xmldb_file($fullmod.'/db/install.xml'); + core_upgrade_time::record_detail('install.xml'); /// Add record into modules table - may be needed in install.php already $module->id = $DB->insert_record('modules', $module); + core_upgrade_time::record_detail('insert_record'); upgrade_mod_savepoint(true, $plugin->version, $module->name, false); /// Post installation hook - optional @@ -857,18 +912,11 @@ function upgrade_plugins_modules($startcallback, $endcallback, $verbose) { $post_install_function = 'xmldb_'.$module->name.'_install'; $post_install_function(); unset_config('installrunning', $module->name); + core_upgrade_time::record_detail('install.php'); } /// Install various components - update_capabilities($component); - log_update_descriptions($component); - external_update_descriptions($component); - \core\task\manager::reset_scheduled_tasks_for_component($component); - \core_analytics\manager::update_default_models_for_component($component); - message_update_providers($component); - \core\message\inbound\manager::update_handlers_for_component($component); - upgrade_plugin_mnet_functions($component); - core_tag_area::reset_definitions_for_component($component); + upgrade_component_updated($component); $endcallback($component, true, $verbose); @@ -880,6 +928,7 @@ function upgrade_plugins_modules($startcallback, $endcallback, $verbose) { require_once($fullmod.'/db/upgrade.php'); // defines new upgrading function $newupgrade_function = 'xmldb_'.$module->name.'_upgrade'; $result = $newupgrade_function($installedversion, $module); + core_upgrade_time::record_detail('upgrade.php'); } else { $result = true; } @@ -897,15 +946,7 @@ function upgrade_plugins_modules($startcallback, $endcallback, $verbose) { } // Upgrade various components - update_capabilities($component); - log_update_descriptions($component); - external_update_descriptions($component); - \core\task\manager::reset_scheduled_tasks_for_component($component); - \core_analytics\manager::update_default_models_for_component($component); - message_update_providers($component); - \core\message\inbound\manager::update_handlers_for_component($component); - upgrade_plugin_mnet_functions($component); - core_tag_area::reset_definitions_for_component($component); + upgrade_component_updated($component); $endcallback($component, false, $verbose); @@ -1019,15 +1060,7 @@ function upgrade_plugins_blocks($startcallback, $endcallback, $verbose) { $recover_install_function(); unset_config('installrunning', 'block_'.$blockname); // Install various components - update_capabilities($component); - log_update_descriptions($component); - external_update_descriptions($component); - \core\task\manager::reset_scheduled_tasks_for_component($component); - \core_analytics\manager::update_default_models_for_component($component); - message_update_providers($component); - \core\message\inbound\manager::update_handlers_for_component($component); - upgrade_plugin_mnet_functions($component); - core_tag_area::reset_definitions_for_component($component); + upgrade_component_updated($component); $endcallback($component, true, $verbose); } } @@ -1044,8 +1077,10 @@ function upgrade_plugins_blocks($startcallback, $endcallback, $verbose) { if (file_exists($fullblock.'/db/install.xml')) { $DB->get_manager()->install_from_xmldb_file($fullblock.'/db/install.xml'); + core_upgrade_time::record_detail('install.xml'); } $block->id = $DB->insert_record('block', $block); + core_upgrade_time::record_detail('insert_record'); upgrade_block_savepoint(true, $plugin->version, $block->name, false); if (file_exists($fullblock.'/db/install.php')) { @@ -1055,20 +1090,13 @@ function upgrade_plugins_blocks($startcallback, $endcallback, $verbose) { $post_install_function = 'xmldb_block_'.$blockname.'_install'; $post_install_function(); unset_config('installrunning', 'block_'.$blockname); + core_upgrade_time::record_detail('install.php'); } $blocktitles[$block->name] = $blocktitle; // Install various components - update_capabilities($component); - log_update_descriptions($component); - external_update_descriptions($component); - \core\task\manager::reset_scheduled_tasks_for_component($component); - \core_analytics\manager::update_default_models_for_component($component); - message_update_providers($component); - \core\message\inbound\manager::update_handlers_for_component($component); - core_tag_area::reset_definitions_for_component($component); - upgrade_plugin_mnet_functions($component); + upgrade_component_updated($component); $endcallback($component, true, $verbose); @@ -1079,6 +1107,7 @@ function upgrade_plugins_blocks($startcallback, $endcallback, $verbose) { require_once($fullblock.'/db/upgrade.php'); // defines new upgrading function $newupgrade_function = 'xmldb_block_'.$blockname.'_upgrade'; $result = $newupgrade_function($installedversion, $block); + core_upgrade_time::record_detail('upgrade.php'); } else { $result = true; } @@ -1096,15 +1125,7 @@ function upgrade_plugins_blocks($startcallback, $endcallback, $verbose) { } // Upgrade various components - update_capabilities($component); - log_update_descriptions($component); - external_update_descriptions($component); - \core\task\manager::reset_scheduled_tasks_for_component($component); - \core_analytics\manager::update_default_models_for_component($component); - message_update_providers($component); - \core\message\inbound\manager::update_handlers_for_component($component); - upgrade_plugin_mnet_functions($component); - core_tag_area::reset_definitions_for_component($component); + upgrade_component_updated($component); $endcallback($component, false, $verbose); @@ -1646,6 +1667,7 @@ function print_upgrade_part_start($plugin, $installation, $verbose) { echo $OUTPUT->heading($plugin); } } + core_upgrade_time::record_start($installation); if ($installation) { if (empty($plugin) or $plugin == 'moodle') { // no need to log - log table not yet there ;-) @@ -1653,7 +1675,6 @@ function print_upgrade_part_start($plugin, $installation, $verbose) { upgrade_log(UPGRADE_LOG_NORMAL, $plugin, 'Starting plugin installation'); } } else { - core_upgrade_time::record_start(); if (empty($plugin) or $plugin == 'moodle') { upgrade_log(UPGRADE_LOG_NORMAL, $plugin, 'Starting core upgrade'); } else { @@ -1684,15 +1705,7 @@ function print_upgrade_part_end($plugin, $installation, $verbose) { } } if ($verbose) { - if ($installation) { - $message = get_string('success'); - } else { - $duration = core_upgrade_time::get_elapsed(); - $message = get_string('successduration', '', format_float($duration, 2)); - } - $notification = new \core\output\notification($message, \core\output\notification::NOTIFY_SUCCESS); - $notification->set_show_closebutton(false); - echo $OUTPUT->render($notification); + core_upgrade_time::record_end(); print_upgrade_separator(); } } @@ -1805,26 +1818,25 @@ function install_core($version, $verbose) { print_upgrade_part_start('moodle', true, $verbose); // does not store upgrade running flag $DB->get_manager()->install_from_xmldb_file("$CFG->libdir/db/install.xml"); + core_upgrade_time::record_detail('install.xml'); upgrade_started(); // we want the flag to be stored in config table ;-) + core_upgrade_time::record_detail('upgrade_started'); // set all core default records and default settings require_once("$CFG->libdir/db/install.php"); + core_upgrade_time::record_detail('install.php'); xmldb_main_install(); // installs the capabilities too + core_upgrade_time::record_detail('xmldb_main_install'); // store version upgrade_main_savepoint(true, $version, false); // Continue with the installation - log_update_descriptions('moodle'); - external_update_descriptions('moodle'); - \core\task\manager::reset_scheduled_tasks_for_component('moodle'); - \core_analytics\manager::update_default_models_for_component('moodle'); - message_update_providers('moodle'); - \core\message\inbound\manager::update_handlers_for_component('moodle'); - core_tag_area::reset_definitions_for_component('moodle'); + upgrade_component_updated('moodle', '', true); // Write default settings unconditionally admin_apply_default_settings(NULL, true); + core_upgrade_time::record_detail('admin_apply_default_settings'); print_upgrade_part_end(null, true, $verbose); @@ -1869,9 +1881,11 @@ function upgrade_core($version, $verbose) { require($preupgradefile); // Reset upgrade timeout to default. upgrade_set_timeout(); + core_upgrade_time::record_detail('local/preupgrade.php'); } $result = xmldb_main_upgrade($CFG->version); + core_upgrade_time::record_detail('xmldb_main_upgrade'); if ($version > $CFG->version) { // store version if not already there upgrade_main_savepoint($result, $version, false); @@ -1882,27 +1896,27 @@ function upgrade_core($version, $verbose) { $COURSE = clone($SITE); // perform all other component upgrade routines - update_capabilities('moodle'); - log_update_descriptions('moodle'); - external_update_descriptions('moodle'); - \core\task\manager::reset_scheduled_tasks_for_component('moodle'); - \core_analytics\manager::update_default_models_for_component('moodle'); - message_update_providers('moodle'); - \core\message\inbound\manager::update_handlers_for_component('moodle'); - core_tag_area::reset_definitions_for_component('moodle'); + upgrade_component_updated('moodle'); // Update core definitions. cache_helper::update_definitions(true); + core_upgrade_time::record_detail('cache_helper::update_definitions'); // Purge caches again, just to be sure we arn't holding onto old stuff now. cache_helper::purge_all(true); + core_upgrade_time::record_detail('cache_helper::purge_all'); purge_all_caches(); + core_upgrade_time::record_detail('purge_all_caches'); // Clean up contexts - more and more stuff depends on existence of paths and contexts context_helper::cleanup_instances(); + core_upgrade_time::record_detail('context_helper::cleanup_instance'); context_helper::create_instances(null, false); + core_upgrade_time::record_detail('context_helper::create_instances'); context_helper::build_all_paths(false); + core_upgrade_time::record_detail('context_helper::build_all_paths'); $syscontext = context_system::instance(); $syscontext->mark_dirty(); + core_upgrade_time::record_detail('context_system::mark_dirty'); print_upgrade_part_end('moodle', false, $verbose); } catch (Exception $ex) { @@ -1919,7 +1933,7 @@ function upgrade_core($version, $verbose) { * @return void, may throw exception */ function upgrade_noncore($verbose) { - global $CFG; + global $CFG, $OUTPUT; raise_memory_limit(MEMORY_EXTRA); @@ -1933,19 +1947,32 @@ function upgrade_noncore($verbose) { foreach ($plugintypes as $type=>$location) { upgrade_plugins($type, 'print_upgrade_part_start', 'print_upgrade_part_end', $verbose); } + if ($CFG->debugdeveloper) { + // Only show this heading in developer mode to go with the times below. + echo $OUTPUT->heading('upgrade_noncore()'); + } + core_upgrade_time::record_start(); // Upgrade services. // This function gives plugins and subsystems a chance to add functions to existing built-in services. external_update_services(); + core_upgrade_time::record_detail('external_update_services'); // Update cache definitions. Involves scanning each plugin for any changes. cache_helper::update_definitions(); + core_upgrade_time::record_detail('cache_helper::update_definitions'); + // Mark the site as upgraded. set_config('allversionshash', core_component::get_all_versions_hash()); + core_upgrade_time::record_detail('core_component::get_all_versions_hash'); // Purge caches again, just to be sure we arn't holding onto old stuff now. cache_helper::purge_all(true); + core_upgrade_time::record_detail('cache_helper::purge_all'); purge_all_caches(); + core_upgrade_time::record_detail('purge_all_caches'); + // Only display the final 'Success' if we also showed the heading. + core_upgrade_time::record_end($CFG->debugdeveloper); } catch (Exception $ex) { upgrade_handle_exception($ex); } catch (Throwable $ex) {