Caching performance regression between django 1.0 and django 1.1.1 with callables as default on model fields

[Michael Thornhill]

In django 1.0 reading from the cache is a fast operation however in
django 1.1.1 reading from cache causes all fields with a callable as
default to be called.

In the case where that callable is an expensive operation the
performance is severely affected.

I've created patches showing this regression for the 1.1.1 branch:

1. ​http://code.djangoproject.com/svn/django/branches/releases/1.0.X

callable only called at creation, test case passes

2. ​http://code.djangoproject.com/svn/django/branches/releases/1.1.X

which shows the default callable being called at creation and on cache read (test case fails)

[Michael Thornhill]

I should have mentioned in the initial report that this bug report relates to caching of model instances.

[Michael Thornhill]

Test case for django 1.0.x showing that callables for default are NOT called on cache read

[Thomas Güttler]

If you raise an exception in expensive_calculation() if num_run>1 you could see where the method is called. Please show the traceback here.

[Michael Thornhill]

Test case for django 1.1.1 showing that callables for default are called on cache read

[Michael Thornhill]

Revised patch for django 1.1.1 prints the traceback 3 times (once each for DBCache, File and LocMem), here is the File based traceback

File "./tests/runtests.py", line 191, in <module>
    django_tests(int(options.verbosity), options.interactive, args)
  File "./tests/runtests.py", line 161, in django_tests
    failures = test_runner(test_labels, verbosity=verbosity, interactive=interactive, extra_tests=extra_tests)
  File "/home/mick/src/django111/django/django/test/simple.py", line 192, in run_tests
    result = unittest.TextTestRunner(verbosity=verbosity).run(suite)
  File "/usr/lib/python2.6/unittest.py", line 753, in run
    test(result)
  File "/usr/lib/python2.6/unittest.py", line 464, in __call__
    return self.run(*args, **kwds)
  File "/usr/lib/python2.6/unittest.py", line 460, in run
    test(result)
  File "/usr/lib/python2.6/unittest.py", line 300, in __call__
    return self.run(*args, **kwds)
  File "/usr/lib/python2.6/unittest.py", line 279, in run
    testMethod()
  File "/home/mick/src/django111/django/tests/regressiontests/cache/tests.py", line 220, in test_model_instance
    cached_poll = self.cache.get('question')
  File "/home/mick/src/django111/django/django/core/cache/backends/filebased.py", line 50, in get
    return pickle.load(f)
  File "/home/mick/src/django111/django/django/db/models/base.py", line 305, in __init__
    val = field.get_default()
  File "/home/mick/src/django111/django/django/db/models/fields/__init__.py", line 244, in get_default
    return self.default()
  File "/home/mick/src/django111/django/tests/regressiontests/cache/models.py", line 9, in expensive_calculation
    traceback.print_stack()

[Michael Thornhill]

This is also an issue with django trunk r11367.
The difference between django 1.0 and django trunk seems to be related to what is pickled when you cache a model object.
In Django 1.0 reading the cached pickle does not call django.db.models.base.Model.init
in Django 1.1.1+ reading the cached pickle does call django.db.models.base.Model.init and hence callables that are set as default.

[Michael Thornhill]

I've had a further look into this and it seems this behaviour is being caused by the

__reduce__

method in django.db.models.base.Model
ref (​http://docs.python.org/library/pickle.html).
The "reduce" method doesn't exist on the django 1.0 branch
From the comment on the reduce method

Provide pickling support. Normally, this just dispatches to Python's
standard handling. However, for models with deferred field loading, we
need to do things manually, as they're dynamically created classes and
only module-level classes can be pickled by the default path.

it seems that pickling support is required for models with deferred field loading.
Anyone any ideas on how this can be supported without forcing a models

__init__

method to be called on loading a pickled model instance?

[Michael Thornhill]

I've made a branch for this bug on ​http://github.com/mthornhill/django (master branch) and have come up with a possible solution
The test cases pass and prevent __init__ being called for every model instance that is unpickled.
It's not a very elegant solution as it relies on a hardcoded string. It would be great to get other possible solutions to this.
The attached patch prevent__init__on_pickle_load.patch contains all the new code

[Michael Thornhill]

Added an improved patch to solve the problem for models without deferred fields (Thanks to Russell Keith Magee).
Models with deferred fields still exhibit this behaviour and the patch adds a test case to show this.

[Michael Thornhill]

Patch and test cases to prevent init being called when a model instance is loaded from a pickle

[Michael Thornhill]

More research on this shows that cache reading (unpickling) works fine for models with and without deferred fields with the patch.
However cache setting (pickling) for models with deferred fields causes a model instances __init__ function to be called (source:/django/trunk/django/db/models/query.py@11669#L241 )
I have modified the patch prevent__init__on_pickle_load.patch to add a third test case for cache setting showing that __init__ is being called for deferred models on pickle.
Is this by design?
If so then I can modify the test case to make the test pass.

[Russell Keith-Magee]

The callable default shouldn't be invoked in this case. Your test case here was enough to point out the problem - I'm about to commit a fix. Thanks for the help diagnosing this.

[Russell Keith-Magee]

(In [11681]) Fixed #12057 -- Corrected regression of caching performance when a model contained a callable default. Thanks to Michael Thornhill for the excellent assistance tracking this problem.

[Russell Keith-Magee]

(In [11682]) [1.1.X] Fixed #12057 -- Corrected regression of caching performance when a model contained a callable default. Thanks to Michael Thornhill for the excellent assistance tracking this problem.

Backport of r11681 from trunk.

[Jacob]

Milestone 1.2 deleted