Pre-load Definitions in Split Modulestore when accessing all blocks by nasthagiri · Pull Request #14213 · openedx/openedx-platform

nasthagiri · 2016-12-23T16:16:53Z

TNL-6222

Description

TLDR;

This PR addresses the excessive calls to modulestore.definitions find_one and modulestore.active_versions find_one in lms.djangoapps.grades.tasks.recalculate_subsection_grade_v2. It also reduces the number of calls to modulestore.definitions find_one in courseware.views.index:CoursewareIndex.get.

Details

When monitoring the staged rollout of Persistent Grades, we noticed that the celery task for updating grades was making unexpected number of mongo queries - some even up to 2,000 mongo queries!

We were able to reduce the extra calls to modulestore.active_versions find_one by surrounding the task with a transactional bulk_operations context manager. Those grew linearly by the number of subsections in the course.

However, there were still excessive calls to modulestore.definitions find_one (growing linearly by the number of problems in the course). After further testing, we narrowed down the issue to: (1) cache misses on the Block Structure and (2) Split Modulestore courses.

For Block Structures, we expected all course blocks to be pre-loaded in a few (4) queries since we loaded the course with depth=None. Apparently, there is another parameter that we should have also set: lazy=False. So this PR corrects the Block Structure's call to the modulestore to pre-load all definitions since they are needed during the "collect" phase.

Additionally, when investigating this issue, we noticed that loading the Sequential on the Courseware page had the same issue (since lazy=False was not specified along with depth=None, although definitions of all descendant blocks of the Sequential need to be accessed). So this PR updates Courseware to do so, and adds query count tests to validate the change.

Finally, the implementation of the Split Modulestore had to be updated to:

Support pre-loading of Definitions with the lazy=False parameter even after the runtime for the course had been previously cached. This allows callers to be agnostic to whether a course is pre-fetched without the depth=None, lazy=False parameters, but then later accessed with those parameters.
Fix a bug in get_definitions so the bulk_write_record.definitions_in_db object is also updated. Otherwise, the Mongo collection was mistakenly "Inserted" with pre-fetched records at the end of the bulk-operation - since the code incorrectly calculated that those definitions didn't pre-exist in the database.

Note: There are still linearly growing SQL queries that will be addressed by a separate ticket: https://openedx.atlassian.net/browse/TNL-6225

Reviewers

If you've been tagged for review, please check your corresponding box once you've given the 👍.

Code review: @doctoryes and/or @ormsbee
Code review: @sanfordstudent

FYI: @jcdyer

Post-review

Rebase and squash commits

estute · 2016-12-27T18:22:57Z

jenkins run bokchoy

nasthagiri · 2016-12-27T23:24:36Z

bokchoy failure: https://build.testeng.edx.org/job/edx-platform-bok-choy-pr/31238/testReport/junit/common.test.acceptance.tests.lms.test_lms_courseware/ProctoredExamTest/test_masquerade_visibility_override/

ormsbee · 2016-12-28T14:50:41Z

Just so I'm clear on this -- this addresses the excessive calls to modulestore.active_versions find_one in lms.djangoapps.grades.tasks.recalculate_subsection_grade_v2 ?

nasthagiri · 2016-12-28T14:55:20Z

@ormsbee Yes. Sorry if that wasn't clear. I'll update the description.

nasthagiri · 2016-12-28T16:55:50Z

Note to reviewers: This is a bug fix (No 2 in the description). Otherwise, the Mongo collection was mistakenly "Inserted" with pre-fetched records at the end of the bulk-operation - since the code incorrectly calculated that those definitions didn't pre-exist in the database.

nasthagiri · 2016-12-28T16:57:21Z

Note to reviewers: This change allows callers to be agnostic to whether a course was previously prefetched into the runtime. This is No 2 in the description.

Could you explain this more please? Why would we ever not want to cache_items? Or does cache_items imply pre-fetch here?

Good question. My change was an iterative, conservative change - changing the behavior only when lazy=False.

Now that you ask the question, I do wonder why we aren't always caching? For some reason, the previous code chose to cache only when the runtime for the course wasn't cached. Since there are many calls to _load_items from within split.py, there may be a good reason. (?). Here's the precondition listed in cache_items:

Handles caching of items once inheritance and any other one time per course per fetch operations are done.

nasthagiri · 2016-12-28T16:58:29Z

Note to reviewers: This TODO was addressed by passing a request_cache object to the modulestore in these tests.

nasthagiri · 2016-12-28T16:59:10Z

Note to reviewers: I have verified that this test breaks on master (without the changes in this PR).

nasthagiri · 2016-12-28T17:00:15Z

Note to reviewers: Renaming from _data to data allows this stub cache object to be used as a request_cache in the modulestore.

Just curious how the name affects how it's passed.

It's because Split Modulestore expects the given request_cache object to store its dict in a data field. For example: https://github.com/edx/edx-platform/blob/master/common/lib/xmodule/xmodule/modulestore/split_mongo/split.py#L792

nasthagiri · 2016-12-28T17:10:22Z

Note to reviewers: Adding kwargs parameters here allows test code to specify optional parameters to the Modulestore, including a request_cache for this PR.

Some questions:

I see it being passed through the layers with **kwargs, but where does the request_cache actually get popped off and read?

Is it necessary to pass an explicitly created request cache all the way down? Could the the test case inherit from CacheIsolationTestCase, do its setup, and then test in uncached vs. cached states?

Actually, thinking on item 2, are we avoiding it because of the Django dependency...?

yes - exactly. This test runs just under nosetools on Jenkins.
And as we both know, running with python manage.py adds much more overhead. So unless absolutely necessary, I thought about keeping it as a non-django test.

nasthagiri · 2016-12-28T17:14:41Z

Note to reviewers: The query counts here went up by 1 only because the cache is now cleared before measuring the mongo calls. Otherwise, it was resulting in discrepancies between CMS and LMS runtimes.

nasthagiri · 2016-12-28T17:18:45Z

Note to reviewers: On master, instead of 4, this results in 23 mongo calls for Split and grows linearly with the number of blocks in the course.

This. Is. Awesome. (I'm on vacation, so I won't be giving a broader review.)

nasthagiri · 2016-12-28T17:21:51Z

Note to @sanfordstudent: When the query context manager is used in a conjunction, only the latter query count is checked. Not the former. So all the check_mongo_calls in this file were not being called. A surprise for me as well. :(

Wow, that's good to know.

ormsbee · 2016-12-28T18:02:52Z

ormsbee · 2016-12-28T21:56:24Z

store here instead of modulestore()?

Good catch. Thanks.

ormsbee · 2016-12-28T21:59:37Z

Tiny nitpick, but 👍 on the PR either way. Thank you for the reviewer's notes -- they were most helpful.

sanfordstudent · 2016-12-29T00:19:37Z

Like Dave said, thanks for the notes for reviewers. They made understanding what was going on much easier. This looks great! 👍

nasthagiri · 2016-12-29T15:17:22Z

jenkins run bokchoy

https://build.testeng.edx.org/job/edx-platform-bok-choy-pr/31284/testReport/junit/common.test.acceptance.tests.studio.test_import_export/TestLibraryImport/test_library_updated/

nasthagiri · 2016-12-29T16:22:07Z

jenkins run bokchoy

https://build.testeng.edx.org/job/edx-platform-test-subset/691619/testReport/junit/common.test.acceptance.tests.lms.test_teams/CreateTeamTest/test_user_can_see_error_message_for_missing_data/

cpennington · 2017-01-03T20:23:42Z

This PR has been deployed to edx.org Staging in preparation for a release to production on Weds, 1/4/2017. If you feel you need to validate it manually, please do so by then, and contact me if there is an urgent enough issue to scrap the deployment.

doctoryes · 2017-01-03T21:20:34Z

👍 Thanks, @nasthagiri !

cpennington · 2017-01-04T15:28:35Z

This PR has been deployed to edx.org.

nasthagiri force-pushed the beryl/mongocrazy branch 5 times, most recently from 914188f to ce2e699 Compare December 27, 2016 18:17

nasthagiri force-pushed the beryl/mongocrazy branch 2 times, most recently from 7420466 to 8df9851 Compare December 28, 2016 14:06

nasthagiri changed the title ~~Fix Split Modulestore so definitions are pre-loaded when depth=None~~ Pre-load Definitions in Split Modulestore when accessing all blocks Dec 28, 2016

nasthagiri commented Dec 28, 2016

View reviewed changes

ormsbee reviewed Dec 28, 2016

View reviewed changes

Comment thread common/lib/xmodule/xmodule/modulestore/tests/test_mongo_call_count.py Outdated

ormsbee Dec 28, 2016

Copy link
Copy Markdown

Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🎆

ormsbee reviewed Dec 28, 2016

View reviewed changes

Preload definitions when collecting block structures

99e6d53

nasthagiri force-pushed the beryl/mongocrazy branch from 84f4ef1 to 99e6d53 Compare December 29, 2016 13:51

nasthagiri merged commit 1de87f9 into master Jan 3, 2017

nasthagiri deleted the beryl/mongocrazy branch January 3, 2017 14:37

Uh oh!

Conversation

nasthagiri commented Dec 23, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

TLDR;

Details

Reviewers

Post-review

Uh oh!

estute commented Dec 27, 2016

Uh oh!

nasthagiri commented Dec 27, 2016

Uh oh!

ormsbee commented Dec 28, 2016

Uh oh!

nasthagiri commented Dec 28, 2016

Uh oh!

nasthagiri Dec 28, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

nasthagiri Dec 28, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ormsbee commented Dec 28, 2016

Uh oh!

sanfordstudent commented Dec 29, 2016

Uh oh!

nasthagiri commented Dec 29, 2016

Uh oh!

nasthagiri commented Dec 29, 2016

Uh oh!

cpennington commented Jan 3, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

doctoryes commented Jan 3, 2017

Uh oh!

cpennington commented Jan 4, 2017

nasthagiri commented Dec 23, 2016 •

edited

Loading

nasthagiri Dec 28, 2016 •

edited

Loading

nasthagiri Dec 28, 2016 •

edited

Loading

cpennington commented Jan 3, 2017 •

edited

Loading