L-electron-Rare/moodle
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

MDL-75751 upgradelib: Improve upgrade/install performance logging

Browse Source 
* 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.
This commit is contained in:
sam marshall
2022-10-10 17:09:14 +01:00
parent 2280ea18f6
commit d6b4506a8b
1 changed files with 114 additions and 22 deletions
Download Patch File Download Diff File Expand all files Collapse all files
lib/upgradelib.php
+114 -22
View File
@@ -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) {