Uploaded image for project: 'Moodle'
  1. Moodle
  2. MDL-75751

Upgrade: Improve upgrade/install performance logging

    XMLWordPrintable

Details

    • MOODLE_401_STABLE
    • MOODLE_401_STABLE
    • MDL-75751-master
    • Hide

      You will need to be able to run SQL against the database, and run CLI commands on the server, and edit the config.php used by the server, to carry out this test.

      The tests here include a selection of the possible permutations (upgrade/install, debugging on/off, CLI/web) rather than every possible one. I don't think it's necessary to test all of them.

      As part of this test we uninstall the 'big blue button' module which will remove all data from that module, so make sure you don't have any data you care about in that module. The test is still valid if you pick any other (uninstallable) module, so feel free to change it.

      A) Test upgrade (CLI)

      This fun SQL will make all parts of the system (all plugins + core) upgrade, hopefully without breaking it much:

      update mdl_config_plugins set value = (value::integer - 1) where name='version';
      update mdl_config set value = (value::integer - 1) where name='version';
      update mdl_config set value='0' where name='allversionshash';
      

      1 Set the Debug messages (debugging) admin setting under Site administration > Development > Debugging to 'ALL: ...' (not 'DEVELOPER: ...')
      2 Run the SQL above to subtract 1 from all version numbers
      3 Run these at the command line to purge cache and do the upgrade:

      php admin/cli/purge_caches.php --muc
      php admin/cli/upgrade.php --non-interactive --allow-unstable
      

      4 Check the log output is as expected:

      • There should be no errors
      • Each plugin should be listed like this (exactly the same as before):

      -->logstore_standard
      ++ Success (0.30 seconds) ++
      

      • There should be no upgrade_noncore section heading at the end.

      5 Set the Debug messages (debugging) admin setting under Site administration > Development > Debugging to 'DEVELOPER: ...'
      6 Run the SQL above to subtract 1 from all version numbers
      7 Run the same command as in step 3
      8 Check the log output is as expected:

      • There should be no errors.
      • Each plugin should be listed like this (the same as before):

      -->logstore_standard
      ++ 2022053000: Success (0.04 seconds) ++
      ++ Success (0.30 seconds) ++
      

      • It's possible, but not very likely, that some plugins will show additional lines apart from those two (there is a proper test of this later).
      • At the end there should be an upgrade_noncore section heading, with a 'Success' time. This might or might not contain any additional lines. Here's an example which does have an extra line:

      -->upgrade_noncore()
      ++ external_update_services: Success (1.38 seconds) ++
      ++ Success (2.70 seconds) ++
      

      B) Test fresh install (CLI)

      1 In your config.php, change the $CFG->prefix to a previously-unused value so that Moodle will install new database tables.
      2 Also in your config.php, add this line to enable debug display during install:

      $CFG->debug = 32767;
      

      3 Run the CLI install using a command like this (no I have not revealed my password, I just made that one up):

      php admin/cli/install_database.php  --agree-license --adminuser=admin --adminpass=secret0_frog --adminemail=lies@email.invalid --fullname=JUNK --shortname=JUNK --summary=JUNK
      

      4 Look at the output log.

      • There should be detail entries within the initial 'System' install, like this:

        == Setting up database ==
        -->System
        ++ install.xml: Success (19.51 seconds) ++
        ++ xmldb_main_install: Success (63.66 seconds) ++
        ++ admin_apply_default_settings: Success (81.25 seconds) ++
        ++ Success (166.90 seconds) ++
        

      • Each installed plugin should show the time taken:

        -->antivirus_clamav
        ++ Success (0.45 seconds) ++
        

      • Some plugins might show a detail entry (probably for update_capabilities), but this depends on your system performance.

      5 You should put back the changes in your config.php at this point (change back the prefix, remove the debug line).

      6 Optionally, go into your database and delete all the tables created with the temporary prefix you used.

      C) Test plugin installs, displaying all data (CLI)

      This test simulates adding plugins to an existing system. Because there is different upgrade code for blocks, modules, and everything else, we do one of each.

      To show all timing information regardless of performance, we will temporarily turn the display threshold down by editing code.

      1 Edit the file lib/upgradelib.php, search for THRESHOLD = 1.0, and change the 1.0 to 0.0.
      2 You should already be in DEVELOPER debugging mode, but if not, enable it.
      3 Run this CLI command to uninstall 3 existing plugins:

      php admin/cli/uninstall_plugins.php --plugins=mod_bigbluebuttonbn,block_accessreview,datafield_checkbox --run
      

      4 Run this at the command line to do the upgrade, which should install the 3 plugins again

      php admin/cli/upgrade.php --non-interactive --allow-unstable
      

      5 Check the log output is as expected, showing lots of detail lines:

      -->mod_bigbluebuttonbn
      ++ install.xml: Success (0.29 seconds) ++
      ++ insert_record: Success (0.08 seconds) ++
      ++ install.php: Success (0.10 seconds) ++
      ++ update_capabilities: Success (5.77 seconds) ++
      ++ log_update_descriptions: Success (0.05 seconds) ++
      ++ external_update_descriptions: Success (0.05 seconds) ++
      ++ \core\task\manager::reset_scheduled_tasks_for_component: Success (0.03 seconds) ++
      ++ \core_analytics\manager::update_default_models_for_component: Success (0.01 seconds) ++
      ++ message_update_providers: Success (0.12 seconds) ++
      ++ \core\message\inbound\manager::update_handlers_for_component: Success (0.01 seconds) ++
      ++ upgrade_plugin_mnet_functions: Success (0.03 seconds) ++
      ++ core_tag_area::reset_definitions_for_component: Success (0.01 seconds) ++
      ++ Success (6.56 seconds) ++
      -->block_accessreview
      ++ insert_record: Success (0.01 seconds) ++
      ++ update_capabilities: Success (1.31 seconds) ++
      ++ log_update_descriptions: Success (0.01 seconds) ++
      ++ external_update_descriptions: Success (0.01 seconds) ++
      ++ \core\task\manager::reset_scheduled_tasks_for_component: Success (0.01 seconds) ++
      ++ \core_analytics\manager::update_default_models_for_component: Success (0.01 seconds) ++
      ++ message_update_providers: Success (0.01 seconds) ++
      ++ \core\message\inbound\manager::update_handlers_for_component: Success (0.01 seconds) ++
      ++ upgrade_plugin_mnet_functions: Success (0.01 seconds) ++
      ++ core_tag_area::reset_definitions_for_component: Success (0.01 seconds) ++
      ++ Success (1.46 seconds) ++
      -->qbank_customfields
      ++ 2022041900: Success (0.04 seconds) ++
      ++ update_capabilities: Success (0.22 seconds) ++
      ++ log_update_descriptions: Success (0.01 seconds) ++
      ++ external_update_descriptions: Success (0.03 seconds) ++
      ++ \core\task\manager::reset_scheduled_tasks_for_component: Success (0.01 seconds) ++
      ++ \core_analytics\manager::update_default_models_for_component: Success (0.01 seconds) ++
      ++ message_update_providers: Success (0.01 seconds) ++
      ++ \core\message\inbound\manager::update_handlers_for_component: Success (0.01 seconds) ++
      ++ upgrade_plugin_mnet_functions: Success (0.01 seconds) ++
      ++ core_tag_area::reset_definitions_for_component: Success (0.01 seconds) ++
      ++ Success (0.42 seconds) ++
      -->datafield_checkbox
      ++ update_capabilities: Success (0.37 seconds) ++
      ++ log_update_descriptions: Success (0.01 seconds) ++
      ++ external_update_descriptions: Success (0.01 seconds) ++
      ++ \core\task\manager::reset_scheduled_tasks_for_component: Success (0.01 seconds) ++
      ++ \core_analytics\manager::update_default_models_for_component: Success (0.01 seconds) ++
      ++ message_update_providers: Success (0.01 seconds) ++
      ++ \core\message\inbound\manager::update_handlers_for_component: Success (0.01 seconds) ++
      ++ upgrade_plugin_mnet_functions: Success (0.01 seconds) ++
      ++ core_tag_area::reset_definitions_for_component: Success (0.01 seconds) ++
      ++ Success (0.52 seconds) ++
      -->upgrade_noncore()
      ++ external_update_services: Success (0.61 seconds) ++
      ++ cache_helper::update_definitions: Success (0.06 seconds) ++
      ++ core_component::get_all_versions_hash: Success (0.35 seconds) ++
      ++ cache_helper::purge_all: Success (0.08 seconds) ++
      ++ purge_all_caches: Success (0.55 seconds) ++
      ++ Success (1.66 seconds) ++
      

      After this there is more log about new default values, which wasn't changed in this MDL.

      D) Test plugin installs, displaying all data (web)

      This test confirms that it looks OK on the web interface when displaying all data.

      1 The lib/upgradelib.php should already have THRESHOLD hacked to 0.0, but if not, do that.
      2 You should already be in DEVELOPER debugging mode, but if not, enable it.
      3 Run this CLI command to uninstall 3 existing plugins:

      php admin/cli/uninstall_plugins.php --plugins=mod_bigbluebuttonbn,block_accessreview,datafield_checkbox --run
      

      4 In your web browser, visit the admin screen, which should trigger the upgrade process.
      5 Continue through the screens (current release information, plugins check) to do the actual upgrade.
      6 When the upgrade completes, look at the screen:

      • Underneath each plugin heading, there should be a final 'Success (5.51 seconds)' notification, currently shown in a green box. This is the information that will still show if you have debugging lower than 'DEVELOPER'.
      • Because debugging is on DEVELOPER and we turned off the threshold, there should also be lots more notifications (the same green boxes) above the 'Success' one. These should correspond to the lines seen in the CLI run, although obviously the times might be slightly different.

      7 Put back the code change in lib/upgradelib.php (set THRESHOLD back to 1.0).

      Note: The attached screenshots show this last sequence with and without the fake threshold setting.

      Show
      You will need to be able to run SQL against the database, and run CLI commands on the server, and edit the config.php used by the server, to carry out this test. The tests here include a selection of the possible permutations (upgrade/install, debugging on/off, CLI/web) rather than every possible one. I don't think it's necessary to test all of them. As part of this test we uninstall the 'big blue button' module which will remove all data from that module , so make sure you don't have any data you care about in that module. The test is still valid if you pick any other (uninstallable) module, so feel free to change it. A) Test upgrade (CLI) This fun SQL will make all parts of the system (all plugins + core) upgrade, hopefully without breaking it much: update mdl_config_plugins set value = (value::integer - 1) where name='version'; update mdl_config set value = (value::integer - 1) where name='version'; update mdl_config set value='0' where name='allversionshash'; 1 Set the Debug messages (debugging) admin setting under Site administration > Development > Debugging to 'ALL: ...' (not 'DEVELOPER: ...') 2 Run the SQL above to subtract 1 from all version numbers 3 Run these at the command line to purge cache and do the upgrade: php admin/cli/purge_caches.php --muc php admin/cli/upgrade.php --non-interactive --allow-unstable 4 Check the log output is as expected: There should be no errors Each plugin should be listed like this (exactly the same as before): -->logstore_standard ++ Success (0.30 seconds) ++ There should be no upgrade_noncore section heading at the end. 5 Set the Debug messages (debugging) admin setting under Site administration > Development > Debugging to 'DEVELOPER: ...' 6 Run the SQL above to subtract 1 from all version numbers 7 Run the same command as in step 3 8 Check the log output is as expected: There should be no errors. Each plugin should be listed like this (the same as before): -->logstore_standard ++ 2022053000: Success (0.04 seconds) ++ ++ Success (0.30 seconds) ++ It's possible, but not very likely, that some plugins will show additional lines apart from those two (there is a proper test of this later). At the end there should be an upgrade_noncore section heading, with a 'Success' time. This might or might not contain any additional lines. Here's an example which does have an extra line: -->upgrade_noncore() ++ external_update_services: Success (1.38 seconds) ++ ++ Success (2.70 seconds) ++ B) Test fresh install (CLI) 1 In your config.php, change the $CFG->prefix to a previously-unused value so that Moodle will install new database tables. 2 Also in your config.php, add this line to enable debug display during install: $CFG->debug = 32767; 3 Run the CLI install using a command like this (no I have not revealed my password, I just made that one up): php admin/cli/install_database.php --agree-license --adminuser=admin --adminpass=secret0_frog --adminemail=lies@email.invalid --fullname=JUNK --shortname=JUNK --summary=JUNK 4 Look at the output log. There should be detail entries within the initial 'System' install, like this: == Setting up database == -->System ++ install.xml: Success (19.51 seconds) ++ ++ xmldb_main_install: Success (63.66 seconds) ++ ++ admin_apply_default_settings: Success (81.25 seconds) ++ ++ Success (166.90 seconds) ++ Each installed plugin should show the time taken: -->antivirus_clamav ++ Success (0.45 seconds) ++ Some plugins might show a detail entry (probably for update_capabilities), but this depends on your system performance. 5 You should put back the changes in your config.php at this point (change back the prefix, remove the debug line). 6 Optionally, go into your database and delete all the tables created with the temporary prefix you used. C) Test plugin installs, displaying all data (CLI) This test simulates adding plugins to an existing system. Because there is different upgrade code for blocks, modules, and everything else, we do one of each. To show all timing information regardless of performance, we will temporarily turn the display threshold down by editing code. 1 Edit the file lib/upgradelib.php, search for THRESHOLD = 1.0, and change the 1.0 to 0.0. 2 You should already be in DEVELOPER debugging mode, but if not, enable it. 3 Run this CLI command to uninstall 3 existing plugins: php admin/cli/uninstall_plugins.php --plugins=mod_bigbluebuttonbn,block_accessreview,datafield_checkbox --run 4 Run this at the command line to do the upgrade, which should install the 3 plugins again php admin/cli/upgrade.php --non-interactive --allow-unstable 5 Check the log output is as expected, showing lots of detail lines: -->mod_bigbluebuttonbn ++ install.xml: Success (0.29 seconds) ++ ++ insert_record: Success (0.08 seconds) ++ ++ install.php: Success (0.10 seconds) ++ ++ update_capabilities: Success (5.77 seconds) ++ ++ log_update_descriptions: Success (0.05 seconds) ++ ++ external_update_descriptions: Success (0.05 seconds) ++ ++ \core\task\manager::reset_scheduled_tasks_for_component: Success (0.03 seconds) ++ ++ \core_analytics\manager::update_default_models_for_component: Success (0.01 seconds) ++ ++ message_update_providers: Success (0.12 seconds) ++ ++ \core\message\inbound\manager::update_handlers_for_component: Success (0.01 seconds) ++ ++ upgrade_plugin_mnet_functions: Success (0.03 seconds) ++ ++ core_tag_area::reset_definitions_for_component: Success (0.01 seconds) ++ ++ Success (6.56 seconds) ++ -->block_accessreview ++ insert_record: Success (0.01 seconds) ++ ++ update_capabilities: Success (1.31 seconds) ++ ++ log_update_descriptions: Success (0.01 seconds) ++ ++ external_update_descriptions: Success (0.01 seconds) ++ ++ \core\task\manager::reset_scheduled_tasks_for_component: Success (0.01 seconds) ++ ++ \core_analytics\manager::update_default_models_for_component: Success (0.01 seconds) ++ ++ message_update_providers: Success (0.01 seconds) ++ ++ \core\message\inbound\manager::update_handlers_for_component: Success (0.01 seconds) ++ ++ upgrade_plugin_mnet_functions: Success (0.01 seconds) ++ ++ core_tag_area::reset_definitions_for_component: Success (0.01 seconds) ++ ++ Success (1.46 seconds) ++ -->qbank_customfields ++ 2022041900: Success (0.04 seconds) ++ ++ update_capabilities: Success (0.22 seconds) ++ ++ log_update_descriptions: Success (0.01 seconds) ++ ++ external_update_descriptions: Success (0.03 seconds) ++ ++ \core\task\manager::reset_scheduled_tasks_for_component: Success (0.01 seconds) ++ ++ \core_analytics\manager::update_default_models_for_component: Success (0.01 seconds) ++ ++ message_update_providers: Success (0.01 seconds) ++ ++ \core\message\inbound\manager::update_handlers_for_component: Success (0.01 seconds) ++ ++ upgrade_plugin_mnet_functions: Success (0.01 seconds) ++ ++ core_tag_area::reset_definitions_for_component: Success (0.01 seconds) ++ ++ Success (0.42 seconds) ++ -->datafield_checkbox ++ update_capabilities: Success (0.37 seconds) ++ ++ log_update_descriptions: Success (0.01 seconds) ++ ++ external_update_descriptions: Success (0.01 seconds) ++ ++ \core\task\manager::reset_scheduled_tasks_for_component: Success (0.01 seconds) ++ ++ \core_analytics\manager::update_default_models_for_component: Success (0.01 seconds) ++ ++ message_update_providers: Success (0.01 seconds) ++ ++ \core\message\inbound\manager::update_handlers_for_component: Success (0.01 seconds) ++ ++ upgrade_plugin_mnet_functions: Success (0.01 seconds) ++ ++ core_tag_area::reset_definitions_for_component: Success (0.01 seconds) ++ ++ Success (0.52 seconds) ++ -->upgrade_noncore() ++ external_update_services: Success (0.61 seconds) ++ ++ cache_helper::update_definitions: Success (0.06 seconds) ++ ++ core_component::get_all_versions_hash: Success (0.35 seconds) ++ ++ cache_helper::purge_all: Success (0.08 seconds) ++ ++ purge_all_caches: Success (0.55 seconds) ++ ++ Success (1.66 seconds) ++ After this there is more log about new default values, which wasn't changed in this MDL. D) Test plugin installs, displaying all data (web) This test confirms that it looks OK on the web interface when displaying all data. 1 The lib/upgradelib.php should already have THRESHOLD hacked to 0.0, but if not, do that. 2 You should already be in DEVELOPER debugging mode, but if not, enable it. 3 Run this CLI command to uninstall 3 existing plugins: php admin/cli/uninstall_plugins.php --plugins=mod_bigbluebuttonbn,block_accessreview,datafield_checkbox --run 4 In your web browser, visit the admin screen, which should trigger the upgrade process. 5 Continue through the screens (current release information, plugins check) to do the actual upgrade. 6 When the upgrade completes, look at the screen: Underneath each plugin heading, there should be a final 'Success (5.51 seconds)' notification, currently shown in a green box. This is the information that will still show if you have debugging lower than 'DEVELOPER'. Because debugging is on DEVELOPER and we turned off the threshold, there should also be lots more notifications (the same green boxes) above the 'Success' one. These should correspond to the lines seen in the CLI run, although obviously the times might be slightly different. 7 Put back the code change in lib/upgradelib.php (set THRESHOLD back to 1.0). Note: The attached screenshots show this last sequence with and without the fake threshold setting.

    Description

      During upgrades, the time taken by each component is logged. If you have developer debug mode enabled, there is additional logging at each savepoint.

      We experienced behaviour during an upgrade where some times were not really accounted for (e.g. the displayed steps took a certain amount of time, but the total time was several minutes longer). While this is probably unusual and only occurs on specific environments, it would be useful to add more logging to cover the steps that happen during upgrade/install that aren't savepoints - for example, updating capabilities or webservice details - in case some of these sometimes take a long time.

      I propose to add extra logging (in the same format as current) to cover these steps. To avoid making it ridiculously verbose, it will only output these times if they are longer than 1 second.

      This change will also fixes some issues with the current code:

      • Times for install (as opposed to upgrade) are not displayed, even though we have the data. This seems inconsistent especially as it applies to individual plugins (a new plugin being installed as part of a system upgrade) not just the initial install.
      • There is very heavily duplicated code relating to a series of functions that have to be called after a component is installed or updated, I will remove the duplication to make it easier to change this.

      Attachments

        1. MDL-75751_1.png
          MDL-75751_1.png
          148 kB
        2. MDL-75751_2.png
          MDL-75751_2.png
          170 kB
        3. MDL-75751_3.png
          MDL-75751_3.png
          159 kB
        4. MDL-75751_4.png
          MDL-75751_4.png
          221 kB
        5. MDL-75751_5.png
          MDL-75751_5.png
          88 kB
        6. MDL-75751-fake-show-all-times.png
          MDL-75751-fake-show-all-times.png
          49 kB
        7. MDL-75751-real-developer-debug.png
          MDL-75751-real-developer-debug.png
          41 kB
        8. MDL-75751-real-no-debug.png
          MDL-75751-real-no-debug.png
          32 kB
        9. upgradelog.txt
          53 kB

        Issue Links

          Activity

            People

              quen Sam Marshall
              quen Sam Marshall
              Katie Ransom Katie Ransom
              Ilya Tregubov Ilya Tregubov
              Angelia Dela Cruz Angelia Dela Cruz
              Votes:
              1 Vote for this issue
              Watchers:
              7 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Time Tracking

                  Estimated:
                  Original Estimate - 0 minutes
                  0m
                  Remaining:
                  Remaining Estimate - 0 minutes
                  0m
                  Logged:
                  Time Spent - 1 hour, 55 minutes
                  1h 55m

                  Clockify

                    Error rendering 'clockify-timesheets-time-tracking-reports:timer-sidebar'. Please contact your Jira administrators.