[Django] #24554: Migrations taking close to an hour to run
Django
--------------------------------------+--------------------
Reporter: ryanahall | Owner: nobody
Type: Cleanup/optimization | Status: new
Component: Migrations | Version: 1.7
Severity: Normal | Keywords:
Triage Stage: Unreviewed | Has patch: 0
Easy pickings: 0 | UI/UX: 0
--------------------------------------+--------------------
We're currently running django 1.7.2 and been having performance issues
with migrate/makemigrations for the last few months now, but until
recently it hasn't caused us too much trouble. Recently,
migrate/makemigrations calls have reached a point where they take up to
45minutes to run. Unfortunately, this is due to the fact that we have
around 700 models defined with almost 850 migrations since the initial
project. Regardless, I've been looking for any ways to speed this process
up in 1.7.2/1.7.7/1.8b2/master and found that we have a significant
bottleneck with the way states are cloned.
Out of curiousity, I profiled latest master against a set of ~7 migrations
to run and found this:
{{{
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.001 0.001 2687.730 2687.730 manage.py:2(<module>)
1 0.000 0.000 2687.669 2687.669
django/core/management/__init__.py:325(execute_from_command_line)
1 0.000 0.000 2687.669 2687.669
django/core/management/__init__.py:265(execute)
1 0.000 0.000 2680.113 2680.113
django/core/management/base.py:326(run_from_argv)
1 0.002 0.002 2680.111 2680.111
django/core/management/base.py:361(execute)
1 0.198 0.198 2678.912 2678.912
django/core/management/commands/migrate.py:50(handle)
1 10.405 10.405 2676.084 2676.084
django/db/migrations/executor.py:65(migrate)
803 0.024 0.000 2581.336 3.215
django/db/migrations/migration.py:72(mutate_state)
7528892 36.422 0.000 1578.058 0.000
django/db/migrations/state.py:468(construct_fields)
4137 0.504 0.000 1470.027 0.355
django/db/migrations/state.py:81(reload_model)
847 0.012 0.000 1192.585 1.408
django/db/migrations/state.py:135(clone)
847 0.939 0.001 1171.224 1.383
django/db/migrations/state.py:138(<dictcomp>)
402948 6.238 0.000 1170.285 0.003
django/db/migrations/state.py:488(clone)
}}}
In migration.py(mutate_state), the project state gets cloned before
applying the operations everytime. I realize that the project state is
intended to be immutable since the intermediary states need to be used
most of the time, but I'm curious if it is required. During phase 1 of
migration execution, the state gets cloned on every iteration inside
mutate_state at line 90:
{{{#!python
for migration, _ in full_plan:
if migration in migrations_to_run:
states[migration] = state.clone()
state = migration.mutate_state(state) # state is cloned
inside
}}}
and also in migrations/graph.py(make_state) at line 274:
{{{#!python
for node in plan:
project_state = self.nodes[node].mutate_state(project_state)
}}}
If I modify mutate_state and add an option to not preserve (no clone) the
passed in state in these specific cases, the migration time is cut in
half:
{{{
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.001 0.001 955.337 955.337 manage.py:2(<module>)
1 0.000 0.000 955.269 955.269
django/core/management/__init__.py:325(execute_from_command_line)
1 0.000 0.000 955.269 955.269
django/core/management/__init__.py:265(execute)
1 0.000 0.000 946.453 946.453
django/core/management/base.py:326(run_from_argv)
1 0.002 0.002 946.450 946.450
django/core/management/base.py:361(execute)
1 0.169 0.169 945.012 945.012
django/core/management/commands/migrate.py:50(handle)
1 0.006 0.006 941.582 941.582
django/db/migrations/executor.py:65(migrate)
4137 0.387 0.000 869.433 0.210
django/db/migrations/state.py:81(reload_model)
803 0.020 0.000 863.434 1.075
django/db/migrations/migration.py:72(mutate_state)
100499 28.233 0.000 405.016 0.004
django/apps/registry.py:323(clear_cache)
1753 0.027 0.000 399.287 0.228
django/db/migrations/operations/fields.py:43(state_forwards)
}}}
My question is: does the state need to be cloned in mutate_state during
phase 1? The intermediary states are thrown away besides the explicit
calls to clone here:
{{{#!python
if migration in migrations_to_run:
states[migration] = state.clone()
}}}
I can create create a pull request if you'd like to see.
--
Ticket URL: <https://code.djangoproject.com/ticket/24554>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.7
Severity: Normal | Resolution:
Keywords: | Triage Stage:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by ryanahall):
* needs_better_patch: => 0
* needs_docs: => 0
* needs_tests: => 0
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:1>
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.7
Severity: Normal | Resolution:
Keywords: | Triage Stage:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Description changed by ryanahall:
Old description:
New description:
Here's an example commit with this change:
https://github.com/ryanahall/django/commit/a4777e11d8950bd86b07d00ff2d291567c7ba0ff
--
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:2>
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: ryanahall
Type: | Status: assigned
Cleanup/optimization |
Component: Migrations | Version: 1.7
Severity: Normal | Resolution:
Keywords: | Triage Stage:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Changes (by ryanahall):
* status: new => assigned
* owner: nobody => ryanahall
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:3>
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: ryanahall
Type: | Status: assigned
Cleanup/optimization |
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Changes (by knbk):
* version: 1.7 => master
* stage: Unreviewed => Accepted
Comment:
At first glance this looks like an effective and safe way to speed up
migrations.
Could you also check how 888c9b6429a44824078a49fb1ebacf2e950cd887 affects
the migration time on your project? I'm quite curious how much of a
difference that will make.
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:4>
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: ryanahall
Type: | Status: assigned
Cleanup/optimization |
Component: Migrations | Version: master
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by MarkusH):
Hey Ryan, thanks for reporting the issue. Would you mind checking our
https://github.com/django/django/pull/4151 . Besides the change you made
above (except for the part where you touch the graph) it also incorporates
some further speedups. Maybe we can squeeze it in 1.8
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:5>
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: ryanahall
Type: | Status: assigned
Cleanup/optimization |
Component: Migrations | Version: master
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by ryanahall):
@knbk thanks for pointing out that change, I'll pull it and give it a
shot. I also just commented on my pr, but for the sake of consistency I'll
put it here as well.
Thanks for the quick response @MarkusH, I just pulled that pr's branch and
tested it out - looks good to me! Here's the output from cProfile this
time around:
{{{
1 0.001 0.001 1047.865 1047.865 manage.py:2(<module>)
1 0.000 0.000 1047.800 1047.800
/django/core/management/__init__.py:325(execute_from_command_line)
1 0.000 0.000 1047.800 1047.800
/django/core/management/__init__.py:265(execute)
1 0.000 0.000 1040.621 1040.621
/django/core/management/base.py:326(run_from_argv)
1 0.002 0.002 1040.619 1040.619
/django/core/management/base.py:361(execute)
1 0.174 0.174 1039.459 1039.459
/django/core/management/commands/migrate.py:50(handle)
1 0.084 0.084 1036.643 1036.643
/django/db/migrations/executor.py:65(migrate)
3851 0.329 0.000 958.341 0.249
/django/db/migrations/state.py:87(reload_model)
800 0.014 0.000 953.813 1.192
/django/db/migrations/migration.py:72(mutate_state)
3153 0.178 0.000 455.806 0.145
/django/db/migrations/state.py:230(render_multiple)
133631 31.220 0.000 438.594 0.003
/django/apps/registry.py:323(clear_cache)
56702 2.274 0.000 425.492 0.008
/django/db/migrations/state.py:505(render)
1745 0.021 0.000 420.844 0.241
/django/db/migrations/operations/fields.py:43(state_forwards)
62640 0.281 0.000 407.227 0.007
/django/db/migrations/state.py:279(unregister_model)
1166 0.031 0.000 402.408 0.345
/django/db/migrations/operations/fields.py:172(state_forwards)
1358075 6.334 0.000 383.427 0.000
/django/db/migrations/state.py:474(construct_fields)
30963570 233.718 0.000 347.263 0.000
/django/db/models/options.py:712(_expire_cache)
139593 116.218 0.001 253.901 0.002
/django/db/models/fields/related.py:297(swappable_setting)
127628 0.681 0.000 238.117 0.002
/django/db/models/fields/related.py:1927(deconstruct)
127628 1.165 0.000 237.204 0.002
/django/db/models/fields/related.py:1635(deconstruct)
}}}
For reference, most of the time was spent while rendering the states which
was expected.
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:6>
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: ryanahall
Type: | Status: assigned
Cleanup/optimization |
Component: Migrations | Version: master
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by ryanahall):
Actually @knbk, it looks like I've been profiling with that commit all
along. I pulled master yesterday, so these results are fairly recent.
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:7>
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: ryanahall
Cleanup/optimization |
Component: Migrations | Version: master
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Markus Holtermann <info@…>):
* status: assigned => closed
* resolution: => fixed
Comment:
In [changeset:"57dc8dd3fa3c3adf133c522ecadb501d94bacd52" 57dc8dd3]:
{{{
#!CommitTicketReference repository=""
revision="57dc8dd3fa3c3adf133c522ecadb501d94bacd52"
Fixed #24554 -- Sped up migrations by rendering initial apps when they are
first needed
Calling Migration.mutate_state() now also allows to do in_place
mutations in case an intermediate state is thrown away later.
Thanks Anssi Kääriäinen for the idea, Ryan Hall for parts of the patch,
and Claude Paroz and Tim Graham for the review
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:8>
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: ryanahall
Type: | Status: closed
Cleanup/optimization |
Component: Migrations | Version: master
Severity: Normal | Resolution: fixed
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Markus Holtermann <info@…>):
In [changeset:"3e7d9d05ac5efff4e4732c3453c7a8ef502d0ed0" 3e7d9d05]:
{{{
#!CommitTicketReference repository=""
revision="3e7d9d05ac5efff4e4732c3453c7a8ef502d0ed0"
Refs #24554 -- Prevented rendering of unused migrations
Thanks Claude Paroz and Tim Graham for the review
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:9>
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: ryanahall
Type: | Status: closed
Cleanup/optimization |
Component: Migrations | Version: master
Severity: Normal | Resolution: fixed
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Markus Holtermann <info@…>):
In [changeset:"2218f7617e6192a706bf7792db34b034765263e2" 2218f761]:
{{{
#!CommitTicketReference repository=""
revision="2218f7617e6192a706bf7792db34b034765263e2"
[1.8.x] Refs #24554 -- Prevented rendering of unused migrations
Thanks Claude Paroz and Tim Graham for the review
Backport of 3e7d9d05ac5efff4e4732c3453c7a8ef502d0ed0 from master
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:11>
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: ryanahall
Type: | Status: closed
Cleanup/optimization |
Component: Migrations | Version: master
Severity: Normal | Resolution: fixed
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Markus Holtermann <info@…>):
In [changeset:"0c7e2833d9b6f0bbd847d9b9b0eb368611425f7c" 0c7e283]:
{{{
#!CommitTicketReference repository=""
revision="0c7e2833d9b6f0bbd847d9b9b0eb368611425f7c"
[1.8.x] Fixed #24554 -- Sped up migrations by rendering initial apps when
they are first needed
Calling Migration.mutate_state() now also allows to do in_place
mutations in case an intermediate state is thrown away later.
Thanks Anssi Kääriäinen for the idea, Ryan Hall for parts of the patch,
and Claude Paroz and Tim Graham for the review
Backport of 57dc8dd3fa3c3adf133c522ecadb501d94bacd52 from master
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:10>
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: ryanahall
Type: | Status: closed
Cleanup/optimization |
Component: Migrations | Version: master
Severity: Normal | Resolution: fixed
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:12>
Django
-------------------------------------+-------------------------------------
Reporter: ryanahall | Owner: ryanahall
Type: | Status: closed
Cleanup/optimization |
Component: Migrations | Version: master
Severity: Normal | Resolution: fixed
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Tim Graham <timograham@…>):
In [changeset:"8f987323791181783d3f1ba847ffc0a938ddccdf" 8f987323]:
{{{
#!CommitTicketReference repository=""
revision="8f987323791181783d3f1ba847ffc0a938ddccdf"
Added Ryan Hall to AUTHORS. Refs #24554
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/24554#comment:13>