Performance regression when running migrate with RenameModel operations

[mtomiyoshi]

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.

[Tim Graham]

Not sure what, if anything, can be done.

[Marten Kenbeek]

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.

[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.

[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.

[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.

[mtomiyoshi]

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

[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.

[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?

[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.

[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.

[Claude Paroz]

Would be nice to have the optimization in 1.10.2!

[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?

[Marten Kenbeek]

Sure, go ahead.

[Simon Charette]

​PR

[Simon Charette <charette.s@…>]

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.

[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