Django 1.8.1 migrations are actually slower than 1.8?

[Peter Schmidt]

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

[Tim Graham]

We should at least clarify the release notes, I suppose.

[Marten Kenbeek]

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.

[Markus Holtermann]

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:

  django/db/migrations/executor.py

  @@ -104 +104 @@
               state = migration.mutate_state(state, preserve=do_run)
           if self.progress_callback:
               self.progress_callback("render_success")
  +        return
           # Phase 2 -- Run the migrations
           for migration, backwards in plan:
               if not backwards:

[Tim Graham]

Should we add this to the 1.8.1 release notes and remove the release blocker flag?

docs/releases/1.8.1.txt

@@ -93 +93 @@
 * Changed ``ModelState`` to deepcopy fields instead of deconstructing and
   reconstructing (:ticket:`24591`). This speeds up the rendering of model
   states and reduces memory usage when running :djadmin:`manage.py migrate
-  <migrate>`.
+  <migrate>` (although other changes in this release may negate any performance
+  benefits).

[Markus Holtermann]

Hey Tim, that looks reasonable to me.

[Tim Graham <timograham@…>]

In 81d4ce4:

Refs #24743 -- Clarified migrations performance note in 1.8.1 release notes.

[Tim Graham <timograham@…>]

In 7ea6477:

[1.8.x] Refs #24743 -- Clarified migrations performance note in 1.8.1 release notes.

Backport of 81d4ce4a6d21f0e65cabb253927770b3616cb560 from master

[Tim Graham]

Markus says he has an idea to improve performance here, so leaving the ticket open.

[Markus Holtermann]

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.

​https://github.com/django/django/pull/4653

[Peter Sanchez]

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.

[Hugo Tácito]

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

[Isaac Jurado]

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.

[Isaac Jurado]

Profiled run of command migrate

[M. Jackson Wilkinson]

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.

[Markus Holtermann]

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__)

[Markus Holtermann]

I rebased the current implementation onto the recent master in a new PR: ​https://github.com/django/django/pull/5125

[Markus Holtermann]

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:

django/core/management/commands/migrate.py

@@ -219 +219 @@
         else:
             fake = options.get("fake")
             fake_initial = options.get("fake_initial")
-            executor.migrate(targets, plan, fake=fake, fake_initial=fake_initial)
+            import cProfile
+            cProfile.runctx('executor.migrate(targets, plan, fake=fake, fake_initial=fake_initial)', globals(), locals(), filename='/tmp/stats.pstats')
+            # executor.migrate(targets, plan, fake=fake, fake_initial=fake_initial)
 
         # Send the post_migrate signal, so individual apps can do whatever they need
         # to do at this point.

django/db/migrations/executor.py

@@ -104 +104 @@
             state = migration.mutate_state(state, preserve=do_run)
         if self.progress_callback:
             self.progress_callback("render_success")
+        return
         # Phase 2 -- Run the migrations
         for migration, backwards in plan:
             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

[Markus Holtermann]

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.

[Hugo Tácito]

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

[Hugo Tácito]

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

[Hugo Tácito]

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.

[Markus Holtermann]

What do you mean with "freeze"? Endless loop? Running for some time and it gets slower?

[Hugo Tácito]

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)

[Hugo Tácito]

The pstat file: ​https://www.dropbox.com/s/c18k409qvwgn2bl/migrate4.pstats.gz?dl=0

[Markus Holtermann <info@…>]

In e1427cc6:

Fixed #24590 -- Cached calls to swappable_setting.

Moved the lookup in Field.swappable_setting to Apps, and added
an lru_cache to cache the results.

Refs #24743

Thanks Marten Kenbeek for the initial work on the patch. Thanks Aymeric
Augustin and Tim Graham for the review.

[Alistair Lynn]

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

[Markus Holtermann]

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.

[M. Jackson Wilkinson]

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!

[Peter Schmidt]

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 :)

[Markus Holtermann <info@…>]

In 5aa55038:

Fixed #24743, #24745 -- Optimized migration plan handling

The change partly goes back to the old behavior for forwards migrations
which should reduce the amount of memory consumption (#24745). However,
by the way the current state computation is done (there is no
state_backwards on a migration class) this change cannot be applied to
backwards migrations. Hence rolling back migrations still requires the
precomputation and storage of the intermediate migration states.

This improvement also implies that Django does not handle mixed
migration plans anymore. Mixed plans consist of a list of migrations
where some are being applied and others are being unapplied.

Thanks Andrew Godwin, Josh Smeaton and Tim Graham for the review as well
as everybody involved on the ticket that kept me looking into the issue.