During makemigrations Options._expire_cache takes 30% of the time

[Patryk Zawadzki]

Here's the profiler output:

         215373161 function calls (214826612 primitive calls) in 282.839 seconds

   Ordered by: internal time
   List reduced from 6484 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  5225318   59.334    0.000   89.667    0.000 django/db/models/options.py:711(_expire_cache)
 40538898   27.751    0.000   27.751    0.000 {delattr}
 16538241   18.624    0.000   38.450    0.000 django/apps/config.py:164(get_models)
   485536   16.907    0.000   27.126    0.000 django/db/models/fields/__init__.py:358(deconstruct)
  4466221   12.337    0.000   20.062    0.000 /usr/lib64/python2.7/collections.py:109(values)
    79811   10.893    0.000   53.060    0.001 django/apps/registry.py:153(get_models)
    73250   10.582    0.000   43.745    0.001 django/db/models/fields/related.py:317(swappable_setting)
   495362    8.314    0.000   11.430    0.000 django/db/models/fields/__init__.py:137(__init__)
 24359432    7.790    0.000    7.790    0.000 /usr/lib64/python2.7/collections.py:78(__iter__)
15623269/15397100    7.142    0.000    7.330    0.000 {getattr}

I have a pull request ready that makes it slightly better:

         164872486 function calls (164325937 primitive calls) in 199.897 seconds

   Ordered by: internal time
   List reduced from 6484 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
 16538241   18.580    0.000   38.545    0.000 django/apps/config.py:164(get_models)
   485536   16.290    0.000   26.736    0.000 django/db/models/fields/__init__.py:358(deconstruct)
  4466221   12.357    0.000   20.069    0.000 /usr/lib64/python2.7/collections.py:109(values)
    79811   10.933    0.000   53.182    0.001 django/apps/registry.py:153(get_models)
    73250   10.694    0.000   43.931    0.001 django/db/models/fields/related.py:317(swappable_setting)
  5225318    9.295    0.000    9.406    0.000 django/db/models/options.py:711(_expire_cache)
   495362    8.807    0.000   11.958    0.000 django/db/models/fields/__init__.py:137(__init__)
 24359432    7.777    0.000    7.777    0.000 /usr/lib64/python2.7/collections.py:78(__iter__)
15623269/15397100    7.316    0.000    7.504    0.000 {getattr}
        2    4.863    2.431    4.863    2.431 {raw_input}

[Patryk Zawadzki]

Pull request: ​https://github.com/django/django/pull/5649

[Marten Kenbeek]

Can you get a similar result using actual timing functions such as timeit? I've looked into this before, and if my memory serves me right the results of profiling in this case are highly skewed, and the actual improvements are barely noticeable.

Another thing to keep in mind is that #24397 greatly reduces the number of calls to _expire_cache().

[Patryk Zawadzki]

In my case it is noticeably faster even if the act of profiling itself skews the results by making function call more expensive. The slowest part was depending on try/except to trap nonexistent attributes. It may not make much difference in most projects but the one I work for takes several minutes to generate migrations.

[Marten Kenbeek]

It would be interesting to know why it makes such a difference in some projects, and none in others.

[Patryk Zawadzki]

I suppose with #24397 it will make a much smaller difference. In our case according to migrate --list there are 35 apps with 221 migrations.

[Tim Graham <timograham@…>]

In 7628f87e:

Fixed #25750 -- Made Options._expire_cache() faster

Avoided unnecessary list operations and delattr() calls that result
in an exception being raised as it causes call frame reconstruction
which is very costly, especially so in a function that is called
millions of times.