Opened 5 years ago

Closed 5 years ago

Last modified 4 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: mt 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: UI/UX:

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 mt 5 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 mt 5 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 mt 5 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 Changed 5 years ago by mt

  • Needs documentation unset
  • Needs tests unset
  • Patch needs improvement unset

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

Changed 5 years ago by mt

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

comment:2 Changed 5 years ago by guettli

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.

Changed 5 years ago by mt

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

comment:3 Changed 5 years ago by mt

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 Changed 5 years ago by mt

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 Changed 5 years ago by mt

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 Changed 5 years ago by mt

  • 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 Changed 5 years ago by mt

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 Changed 5 years ago by russellm

  • milestone set to 1.2
  • Patch needs improvement set
  • Triage Stage changed from Unreviewed to Accepted

Changed 5 years ago by mt

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

comment:9 Changed 5 years ago by mt

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 Changed 5 years ago by russellm

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 Changed 5 years ago by russellm

  • Resolution set to fixed
  • Status changed from new to closed

(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 Changed 5 years ago by russellm

(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 Changed 4 years ago by jacob

  • milestone 1.2 deleted

Milestone 1.2 deleted

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