Opened 14 years ago

Closed 14 years ago

Last modified 12 years ago

#12057 closed (fixed)

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

Reported by: Michael Thornhill Owned by: nobody
Component: Core (Cache system) Version: 1.1
Severity: Keywords:
Cc: Triage Stage: Accepted
Has patch: yes Needs documentation: no
Needs tests: no Patch needs improvement: yes
Easy pickings: no UI/UX: no

Description

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

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

Attachments (3)

django1.0_cache_read_defaultcallable.patch (1.5 KB ) - added by Michael Thornhill 14 years ago.
Test case for django 1.0.x showing that callables for default are NOT called on cache read
django1.1.1_cache_read_defaultcallable.patch (1.6 KB ) - added by Michael Thornhill 14 years ago.
Test case for django 1.1.1 showing that callables for default are called on cache read
prevent__init__on_pickle_load.patch (3.9 KB ) - added by Michael Thornhill 14 years ago.
Patch and test cases to prevent init being called when a model instance is loaded from a pickle

Download all attachments as: .zip

Change History (16)

comment:1 by Michael Thornhill, 14 years ago

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

by Michael Thornhill, 14 years ago

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

comment:2 by Thomas Güttler, 14 years ago

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.

by Michael Thornhill, 14 years ago

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

comment:3 by Michael Thornhill, 14 years ago

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

comment:4 by Michael Thornhill, 14 years ago

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.

comment:5 by Michael Thornhill, 14 years ago

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?

comment:6 by Michael Thornhill, 14 years ago

Has patch: set

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

comment:7 by Michael Thornhill, 14 years ago

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.

comment:8 by Russell Keith-Magee, 14 years ago

milestone: 1.2
Patch needs improvement: set
Triage Stage: UnreviewedAccepted

by Michael Thornhill, 14 years ago

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

comment:9 by Michael Thornhill, 14 years ago

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.

comment:10 by Russell Keith-Magee, 14 years ago

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.

comment:11 by Russell Keith-Magee, 14 years ago

Resolution: fixed
Status: newclosed

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

comment:12 by Russell Keith-Magee, 14 years ago

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

comment:13 by Jacob, 12 years ago

milestone: 1.2

Milestone 1.2 deleted

Note: See TracTickets for help on using tickets.
Back to Top