Opened 10 years ago
Closed 9 years ago
#24743 closed Cleanup/optimization (fixed)
Django 1.8.1 migrations are actually slower than 1.8?
Reported by: | Peter Schmidt | Owned by: | Markus Holtermann |
---|---|---|---|
Component: | Migrations | Version: | 1.8 |
Severity: | Normal | Keywords: | |
Cc: | Markus Holtermann, marten.knbk@…, chris@…, M. Jackson Wilkinson | 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 ¶
Ran time ./manage.py test <a_project>.<a_fast_app>
, results:
1m25.611s https://github.com/django/django/commit/2329ca969f81309bd3d15da55f25f8e1bee3122d
1m26.505s https://github.com/django/django/commit/0cacb8f8ba94b06a78dcdfa22dc406a8a20a7f88
0m36.864s https://github.com/django/django/commit/697317f3340b1d1f40586262098ad4dbae9aebaf
0m36.250s https://github.com/django/django/commit/516907540b81c009b74d29b2fa36319b47528b49
1m6.195s https://github.com/django/django/commit/43f800a978deba4bc8d13e7f11e0afdc126cec25
Some quick stats for our project - 134 models, 90 apps across 2 databases, 58 migrations in our django_migrations table (the bare minimum needed to get us through Django 1.7 and 1.8).
Thought I'd put it out there and see if others are getting similar overall slower results.
--
P.S. I don't really care either way what happens with ticket - take it, close it, whatever. I was just surprised that the migrations ran more slowly under 1.8.1 when the release notes suggested otherwise.
https://docs.djangoproject.com/en/1.8/releases/1.8.1/#optimizations
P.P.S. In practice migrations take sufficiently long relative to Django 1.6 that I've ended up building a --ramdb
option into https://github.com/pzrq/discover-road-runner which is why I don't really care a great deal anymore - the second (and next dozen) times a 2s unit test is run it takes around 2s instead of around one minute (to rerun the migrations over again, I haven't checked if --keepdb
has been updated since the 1.8 beta to work with in-memory SQLite databases).
Change History (36)
comment:1 by , 10 years ago
Cc: | added |
---|---|
Severity: | Normal → Release blocker |
Triage Stage: | Unreviewed → Accepted |
Type: | Uncategorized → Cleanup/optimization |
comment:2 by , 10 years ago
Cc: | added |
---|
In the specific benchmark setup I'm running, the patch for #24573 triples the amount of calls to ModelState.render()
. That's quite a lot, and explains why it is so much slower.
comment:3 by , 10 years ago
I profiled the executor.migrate()
call based on
- https://github.com/MarkusH/django-migrations-benchmark/tree/e2bd24755389668b34b87d254ec8ac63725dc56e
- https://github.com/django/django/tree/81f76517288eb386304f9cae23873b865945bc82 with this change:
-
TabularUnified django/db/migrations/executor.py
diff --git a/django/db/migrations/executor.py b/django/db/migrations/executor.py index 7dc0350..bf5dd15 100644
a b class MigrationExecutor(object): 104 104 state = migration.mutate_state(state, preserve=do_run) 105 105 if self.progress_callback: 106 106 self.progress_callback("render_success") 107 return 107 108 # Phase 2 -- Run the migrations 108 109 for migration, backwards in plan: 109 110 if not backwards:
-
by , 10 years ago
comment:4 by , 10 years ago
Should we add this to the 1.8.1 release notes and remove the release blocker flag?
-
TabularUnified docs/releases/1.8.1.txt
diff --git a/docs/releases/1.8.1.txt b/docs/releases/1.8.1.txt index b9fc816..b01b09e 100644
a b Optimizations 93 93 * Changed ``ModelState`` to deepcopy fields instead of deconstructing and 94 94 reconstructing (:ticket:`24591`). This speeds up the rendering of model 95 95 states and reduces memory usage when running :djadmin:`manage.py migrate 96 <migrate>`. 96 <migrate>` (although other changes in this release may negate any performance 97 benefits).
comment:5 by , 10 years ago
Triage Stage: | Accepted → Ready for checkin |
---|
Hey Tim, that looks reasonable to me.
comment:8 by , 10 years ago
Severity: | Release blocker → Normal |
---|---|
Triage Stage: | Ready for checkin → Accepted |
Markus says he has an idea to improve performance here, so leaving the ticket open.
comment:9 by , 10 years ago
Owner: | changed from | to
---|---|
Status: | new → assigned |
I have an experimental / play PR that groups consecutive migrations that need to be applied and only stores the state for the first of each of them. This should drastically reduce the amount of used memory.
comment:10 by , 10 years ago
Has anyone tested the PR yet? I haven't had a chance to yet. Upgrading a larger project from 1.7.x to 1.8.2 has migrations running very slow. See output here (note, this is on my MacBook Air, PG9, etc.):
(env)macbook ~/development/houselogic/src/houselogic $ time ./manage.py migrate --fake-initial Operations to perform: Synchronize unmigrated apps: google, rendertext, allauth, twitter, linkedin, django_extensions, typogrify, django_mobile, audioplayer, tinymce, cumulus, humanize, haystack, thumbnail, mptt, staticfiles, sitemaps, facebook, edialog, pipeline, sitecatalyst, messages, syndication, social_media Apply all migrations: redirects, openid, realtors, accounts, user_content, editorial_content, badges, layout, buying_selling, sites, comments, blog, contenttypes, work_queue, sweepstakes, main, core, django_comments, sessions, faq, auth, binder, news, account, admin, contest, modules, recommendations, twitter_logger, socialaccount Synchronizing apps without migrations: Creating tables... Running deferred SQL... Installing custom SQL... Running migrations: Rendering model states... DONE Applying account.0001_initial... FAKED Applying account.0002_email_max_length... OK Applying accounts.0004_auto_20150615_1533... OK Applying auth.0003_auto_20150615_1533... OK Applying badges.0003_auto_20150615_1533... OK Applying django_comments.0002_update_user_email_field_length... OK Applying blog.0004_auto_20150615_1533... OK Applying buying_selling.0004_auto_20150615_1533... OK Applying contenttypes.0002_remove_content_type_name... OK Applying django_comments.0003_auto_20141110_1644... OK Applying editorial_content.0007_auto_20150528_2042... OK Applying editorial_content.0008_video_source... OK Applying editorial_content.0009_navigationcategoryfeaturedlink_video... OK Applying editorial_content.0010_auto_20150618_1845... OK Applying editorial_content.0010_auto_20150615_1533... OK Applying editorial_content.0011_merge... OK Applying layout.0004_homepagecarouselitem_video... OK Applying layout.0005_auto_20150611_2216... OK Applying modules.0003_auto_20150615_1533... OK Applying news.0002_auto_20150615_1533... OK Applying openid.0001_initial... FAKED Applying realtors.0003_auto_20150615_1533... OK Applying socialaccount.0001_initial... FAKED real 7m4.016s user 6m48.144s sys 0m3.732s
The "Rendering model states" piece takes the longest. Over 5 minutes.
comment:11 by , 10 years ago
Cc: | added |
---|
comment:12 by , 10 years ago
Like petersanchez, I was upgrading a big project from 1.7.x to 1.8.2 . MacBook Air here too. Our project has
1900 ForeignKeyFields, 300 ManyToManyFields, 750 Models and 42 modules.
It took me 93 minutes just to render model states for the first time.
Operations to perform:
Synchronize unmigrated apps: pagination, ckeditor, staticfiles, rest_framework_swagger, django_extensions, django_tables2, djtools, rest_framework, django_tables2_reports
Apply all migrations: projetos, ae, ponto, frota, enquete, edu, financeiro, arquivo, patrimonio, estacionamento, authtoken, materiais, convenios, contratos, comum, contenttypes, remanejamento, almoxarifado, temp_ideias, rh, contracheques, protocolo, sessions, chaves, progressoes, auth, eleicao, cnpq, rsc, centralservicos, ldap_backend, processo_seletivo, admin, cpa, gestao, compras, orcamento, cursos, pdi, ferias, planejamento, microsoft
Synchronizing apps without migrations:
...
Running migrations:
Rendering model states... DONE (5554.627s)
Applying ae.0006_auto_20150619_1253... OK (26.600s)
...
After that I ran a new migration and the rendering model states dropped to 11 seconds.
Operations to perform:
Synchronize unmigrated apps: pagination, ckeditor, staticfiles, rest_framework_swagger, django_extensions, django_tables2, djtools, rest_framework, django_tables2_reports
Apply all migrations: projetos, ae, ponto, frota, enquete, edu, financeiro, arquivo, patrimonio, estacionamento, authtoken, materiais, convenios, contratos, comum, contenttypes, remanejamento, almoxarifado, temp_ideias, rh, contracheques, protocolo, sessions, chaves, progressoes, auth, eleicao, cnpq, rsc, centralservicos, ldap_backend, processo_seletivo, admin, cpa, gestao, compras, orcamento, cursos, pdi, ferias, planejamento, microsoft
Synchronizing apps without migrations:
...
Running migrations:
Rendering model states... DONE (11.538s)
Applying edu.0028_historicoimportacao_alunos_afetados... OK (5.851s)
...
comment:13 by , 10 years ago
We also experience a noticeable increase in the rendering model state step. Apparently, the most expensive operation is AddField
even when running only in state mutation mode.
The attached profile results can be inspected by running python -m pstats migrate2.pstats
.
comment:14 by , 9 years ago
Cc: | added |
---|
We've been frustrated by this issue since 1.8 hit, seeing the same impacts as previous posters – the "Rendering model states" step taking several minutes when running fresh, which most notably impacts our testing environments.
Our current "workaround," if you can call it that, is skipping migrations in testing except when testing our master branch, and squashing migrations as much as possible. Still, the vast majority of the time it takes to run our tests is consumed by this "Rendering model states" step.
I tossed in MarkusH's PR (mentioned in comment:9) this morning, and ran migrate
against a fresh database three times against stock 1.8.3, and three times with the changes from the PR:
1.8.3 – Min: 4m56s, Max: 5m32s, Avg: 5m26s
PR – Min: 32s, Max: 39s, Avg: 34s
Specifically, the Rendering models states step went from about 4.5 mins to three or four seconds.
comment:15 by , 9 years ago
Thank you etanol! Here is the output of the first rows sorted by "cumtime". This clearly shows (from my perspective) a high expense in the model's meta class: django/db/models/base.py:72(__new__)
1538924506 function calls (1535110811 primitive calls) in 1483.255 seconds Ordered by: cumulative time ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 1483.272 1483.272 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/core/management/base.py:369(run_from_argv) 16/1 0.001 0.000 1483.270 1483.270 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/core/management/base.py:404(execute) 1 0.008 0.008 1482.956 1482.956 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/core/management/commands/migrate.py:55(handle) 1 0.003 0.003 1473.721 1473.721 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/migrations/executor.py:65(migrate) 1809 0.501 0.000 1471.618 0.813 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/migrations/state.py:91(reload_model) 148 0.008 0.000 1468.430 9.922 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/migrations/migration.py:72(mutate_state) 1536 0.610 0.000 1441.001 0.938 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/migrations/state.py:252(render_multiple) 239262 8.476 0.000 1440.390 0.006 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/migrations/state.py:520(render) 1352 0.058 0.000 1124.941 0.832 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/migrations/operations/fields.py:43(state_forwards) 300486/239262 13.254 0.000 834.475 0.003 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/base.py:72(__new__) 4083939 21.946 0.000 595.130 0.000 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/migrations/state.py:488(construct_fields) 300486 1.486 0.000 498.434 0.002 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/migrations/state.py:285(register_model) 302024 29.834 0.000 496.382 0.002 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/apps/registry.py:334(clear_cache) 40673088 270.223 0.000 388.286 0.000 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/options.py:711(_expire_cache) 5237503/4808935 7.485 0.000 320.286 0.000 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/base.py:321(add_to_class) 734946 2.335 0.000 263.046 0.000 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/utils/lru_cache.py:94(wrapper) 522243 40.921 0.000 255.000 0.000 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/apps/registry.py:153(get_models) 430612 81.365 0.000 240.780 0.001 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/fields/related.py:309(swappable_setting) 369388 1.661 0.000 232.581 0.001 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/fields/related.py:1867(deconstruct) 369388 2.692 0.000 230.388 0.001 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/fields/related.py:1551(deconstruct) 105539832 90.430 0.000 200.647 0.000 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/apps/config.py:164(get_models) 233 0.012 0.000 197.541 0.848 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/migrations/operations/fields.py:172(state_forwards) 3844735 113.134 0.000 176.851 0.000 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/fields/__init__.py:358(deconstruct) 61224 0.902 0.000 170.041 0.003 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/fields/related.py:2518(contribute_to_class) 61224 3.381 0.000 161.656 0.003 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/fields/related.py:2048(create_many_to_many_intermediary_model) 314498387 110.460 0.000 110.460 0.000 {delattr} 115 0.006 0.000 106.834 0.929 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/migrations/operations/models.py:519(state_forwards) 21800334 69.904 0.000 106.573 0.000 /usr/lib/python2.7/collections.py:104(values) 4028349 7.703 0.000 105.095 0.000 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/fields/__init__.py:655(contribute_to_class) 4028349 11.031 0.000 72.275 0.000 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/options.py:289(add_field) 300486 3.620 0.000 72.108 0.000 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/base.py:328(_prepare) 4032533 53.182 0.000 71.715 0.000 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/fields/__init__.py:137(__init__) 1686026 13.135 0.000 64.277 0.000 /home/isaac/virtualenvs/bookcore/local/lib/python2.7/site-packages/django/db/models/fields/__init__.py:1080(__init__)
comment:16 by , 9 years ago
I rebased the current implementation onto the recent master in a new PR: https://github.com/django/django/pull/5125
comment:17 by , 9 years ago
I thought about giving the rendering another improvement, but before diving in I ran cProfile on the rendering model states
phase on the current stable/1.8.x branch (0e3a8c22dfbbe06a9a81afb2593255293efdc87e) and master (97ac77e544f9b1d1f28c0f859bef8fbc195d81a5) with the following diff applied:
-
TabularUnified django/core/management/commands/migrate.py
diff --git a/django/core/management/commands/migrate.py b/django/core/management/commands/migrate.py index d26fd3d..40dca0b 100644
a b class Command(BaseCommand): 219 219 else: 220 220 fake = options.get("fake") 221 221 fake_initial = options.get("fake_initial") 222 executor.migrate(targets, plan, fake=fake, fake_initial=fake_initial) 222 import cProfile 223 cProfile.runctx('executor.migrate(targets, plan, fake=fake, fake_initial=fake_initial)', globals(), locals(), filename='/tmp/stats.pstats') 224 # executor.migrate(targets, plan, fake=fake, fake_initial=fake_initial) 223 225 224 226 # Send the post_migrate signal, so individual apps can do whatever they need 225 227 # to do at this point. -
TabularUnified django/db/migrations/executor.py
diff --git a/django/db/migrations/executor.py b/django/db/migrations/executor.py index aeb021e..2c08ab3 100644
a b class MigrationExecutor(object): 104 104 state = migration.mutate_state(state, preserve=do_run) 105 105 if self.progress_callback: 106 106 self.progress_callback("render_success") 107 return 107 108 # Phase 2 -- Run the migrations 108 109 for migration, backwards in plan: 109 110 if not backwards:
This yield the attached pstats files with my "benchmark" repository https://github.com/MarkusH/django-migrations-benchmark. I put the output of the first ~40 rows into a gist (better readability): https://gist.github.com/MarkusH/0c5d30449cdf7f1961f6 . What one can see is a reduction by almost 50%.
Can somebody confirm this improvement in one of their real world projects, please.
This is on Python 3.4.3 on ArchLinux
by , 9 years ago
Attachment: | stats-1.8.4.pstats added |
---|
by , 9 years ago
Attachment: | stats-master.pstats added |
---|
follow-up: 29 comment:18 by , 9 years ago
Here's another approach that partly goes back to the old behavior: https://github.com/django/django/pull/5178
Could you all please run your migrations on that pull request and give some feedback.
At least forwards migrations should be faster.
comment:19 by , 9 years ago
Has patch: | set |
---|---|
Needs documentation: | set |
comment:20 by , 9 years ago
Hello markush, the first PR: https://github.com/django/django/pull/5125 didn't improved the speed... I'm gonna test asap the other PR, but the problem is that the test takes a long time. And I have to run on an idle machine to not impact in results.
-> % time python -m cProfile -o migrate2.pstats manage.py migrate -v 3 Operations to perform: Synchronize unmigrated apps: pagination, ckeditor, staticfiles, rest_framework_swagger, django_extensions, django_tables2, saude, djtools, rest_framework, django_tables2_reports Apply all migrations: projetos, ae, ... Synchronizing apps without migrations: Running pre-migrate handlers for application auth Running pre-migrate handlers for application contenttypes Running pre-migrate handlers for application sessions Running pre-migrate handlers for application djtools Running pre-migrate handlers for application admin ... Creating tables... Running deferred SQL... Installing custom SQL... Loading 'initial_data' fixtures... Checking '/Users/hugo/workspace/suap' for fixtures... No fixture 'initial_data' in '/Users/hugo/workspace/suap'. ... Running migrations: Rendering model states... DONE (7598.382s) Applying ae.0009_auto_20150819_1451... OK (32.787s) Applying arquivo.0004_auto_20150819_1451... OK (5.327s) Applying contenttypes.0002_remove_content_type_name... OK (14.731s) Applying auth.0002_alter_permission_name_max_length... OK (4.936s) Applying auth.0003_alter_user_email_max_length... OK (5.118s) Applying auth.0004_alter_user_username_opts... OK (5.106s) Applying auth.0005_alter_user_last_login_null... OK (6.599s) Applying auth.0006_require_contenttypes_0002... OK (0.015s) ... Running post-migrate handlers for application auth Running post-migrate handlers for application contenttypes Running post-migrate handlers for application sessions Running post-migrate handlers for application djtools Running post-migrate handlers for application admin ... python -m cProfile -o migrate3.pstats manage.py migrate -v 3 7671.55s user 93.25s system 92% cpu 2:20:36.92 total
comment:21 by , 9 years ago
Unfortunatly the pstat file was too big to fit in this ticket system so I uploaded it to dropbox https://www.dropbox.com/s/x22vjeog1ev1bdv/migrate3.pstats.gz?dl=0
comment:22 by , 9 years ago
The PR https://github.com/django/django/pull/5178 dropped down the Rendering model states to 5 seconds in my project. But at some point the migrations freeze (usually when goes to execute the migrations from a third module).
PS: My project is not compliant with django 1.9 yet, so i copied the content from the PR to django 1.8.4. Probably thats the problem with the freezing.
comment:23 by , 9 years ago
What do you mean with "freeze"? Endless loop? Running for some time and it gets slower?
comment:24 by , 9 years ago
Hello markus, after running for some time it gets very slower (like 5 minutes) in between the change of modules. It doesn't go to endless loop.
Example:
Applying financial.0007_auto_20150819_1451... OK (24.984s)
(long wait)
Applying fleet.0004_auto_20150819_1451... OK (17.156s)
(long wait)
Applying parking.0004_auto_20150819_1451... OK (11.604s)
(long wait)
Applying poll.0014_auto_20150805_1413... OK (9.664s)
Applying poll.0015_auto_20150819_1451... OK (34.831s)
(long wait)
Applying protocol.0003_auto_20150819_1451... OK (10.068s)
comment:25 by , 9 years ago
follow-up: 28 comment:27 by , 9 years ago
For what it's worth, this patch greatly improved model state rendering for us:
diff -r /tmp/saved-django/db/migrations/executor.py contrib/django/db/migrations/executor.py 99,100d98 < if 'apps' not in state.__dict__: < state.apps # Render all real_apps -- performance critical
comment:28 by , 9 years ago
Replying to prophile:
For what it's worth, this patch greatly improved model state rendering for us:
diff -r /tmp/saved-django/db/migrations/executor.py contrib/django/db/migrations/executor.py 99,100d98 < if 'apps' not in state.__dict__: < state.apps # Render all real_apps -- performance critical
Not really, it just delays the rendering.
The Rendering model state
will be faster, yes. But instead of rendering the models there, Django will render them when applying the migrations. At that phase it might even look like migrations are stuck.
follow-up: 30 comment:29 by , 9 years ago
Replying to MarkusH:
Here's another approach that partly goes back to the old behavior: https://github.com/django/django/pull/5178
Could you all please run your migrations on that pull request and give some feedback.
Yup, brings the "rendering model states" step down to practically zero, and no obvious side effects or other unexpected impacts. Looking forward to this!
comment:30 by , 9 years ago
Replying to mjacksonw:
Replying to MarkusH:
Here's another approach that partly goes back to the old behavior: https://github.com/django/django/pull/5178
Could you all please run your migrations on that pull request and give some feedback.
Yup, brings the "rendering model states" step down to practically zero, and no obvious side effects or other unexpected impacts. Looking forward to this!
+1 here - hope it makes it into Django 1.9 and gives people more good reasons to upgrade.
I backported (poorly, though it's a reasonably clean cherry-pick in just bringing in some extra unused 1.9 stuff) to 1.8.x:
https://github.com/pzrq/django/compare/stable/1.8.x...backport_for_test_24743
With that I get a >50% speedup from 5m59.611s to 2m54.410s when running the built in time ./manage.py test <a_project>.<a_fast_app>
. Not comparable to the originally reported timings as we've added a lot of migrations, but a very welcome speedup either way :)
comment:31 by , 9 years ago
Needs documentation: | unset |
---|---|
Triage Stage: | Accepted → Ready for checkin |
We should at least clarify the release notes, I suppose.