Opened 3 years ago

Closed 3 years ago

Last modified 3 years ago

#27279 closed Cleanup/optimization (fixed)

Performance regression when running migrate with RenameModel operations

Reported by: mtomiyoshi Owned by: Simon Charette
Component: Migrations Version: 1.10
Severity: Normal Keywords:
Cc: Simon Charette, marten.knbk@… Triage Stage: Ready for checkin
Has patch: yes Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description

Since I upgraded to 1.10.1 I've been seeing much slower test initialization than before. There is no noticeable difference afterwards, but when running just a small subset of tests the slow startup is becoming a little bit annoying.

These are the results of cProfile I got when running only one test:

  • 1.10.1:
    Using existing test database for alias 'default'...
    Preserving test database for alias 'default'...
             29267726 function calls (28542239 primitive calls) in 41.733 seconds
    
       Ordered by: cumulative time
    
       ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       1422/1    0.024    0.000   41.737   41.737 {built-in method exec}
            1    0.000    0.000   41.737   41.737 manage.py:2(<module>)
            1    0.000    0.000   41.528   41.528 __init__.py:362(execute_from_command_line)
            1    0.000    0.000   41.528   41.528 __init__.py:286(execute)
            1    0.000    0.000   40.005   40.005 test.py:18(run_from_argv)
            1    0.000    0.000   40.005   40.005 base.py:277(run_from_argv)
          3/1    0.001    0.000   39.997   39.997 base.py:308(execute)
            1    0.000    0.000   39.997   39.997 test.py:61(handle)
            1    0.000    0.000   39.997   39.997 runner.py:535(run_tests)
            1    0.000    0.000   39.655   39.655 runner.py:496(setup_databases)
            1    0.000    0.000   39.655   39.655 runner.py:722(setup_databases)
            1    0.000    0.000   39.655   39.655 creation.py:31(create_test_db)
            2    0.000    0.000   33.294   16.647 __init__.py:79(call_command)
            1    0.000    0.000   33.272   33.272 migrate.py:65(handle)
            1    0.001    0.001   32.714   32.714 executor.py:66(_create_project_state)
          205    0.002    0.000   32.638    0.159 migration.py:81(mutate_state)
          473    0.036    0.000   32.441    0.069 state.py:103(reload_model)
          351    0.058    0.000   30.502    0.087 state.py:263(render_multiple)
        14865    0.690    0.000   30.195    0.002 state.py:528(render)
    
  • 1.10:
    Using existing test database for alias 'default'...
    Preserving test database for alias 'default'...
             8427740 function calls (7801541 primitive calls) in 9.000 seconds
    
       Ordered by: cumulative time
    
       ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       1420/1    0.028    0.000    9.005    9.005 {built-in method exec}
            1    0.000    0.000    9.005    9.005 manage.py:2(<module>)
            1    0.000    0.000    8.752    8.752 __init__.py:362(execute_from_command_line)
            1    0.000    0.000    8.752    8.752 __init__.py:286(execute)
            1    0.000    0.000    7.013    7.013 test.py:18(run_from_argv)
            1    0.000    0.000    7.013    7.013 base.py:288(run_from_argv)
          3/1    0.000    0.000    7.005    7.005 base.py:319(execute)
            1    0.000    0.000    7.005    7.005 test.py:61(handle)
            1    0.000    0.000    7.005    7.005 runner.py:535(run_tests)
            1    0.000    0.000    6.634    6.634 runner.py:496(setup_databases)
            1    0.000    0.000    6.634    6.634 runner.py:722(setup_databases)
            1    0.000    0.000    6.634    6.634 creation.py:31(create_test_db)
            1    0.000    0.000    6.403    6.403 creation.py:94(serialize_db_to_string)
            1    0.000    0.000    6.374    6.374 __init__.py:123(serialize)
            1    0.227    0.227    6.371    6.371 base.py:63(serialize)
        18925    0.203    0.000    4.176    0.000 json.py:52(end_object)
        18925    0.392    0.000    3.049    0.000 __init__.py:119(dump)
    

I am not including the whole result, but I could do so if needed.

It seems to be related to changes in the 'executor.py' file. I looked for when this was changed and found this commit: https://github.com/django/django/commit/d5c4ea524679a787fe11c927448e44e95646096b

I am not sure if this was an intended behavior so that's why I am filing this as an optimization instead of a bug.

Attachments (2)

profile_results.tar.gz (169.7 KB) - added by mtomiyoshi 3 years ago.
renamemodel-reset-apps.patch (975 bytes) - added by Marten Kenbeek 3 years ago.

Download all attachments as: .zip

Change History (19)

comment:1 Changed 3 years ago by Tim Graham

Cc: Simon Charette added
Component: Testing frameworkMigrations

Not sure what, if anything, can be done.

comment:2 Changed 3 years ago by Marten Kenbeek

Cc: marten.knbk@… added

Since you use --keepdb, the database should already have all migrations applied, and I think only the final project state should render all models. If that's the case, the number of calls to ModelState.render() (14865) is way higher than it should be.

Could you provide the complete profile file for the 1.10.1 case? I'd like to take a closer look to see when those models are actually rendered.

comment:3 Changed 3 years ago by Simon Charette

The final state has to be rendered to allow post_migrate to dispatch its apps argument even when --keepdb is used.

The issue here is that during the process of computing the final state some operation's state_forwards might require access to state.apps triggering the rendering. I know that Markus has been working on teaching the migration framework to forward without accessing rendered model state but in this case we might be able to get away by preventing reload_model() from actually doing anything by deleting state.apps on every step of mutate_state as reload_model() is a noop when state.apps is missing.

The RenameModel.state_forwards() operation still require access to state.apps (that should be fixed if possible in 1.11) so migrations containing them would still trigger an extra model rendering but the subsequent call to render_model() wouldn't until another RenameModel operation is performed.

TL;DR adding a delattr(state, 'apps', None) before mutate_state() here should speed up things significantly.

Changed 3 years ago by mtomiyoshi

Attachment: profile_results.tar.gz added

comment:4 Changed 3 years ago by mtomiyoshi

I've attached the full profile report.

I reran it two times with an empty test suite: the "profile1101" file is the regular Django 1.10.1 version but I also ran it with the Simon's suggested modification and the running time lowered by about 8 seconds. These results are on the "profile1101mod" file.

comment:5 Changed 3 years ago by Simon Charette

Does you project include a lot of RenameModel operations? I might have missed operations that require accessing state.apps to perform state_forwards.

comment:6 Changed 3 years ago by mtomiyoshi

I found 5 migrations with RenameModels on my project, so not that much, I think!

comment:7 in reply to:  6 Changed 3 years ago by Simon Charette

Replying to mtomiyoshi:

I found 5 migrations with RenameModels on my project, so not that much, I think!

If these migrations include a lot operations after these RenameModel it could be significantly slow.

Could you try putting a breakpoint before this return statement to make sure it's mostly triggered by RenameModel.state_forwards during the state mutation process.

comment:8 Changed 3 years ago by mtomiyoshi

There are several other migrations (around 20-30) after one of those that uses a RenameModel, is this the cause of the slow startup? Or do you mean if there are several other operations inside these RenameModel migrations?

I am not sure if I understood correctly, but I tried setting a breakpoint on that return line and it got called only once (that one call
was made by a RenameModel operation). Is this what you were expecting?

Changed 3 years ago by Marten Kenbeek

comment:9 Changed 3 years ago by Marten Kenbeek

Can you try the patch I've attached to the ticket? It may or may not make much of a difference compared to Simon's patch. If it doesn't make a difference, we can at least pinpoint the performance degradation to what happens during the RenameModel.state_forwards() method.

For the profile files: could you use the -o <output_file> option? That will write all the raw profile data to the file, not just the output to stdout. We can then use the pstats module to analyze e.g. the caller/callee graph.

I am not sure if I understood correctly, but I tried setting a breakpoint on that return line and it got called only once (that one call
was made by a RenameModel operation). Is this what you were expecting?

With the regular 1.10.1, I would indeed expect this to be called once, when the first RenameModel accesses state.apps. With Simon's patch I would expect it to be called a few times: once for each migration containing a RenameModel operation, and once when rendering the final project state.

comment:10 in reply to:  9 Changed 3 years ago by mtomiyoshi

Ok, so I did something stupid when trying Simon's suggestion and that's why it was so slow... Sorry about that!

With a proper implementation of his suggestion the time to run an empty test got down to around 5-6 seconds in total, even better than what I was seeing with 1.10 (which was around 9-10 seconds). I also tried Marten's patch and it also runs around the same 5-6 seconds here, so I would say both implementations are great!

Replying to Marten Kenbeek:

Can you try the patch I've attached to the ticket? It may or may not make much of a difference compared to Simon's patch. If it doesn't make a difference, we can at least pinpoint the performance degradation to what happens during the RenameModel.state_forwards() method.

For the profile files: could you use the -o <output_file> option? That will write all the raw profile data to the file, not just the output to stdout. We can then use the pstats module to analyze e.g. the caller/callee graph.

I am not sure if I understood correctly, but I tried setting a breakpoint on that return line and it got called only once (that one call
was made by a RenameModel operation). Is this what you were expecting?

With the regular 1.10.1, I would indeed expect this to be called once, when the first RenameModel accesses state.apps. With Simon's patch I would expect it to be called a few times: once for each migration containing a RenameModel operation, and once when rendering the final project state.

comment:11 Changed 3 years ago by Claude Paroz

Triage Stage: UnreviewedAccepted

Would be nice to have the optimization in 1.10.2!

comment:12 Changed 3 years ago by Simon Charette

Sorry for missing the 1.10.2 deadline.

Thinking about it I like Marten's approach better as it deals with the limitation of RenameModel.state_forwards() directly and is easier to test.

@Marten, do you mind if I submit a PR with your patch and tests I would add?

comment:13 Changed 3 years ago by Marten Kenbeek

Sure, go ahead.

comment:14 Changed 3 years ago by Simon Charette

Has patch: set
Owner: changed from nobody to Simon Charette
Status: newassigned

comment:15 Changed 3 years ago by Tim Graham

Summary: Slow test framework initialization in 1.10.1 compared to 1.10Performance regression when running migrate with RenameModel operations
Triage Stage: AcceptedReady for checkin

comment:16 Changed 3 years ago by Simon Charette <charette.s@…>

Resolution: fixed
Status: assignedclosed

In 040bd7c:

Fixed #27279 -- Fixed a migration performance regression related to RenameModel operations.

Thanks Trac alias mtomiyoshi for the report, Marten Kenbeek for the initial
patch and Tim for the review.

comment:17 Changed 3 years ago by Simon Charette <charette.s@…>

In b122287:

[1.10.x] Fixed #27279 -- Fixed a migration performance regression related to RenameModel operations.

Thanks Trac alias mtomiyoshi for the report, Marten Kenbeek for the initial
patch and Tim for the review.

Backport of 040bd7c9387cfbf70a543c507b3b9eeb8f2725dc from master

Note: See TracTickets for help on using tickets.
Back to Top