Moodle’s performance information and events

Moodle’s performance information (can be enabled in Site administration -> Development -> Debugging) is very useful for troubleshooting your site performance. Sometimes just one look there will tell you where the (performance) problem is. But sometimes not.

The limitation of the current implementation is that the time and resources used by event-triggered logging action are not taken into account.

Consider the following Moodle page:

<?php
require_once('config.php');

$PAGE->set_context(context_system::instance());
$PAGE->set_url('/log.php');

$event = \core\event\user_login_failed::create(
           ['other' => ['username' => 'Test','reason' => 'No reason!']]
         );
$event->trigger();

echo $OUTPUT->header();
echo $OUTPUT->footer();

See the sample footer with the performance information:

It tells us that there were no DB writes performed. This can not be true, because there was a new row added to in mdl_logstore_standard_log table.

Let’s check if the time spent by the logging function is covered. I have edited function insert_event_entries in admin/tool/log/store/standard/classes/log/store.php - injected sleep(10); there:

    protected function insert_event_entries($evententries) {
        global $DB;

        sleep(10);
        $DB->insert_records('logstore_standard_log', $evententries);
    }

After refresh - the information from the footer does not change! Moodle tells me it took 0.133499 secs to generate it, while it obviously took more than 10 seconds. Browser debugger confirms it:

I have logged that in Moodle tracker MDL-68817.