[Django] #27279: Slow test framework initialization in 1.10.1 compared to 1.10
Django
--------------------------------------+--------------------
Reporter: mtomiyoshi | Owner: nobody
Type: Cleanup/optimization | Status: new
Component: Testing framework | Version: 1.10
Severity: Normal | Keywords:
Triage Stage: Unreviewed | Has patch: 0
Easy pickings: 0 | UI/UX: 0
--------------------------------------+--------------------
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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27279>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
Django
Reporter: mtomiyoshi | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.10
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 Tim Graham):
* cc: Simon Charette (added)
* needs_better_patch: => 0
* component: Testing framework => Migrations
* needs_tests: => 0
* needs_docs: => 0
Comment:
Not sure what, if anything, can be done.
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:1>
Django
Reporter: mtomiyoshi | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Marten Kenbeek):
* cc: marten.knbk@… (added)
Comment:
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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:2>
Django
Reporter: mtomiyoshi | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (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`
[https://github.com/django/django/commit/d5c4ea524679a787fe11c927448e44e95646096b
#diff-191c6b8087fd8fb2cc08a2d9f9bf44deR79 on every step] of `mutate_state`
as `reload_model()` is a noop when `state.apps`
[https://github.com/django/django/blob/master/django/db/migrations/state.py#L104
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()`
[https://github.com/django/django/commit/d5c4ea524679a787fe11c927448e44e95646096b
#diff-191c6b8087fd8fb2cc08a2d9f9bf44deR81 here] should speed up things
significantly.
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:3>
Django
Reporter: mtomiyoshi | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Changes (by mtomiyoshi):
* Attachment "profile_results.tar.gz" added.
Django
Reporter: mtomiyoshi | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:4>
Django
Reporter: mtomiyoshi | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (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`.
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:5>
Django
Reporter: mtomiyoshi | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by mtomiyoshi):
I found 5 migrations with RenameModels on my project, so not that much, I
think!
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:6>
Django
Reporter: mtomiyoshi | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Simon Charette):
Replying to [comment:6 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
[https://github.com/django/django/blob/9c522d2ed8e752932bfff62d6e2940e56dee700b/django/db/migrations/state.py#L176
this return statement] to make sure it's mostly triggered by
`RenameModel.state_forwards` during the state mutation process.
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:7>
Django
Reporter: mtomiyoshi | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (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?
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:8>
Django
Reporter: mtomiyoshi | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Marten Kenbeek):
* Attachment "renamemodel-reset-apps.patch" added.
Django
Reporter: mtomiyoshi | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:9>
Django
Reporter: mtomiyoshi | Owner: nobody
Type: | Status: new
Cleanup/optimization |
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
| Unreviewed
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (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 [comment:9 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:10>
Django
Reporter: mtomiyoshi | Owner: nobody
Type: Cleanup/optimization | Status: new
Severity: Normal | Resolution:
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Claude Paroz):
* stage: Unreviewed => Accepted
Comment:
Would be nice to have the optimization in 1.10.2!
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:11>
Django
Reporter: mtomiyoshi | Owner: nobody
Type: Cleanup/optimization | Status: new
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (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?
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:12>
Django
Reporter: mtomiyoshi | Owner: nobody
Type: Cleanup/optimization | Status: new
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Marten Kenbeek):
Sure, go ahead.
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:13>
Django
Reporter: mtomiyoshi | Owner: Simon
Type: | Charette
Cleanup/optimization | Status: assigned
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Simon Charette):
* status: new => assigned
* owner: nobody => Simon Charette
* has_patch: 0 => 1
Comment:
[https://github.com/django/django/pull/7336 PR]
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:14>
Django
-------------------------------------+-------------------------------------
Reporter: mtomiyoshi | Owner: Simon
Type: | Charette
Cleanup/optimization | Status: assigned
Component: Migrations | Version: 1.10
Severity: Normal | Resolution:
| checkin
Has patch: 1 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Tim Graham):
* stage: Accepted => Ready for checkin
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:15>
Django
-------------------------------------+-------------------------------------
Reporter: mtomiyoshi | Owner: Simon
Type: | Charette
Component: Migrations | Version: 1.10
Severity: Normal | Resolution: fixed
Keywords: | Triage Stage: Ready for
| checkin
Has patch: 1 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Simon Charette <charette.s@…>):
* status: assigned => closed
* resolution: => fixed
Comment:
In [changeset:"040bd7c9387cfbf70a543c507b3b9eeb8f2725dc" 040bd7c]:
{{{
#!CommitTicketReference repository=""
revision="040bd7c9387cfbf70a543c507b3b9eeb8f2725dc"
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.
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:16>
Django
-------------------------------------+-------------------------------------
Reporter: mtomiyoshi | Owner: Simon
Type: | Charette
Cleanup/optimization | Status: closed
Component: Migrations | Version: 1.10
Severity: Normal | Resolution: fixed
Keywords: | Triage Stage: Ready for
| checkin
Has patch: 1 | Needs documentation: 0
Easy pickings: 0 | UI/UX: 0
Comment (by Simon Charette <charette.s@…>):
In [changeset:"b12228759ce1aa0c93a00ed53e382ecf25cd5398" b122287]:
{{{
#!CommitTicketReference repository=""
revision="b12228759ce1aa0c93a00ed53e382ecf25cd5398"
[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
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/27279#comment:17>