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

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)