Repository navigation
Modulestore migrator performance #584
Description
Activity
- added a parent issue
on May 5, 2026 Before:
Importing "Open edX Demo Course" took 1311s (22m).
Partial breakdown:bulk_migrate_from_modulestore- 49s- As the migration progresses, publishing happens on each item, resulting in
LIBRARY_BLOCK_PUBLISHEDandLIBRARY_CONTAINER_PUBLISHEDevents, trigger interleaved calls to:upsert_library_block_index_doc(x310, avg. 0.5s/call, total 172s) (🔵 ~ 0s platform, 🔴 ~0.5s Meilisearch) andupdate_library_container_index_doc(x81, avg 0.7s/call, total 58s) (🔵 ~ 0.2s platform, 🔴 ~0.5s Meilisearch)
update_library_collection_index_doc- 0.5s (🔵 ~ 0s platform, 🔴 ~0.5s Meilisearch)send_collections_changed_events- 206.18s (🔴 almost entirely due to 393x calls to Meilisearch taking ~0.5s each)send_change_events_for_modified_entities- given draft change log with 393 changes (first containers, then components) - 438s:- 81
LIBRARY_CONTAINER_CREATEDevents emitting, triggeringupdate_library_container_index_doc(x81, avg 0.7s/call, total 57s). Plus (directly fromsend_change_events...), 81 calls tocheck_container_content_changes(x81, avg 2.6s/call, total 208s) for the new containers - 310
LIBRARY_BLOCK_CREATEDevents emitted, calling again toupsert_library_block_index_doc(x310, avg. 0.5s/call, total 172s)
- 81
update_library_collection_index_docx2 - 0.5s each timesend_collections_changed_events(with 393 entity IDs) - 206.4s
Notes:
- Almost all the slowness is due to Meilisearch, and almost every call to Meilisearch takes 0.5s very consistently.
- the published events are occurring before the
CREATEDevents, as expected due to publishing in a draft changes context. - there is a lot of redundancy here, but we lack a mechanism for consolidating redundant events in the event queue.
After: TBD
OK, turns out there is some really low-hanging fruit here. The change in openedx/openedx-platform#38576 reduces the import time of the demo course from ~21 minutes to ~5 minutes. Still more to do, which I'm looking into, but let's fix that right off the bat.
Reacted by Rômulo Penido and David OrmsbeeWith the changes from openedx/openedx-platform#38576, openedx/openedx-platform#38508 and #593 together, the breakdown of the 286s import of the demo course in eager mode (no async tasks) is:
bulk_migrate_from_modulestore- 30ssend_change_events_for_modified_entities- 70sLIBRARY_CONTAINER_CREATEDevents emitting, triggering:update_library_container_index_doc(x81, avg 0.23s/call, total 18.4s). Plus (directly fromsend_change_events...), 81 calls tocheck_container_content_changes(x81, avg 0.23s/call, total 18.8s) for the new containersLIBRARY_BLOCK_CREATEDevents emitted, callingupsert_library_block_index_doc(x310, avg. 0.10s/call, total 32s)
send_events_after_publish- 39.745sLIBRARY_BLOCK_PUBLISHEDevents ->upsert_library_block_index_doc(x310, avg. 0.06s/call, total 19.2s)LIBRARY_CONTAINER_PUBLISHEDevents ->update_library_container_index_doc(x81, avg. 0.20s/call, total 16.2s)
send_collections_changed_eventsfor 393 entities changed - 30.7s- TBD / ????????? (120s)
I haven't yet figured out what handler is running after the bulk migration is kicked off that takes 120s.
Most of these events unfortunately cannot be further consolidated without changing the event API. The easiest change to make would be to change
CONTENT_OBJECT_ASSOCIATIONS_CHANGEDfrom a single-entity event to a bulk event, as it's often emitted for many entities in bulk.OK, this is very weird. When I run the import of the demo course from the CMS django shell, it takes only 120s to import the same content, with the exact same parameters.
from opaque_keys.edx.keys import CourseKey, UsageKeyV2 from opaque_keys.edx.locator import LibraryLocatorV2 from openedx_content import api as content_api from openedx.core.djangoapps.content_libraries import api as library_api from openedx.core.djangoapps.xblock import api as xblock_api from cms.djangoapps.modulestore_migrator import api as migrator_api from cms.djangoapps.modulestore_migrator import data as migrator_data from django.db import transaction import time start_time = time.perf_counter() with transaction.atomic(): migrator_api.start_bulk_migration_to_library( user=User.objects.get(email="braden@opencraft.com"), source_key_list=[CourseKey.from_string("course-v1:OpenedX+DemoX+DemoCourse")], target_library_key=LibraryLocatorV2.from_string("lib:OpenCraftX:MTL4"), target_collection_slug_list=[None], create_collections=True, composition_level=migrator_data.CompositionLevel.Section, repeat_handling_strategy=migrator_data.RepeatHandlingStrategy.Fork, preserve_url_slugs=True, forward_source_to_target=None, ) finished_in = time.perf_counter() - start_time finished_in
But when I run it from the REST API endpoint using the "Import" menu in the libraries UI, it consistently takes twice as long. It's pausing after the last step of the import for almost two minutes, and I can't figure out what it's doing - it doesn't seem to be making any database queries or logging any output, and the pause doesn't happen when I run the same thing from the CMS shell.
Oh my god, I should have known. It's Django Debug Toolbar's SQL panel post-processing every single query the migration ran. render_stacktrace is formatting a stacktrace for each captured query, and with tens of thousands of queries from the migration, it's taking a full 2 minutes.
Why does it even run on REST API requests?!?!?!
I think openedx/openedx-platform#37301 only fixed it for the LMS 😭
Ugh, sorry. I encountered an issue where debug-toolbar actually crashed my attempt to import Grape Ape because it ran too many queries to keep track of, and I was in such a rush to try to get a demo working that I forgot to write a ticket for it.
☹️ .Why does it even run on REST API requests?!?!?!
Because you can hit the "History" tab and look at previous request profiles. I use it when trying to diagnose n+1 queries locally.
Edit: To be clear, I'm fine with disabling the toolbar for now and having folks toggle it on as needed for profiling work. But that's the rationale for why it does REST API endpoint requests, even though it can't display itself in them.
OK, so disabling django debug toolbar brings the demo course import time down to ~130s, and with celery enabled it takes about 48s although some of the imported content does not appear in the collection for another few seconds after the import task says it's complete.
Metadata
Metadata
Assignees
Labels
Type
Projects
- Status
Per @ormsbee :
The PR at openedx/openedx-platform#38508 should start to fix this, but we still have more to go. Investigate the performance and see how we can improve it further.