Issues

Issue #2379 resolved

time_func is not fine-grained enough to be used for LRUCache on Linux/alpha

Anonymous created an issue

The LRUCache uses time.time() on Linux platforms to get usage timestamps:

(from lib/sqlalchemy/util/_collections.py:773)

    def __getitem__(self, key):
        item = dict.__getitem__(self, key)
        item[2](2) = time_func()
        return item[0](0)
[...](...)

   def __setitem__(self, key, value):
        item = dict.get(self, key)
        if item is None:
            item = [value, time_func()](key,)
            dict.__setitem__(self, key, item)
        else:
            item[1](1) = value
        self._manage_size()

time_func is an alias to time.time on all non-win32, non-jython platforms (defined in ./lib/sqlalchemy/util/compat.py, around line 225).

The problem with this is that on Linux/alpha (probably other platforms, too), the timestamps as returned by time.time() do not carry enough precision (the Python Library Documentation even notes that some platforms only have whole-second-precision time() calls). When running the test suite, this makes test.base.test_utils.LRUTest.test_lru fail in random ways. After augmenting ./lib/sqlalchemy/util/_collections.py with some debugging output, running the test looks like this:

$ python sqla_nose.py test.base.test_utils
.................................set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
set timestamp: 1326964787.29
LRU state before first assert: [8, 9, 10, 11, 12, 13, 14, 18, 19](7,)
F............................
======================================================================
FAIL: test.base.test_utils.LRUTest.test_lru
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/root/src/SQLAlchemy-0.7.4/./test/base/test_utils.py", line 175, in test_lru
    assert id_ in l
AssertionError

----------------------------------------------------------------------
Ran 62 tests in 0.303s

FAILED (failures=1)

The problem is that the time stamps are identical for all entries, hence their removal becomes random, eventually making the assertions fail. Since the contents of the cache is basically random, some of the assertions might pass (like above, where the "1 and 2 are absent" assertions work fine), but usually, one of them fails. Still, it's quite possible that sometimes the cache accidentally looks like it's supposed to, making the test pass.

Since I don't know how extensively the LRUCache is used, I don't know if fixing the test suite by adding small delays is all that is needed. If the cache needs to guarantee strict ordering, a better timebase or special-casing is needed for platforms where time.time() is not up to the task.

Comments (5)

  1. Mike Bayer repo owner

    I've never seen that test fail and of course we run primarily on linux so this must be the "Alpha" thing coming into play. The LRU is not extensively used and also it doesn't need to be supremely accurate. Two solutions here might be just adding a delay to the test as you mention, or replacing the timestamp with an incrementing counter function instead. A patch for the latter is attached. The test still passes, how does it look to you ?

  2. Anonymous

    Yes, that patch makes it work on alpha. I'll include the patch in Gentoo (I'm the alpha arch team lead) until the next version of SQLAlchemy is released.

    Thanks a bunch!

  3. Log in to comment