From 2280ea18f67f3ab79198d00aede717e4d62867ee Mon Sep 17 00:00:00 2001 From: sam marshall Date: Thu, 15 Sep 2022 14:26:05 +0100 Subject: [PATCH 1/2] MDL-75751 upgradelib: Refactor out duplicated component update code There are many places (install/upgrade for core, modules, blocks, and plugins) where we need to call the same, or very similar, sequence of Moodle functions to ensure the item is updated properly. This change moves that sequence into a function so that it can be held consistently in one place. --- lib/upgradelib.php | 147 +++++++++++++-------------------------------- 1 file changed, 41 insertions(+), 106 deletions(-) diff --git a/lib/upgradelib.php b/lib/upgradelib.php index f131719cf28..099d408e6ad 100644 --- a/lib/upgradelib.php +++ b/lib/upgradelib.php @@ -569,6 +569,36 @@ 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); + } + 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 ($messageplug !== '') { + // Ugly hack! + message_update_processors($messageplug); + } + if ($component !== 'moodle') { + // This one is not run for core upgrades. + upgrade_plugin_mnet_functions($component); + } + core_tag_area::reset_definitions_for_component($component); +} + /** * Upgrade plugins * @param string $type The type of plugins that should be updated (e.g. 'enrol', 'qtype') @@ -645,18 +675,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); } } @@ -684,18 +703,7 @@ function upgrade_plugins($type, $startcallback, $endcallback, $verbose) { } /// 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 @@ -718,19 +726,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) { @@ -826,15 +822,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); } } @@ -861,15 +849,7 @@ function upgrade_plugins_modules($startcallback, $endcallback, $verbose) { } /// 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); @@ -898,15 +878,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); @@ -1020,15 +992,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); } } @@ -1061,15 +1025,7 @@ function upgrade_plugins_blocks($startcallback, $endcallback, $verbose) { $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); @@ -1097,15 +1053,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); @@ -1816,13 +1764,7 @@ function install_core($version, $verbose) { 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); @@ -1883,14 +1825,7 @@ 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); From d6b4506a8bf4cd34f7aa1b03dcb6eaab6fee0e46 Mon Sep 17 00:00:00 2001 From: sam marshall Date: Thu, 15 Sep 2022 14:45:57 +0100 Subject: [PATCH 2/2] MDL-75751 upgradelib: Improve upgrade/install performance logging * Adds time logging (number of seconds for each success) on install, which was previously only shown in upgrades. Useful when installing a new plugin as part of an upgrade, or if anyone wants to optimise Moodle installation. * In developer debug mode, upgrade savepoint time was already logged but now it also logs time for lots of 'details' of the process in case time is taken in other Moodle function calls. --- lib/upgradelib.php | 136 +++++++++++++++++++++++++++++++++++++-------- 1 file changed, 114 insertions(+), 22 deletions(-) diff --git a/lib/upgradelib.php b/lib/upgradelib.php index 099d408e6ad..a227533a491 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; } } @@ -581,22 +633,32 @@ 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'); } /** @@ -688,6 +750,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 @@ -700,6 +763,7 @@ 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 @@ -715,6 +779,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; } @@ -833,9 +898,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 @@ -846,6 +913,7 @@ 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 @@ -861,6 +929,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; } @@ -1009,8 +1078,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')) { @@ -1020,6 +1091,7 @@ 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; @@ -1036,6 +1108,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; } @@ -1595,6 +1668,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 ;-) @@ -1602,7 +1676,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 { @@ -1633,15 +1706,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(); } } @@ -1754,11 +1819,15 @@ 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); @@ -1768,6 +1837,7 @@ function install_core($version, $verbose) { // 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); @@ -1812,9 +1882,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); @@ -1828,17 +1900,24 @@ function upgrade_core($version, $verbose) { 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) { @@ -1855,7 +1934,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); @@ -1869,19 +1948,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) {