-
Bug
-
Resolution: Duplicate
-
Minor
-
None
-
3.0.6
-
None
-
MOODLE_30_STABLE
We experienced a massive performance loss for admins during the last months. The reason, as it turned out finally, was the fact that tool_monitor was enabled.
Our setup:
- On /admin/tool/monitor/managerules.php, the event monitoring was globally enabled.
- On /admin/tool/monitor/managerules.php, there were two monitoring rules globally defined.
- According to the entries in the mdl_tool_monitor_subscriptions and mdl_tool_monitor_rules tables, only 9 users had subscribed 57 times to either our global rules or have created their own rules.
- No admin had subscribed to any event monitoring rules.
- We did not have any custom caching backends configured for MUC, if this information is relevant
Our findings:
- When logged in as an admin user, we saw that there is a massive performance loss on every page in Moodle. Normal users got a page delivered in approx. 1 sec and admins had to wait up to 10 secs.
- We enabled $CFG->perfdebug and saw that normal users have approx. 95 SQL queries for /course/view.php for example, but admins have 2.500 queries!
- We added
$CFG->dboptions['logall'] = true;
to config.php and investigated the SQL queries which are run for admins. It turned out that Moodle did several queries which resulted from tool_monitor according to the call stack, but especially it fetched the context of every course from the DB!- The queries looked like: SELECT * FROM mdl_context WHERE contextlevel = $1 AND instanceid = $2
- The query parameters looked like: "array (
0 => 50,
1 => '554',
)" - The call stack was:"* line 744 of /lib/dml/pgsql_native_moodle_database.php: call to pgsql_native_moodle_database->query_end()
line 904 of /lib/filterlib.php: call to pgsql_native_moodle_database->get_recordset_sql()
line 122 of /lib/filterlib.php: call to filter_get_active_in_context()
line 189 of /lib/filterlib.php: call to filter_manager->load_filters()
line 270 of /lib/filterlib.php: call to filter_manager->get_text_filters()
line 1404 of /lib/weblib.php: call to filter_manager->setup_page_for_filters()
line 110 of /admin/tool/monitor/lib.php: call to format_string()
line 83 of /admin/tool/monitor/lib.php: call to tool_monitor_get_user_courses()
line 4510 of /lib/navigationlib.php: call to tool_monitor_extend_navigation_user_settings()
line 4085 of /lib/navigationlib.php: call to settings_navigation->generate_user_settings()
line 3480 of /lib/navigationlib.php: call to settings_navigation->load_user_settings()
line 719 of /lib/pagelib.php: call to settings_navigation->initialise()
line 768 of /lib/pagelib.php: call to moodle_page->magic_get_settingsnav()
line 135 of /blocks/settings/block_settings.php: call to moodle_page->__get()
line 288 of /blocks/moodleblock.class.php: call to block_settings->get_content()
line 230 of /blocks/moodleblock.class.php: call to block_base->formatted_contents()
line 973 of /lib/blocklib.php: call to block_base->get_content_for_output()
line 1025 of /lib/blocklib.php: call to block_manager->create_block_contents()
line 476 of /lib/outputrenderers.php: call to block_manager->ensure_content_created()
line 39 of /theme/bootstrapbase/renderers/core_renderer.php: call to core_renderer->standard_head_html()
line 40 of /theme/uulm/layout/columns3.php: call to theme_bootstrapbase_core_renderer->standard_head_html()
line 1018 of /lib/outputrenderers.php: call to include()
line 948 of /lib/outputrenderers.php: call to core_renderer->render_page_layout()
line 244 of /course/view.php: call to core_renderer->header()
- Additionally, we saw that if we have the multilang filter on /admin/filters.php enabled for content and headings (which we normally have), the amount of SQL queries per call doubled to approx. 5.000 because Moodle also fetched filter settings from the DB for every context!
- The queries looked like:
"SELECT active.filter, fc.name, fc.value
FROM (SELECT f.filter, MAX(f.sortorder) AS sortorder
FROM mdl_filter_active f
JOIN mdl_context ctx ON f.contextid = ctx.id
WHERE ctx.id IN (1,9288,28710,77078)
GROUP BY filter
HAVING MAX(f.active * ctx.depth) > -MIN(f.active * ctx.depth)
) active
LEFT JOIN mdl_filter_config fc ON fc.filter = active.filter AND fc.contextid = 77078
ORDER BY active.sortorder" - Interestingly, the context IDs were always contained in the query itself and were not submitted as parameters to the DB.
- The call stack was:
line 744 of /lib/dml/pgsql_native_moodle_database.php: call to pgsql_native_moodle_database->query_end()
line 904 of /lib/filterlib.php: call to pgsql_native_moodle_database->get_recordset_sql()
line 122 of /lib/filterlib.php: call to filter_get_active_in_context()
line 189 of /lib/filterlib.php: call to filter_manager->load_filters()
line 270 of /lib/filterlib.php: call to filter_manager->get_text_filters()
line 1404 of /lib/weblib.php: call to filter_manager->setup_page_for_filters()
line 110 of /admin/tool/monitor/lib.php: call to format_string()
line 83 of /admin/tool/monitor/lib.php: call to tool_monitor_get_user_courses()
line 4510 of /lib/navigationlib.php: call to tool_monitor_extend_navigation_user_settings()
line 4085 of /lib/navigationlib.php: call to settings_navigation->generate_user_settings()
line 3480 of /lib/navigationlib.php: call to settings_navigation->load_user_settings()
line 719 of /lib/pagelib.php: call to settings_navigation->initialise()
line 768 of /lib/pagelib.php: call to moodle_page->magic_get_settingsnav()
line 135 of /blocks/settings/block_settings.php: call to moodle_page->__get()
line 288 of /blocks/moodleblock.class.php: call to block_settings->get_content()
line 230 of /blocks/moodleblock.class.php: call to block_base->formatted_contents()
line 973 of /lib/blocklib.php: call to block_base->get_content_for_output()
line 1025 of /lib/blocklib.php: call to block_manager->create_block_contents()
line 476 of /lib/outputrenderers.php: call to block_manager->ensure_content_created()
line 39 of /theme/bootstrapbase/renderers/core_renderer.php: call to core_renderer->standard_head_html()
line 40 of /theme/uulm/layout/columns3.php: call to theme_bootstrapbase_core_renderer->standard_head_html()
line 1018 of /lib/outputrenderers.php: call to include()
line 948 of /lib/outputrenderers.php: call to core_renderer->render_page_layout()
line 244 of /course/view.php: call to core_renderer->header()
- The queries looked like:
- We haven't tested it, but we expect that our findings / the performance loss also apply for non-admin users who are enrolled in a large amount of courses
Our conclusion was that we had to disable tool_monitor immediately. However, I submit this ticket to give the core developers a chance to investigate and fix this issue.
- duplicates
-
MDL-51833 Event Monitor loads every course context and builds strings on every page view
- Closed