view tests/test-propertycache.py @ 38732:be4984261611

merge: mark file gets as not thread safe (issue5933)

In default installs, this has the effect of disabling the thread-based
worker on Windows when manifesting files in the working directory. My
measurements have shown that with revlog-based repositories, Mercurial
spends a lot of CPU time in revlog code resolving file data. This ends
up incurring a lot of context switching across threads and slows down
`hg update` operations when going from an empty working directory to
the tip of the repo.

On mozilla-unified (246,351 files) on an i7-6700K (4+4 CPUs):

before: 487s wall
after:  360s wall (equivalent to worker.enabled=false)
cpus=2: 379s wall

Even with only 2 threads, the thread pool is still slower.

The introduction of the thread-based worker (02b36e860e0b) states that
it resulted in a "~50%" speedup for `hg sparse --enable-profile` and
`hg sparse --disable-profile`. This disagrees with my measurement
above. I theorize a few reasons for this:

1) Removal of files from the working directory is I/O - not CPU - bound
   and should benefit from a thread pool (unless I/O is insanely fast
   and the GIL release is near instantaneous). So tests like `hg sparse
   --enable-profile` may exercise deletion throughput and aren't good
   benchmarks for worker tasks that are CPU heavy.
2) The patch was authored by someone at Facebook. The results were
   likely measured against a repository using remotefilelog. And I
   believe that revision retrieval during working directory updates with
   remotefilelog will often use a remote store, thus being I/O and not
   CPU bound. This probably resulted in an overstated performance gain.

Since there appears to be a need to enable the thread-based worker with
some stores, I've made the flagging of file gets as thread safe
configurable. I've made it experimental because I don't want to formalize
a boolean flag for this option and because this attribute is best
captured against the store implementation. But we don't have a proper
store API for this yet. I'd rather cross this bridge later.

It is possible there are revlog-based repositories that do benefit from
a thread-based worker. I didn't do very comprehensive testing. If there
are, we may want to devise a more proper algorithm for whether to use
the thread-based worker, including possibly config options to limit the
number of threads to use. But until I see evidence that justifies
complexity, simplicity wins.

Differential Revision: https://phab.mercurial-scm.org/D3963

"""test behavior of propertycache and unfiltered propertycache

The repoview overlay is quite complex. We test the behavior of
property cache of both localrepo and repoview to prevent
regression."""

from __future__ import absolute_import, print_function
import os
import subprocess

from mercurial import (
    hg,
    localrepo,
    ui as uimod,
    util,
)

# create some special property cache that trace they call

calllog = []
@util.propertycache
def testcachedfoobar(repo):
    name = repo.filtername
    if name is None:
        name = ''
    val = len(name)
    calllog.append(val)
    return val

unficalllog = []
@localrepo.unfilteredpropertycache
def testcachedunfifoobar(repo):
    name = repo.filtername
    if name is None:
        name = ''
    val = 100 + len(name)
    unficalllog.append(val)
    return val

#plug them on repo
localrepo.localrepository.testcachedfoobar = testcachedfoobar
localrepo.localrepository.testcachedunfifoobar = testcachedunfifoobar


# Create an empty repo and instantiate it. It is important to run
# these tests on the real object to detect regression.
repopath = os.path.join(os.environ['TESTTMP'], 'repo')
assert subprocess.call(['hg', 'init', repopath]) == 0
ui = uimod.ui.load()
repo = hg.repository(ui, path=repopath).unfiltered()


print('')
print('=== property cache ===')
print('')
print('calllog:', calllog)
print('cached value (unfiltered):',
    vars(repo).get('testcachedfoobar', 'NOCACHE'))

print('')
print('= first access on unfiltered, should do a call')
print('access:', repo.testcachedfoobar)
print('calllog:', calllog)
print('cached value (unfiltered):',
    vars(repo).get('testcachedfoobar', 'NOCACHE'))

print('')
print('= second access on unfiltered, should not do call')
print('access', repo.testcachedfoobar)
print('calllog:', calllog)
print('cached value (unfiltered):',
    vars(repo).get('testcachedfoobar', 'NOCACHE'))

print('')
print('= first access on "visible" view, should do a call')
visibleview = repo.filtered('visible')
print('cached value ("visible" view):',
    vars(visibleview).get('testcachedfoobar', 'NOCACHE'))
print('access:', visibleview.testcachedfoobar)
print('calllog:', calllog)
print('cached value (unfiltered):',
    vars(repo).get('testcachedfoobar', 'NOCACHE'))
print('cached value ("visible" view):',
    vars(visibleview).get('testcachedfoobar', 'NOCACHE'))

print('')
print('= second access on "visible view", should not do call')
print('access:', visibleview.testcachedfoobar)
print('calllog:', calllog)
print('cached value (unfiltered):',
    vars(repo).get('testcachedfoobar', 'NOCACHE'))
print('cached value ("visible" view):',
    vars(visibleview).get('testcachedfoobar', 'NOCACHE'))

print('')
print('= no effect on other view')
immutableview = repo.filtered('immutable')
print('cached value ("immutable" view):',
    vars(immutableview).get('testcachedfoobar', 'NOCACHE'))
print('access:', immutableview.testcachedfoobar)
print('calllog:', calllog)
print('cached value (unfiltered):',
    vars(repo).get('testcachedfoobar', 'NOCACHE'))
print('cached value ("visible" view):',
    vars(visibleview).get('testcachedfoobar', 'NOCACHE'))
print('cached value ("immutable" view):',
    vars(immutableview).get('testcachedfoobar', 'NOCACHE'))

# unfiltered property cache test
print('')
print('')
print('=== unfiltered property cache ===')
print('')
print('unficalllog:', unficalllog)
print('cached value (unfiltered):      ',
    vars(repo).get('testcachedunfifoobar', 'NOCACHE'))
print('cached value ("visible" view):  ',
    vars(visibleview).get('testcachedunfifoobar', 'NOCACHE'))
print('cached value ("immutable" view):',
    vars(immutableview).get('testcachedunfifoobar', 'NOCACHE'))

print('')
print('= first access on unfiltered, should do a call')
print('access (unfiltered):', repo.testcachedunfifoobar)
print('unficalllog:', unficalllog)
print('cached value (unfiltered):      ',
    vars(repo).get('testcachedunfifoobar', 'NOCACHE'))

print('')
print('= second access on unfiltered, should not do call')
print('access (unfiltered):', repo.testcachedunfifoobar)
print('unficalllog:', unficalllog)
print('cached value (unfiltered):      ',
    vars(repo).get('testcachedunfifoobar', 'NOCACHE'))

print('')
print('= access on view should use the unfiltered cache')
print('access (unfiltered):      ', repo.testcachedunfifoobar)
print('access ("visible" view):  ', visibleview.testcachedunfifoobar)
print('access ("immutable" view):', immutableview.testcachedunfifoobar)
print('unficalllog:', unficalllog)
print('cached value (unfiltered):      ',
    vars(repo).get('testcachedunfifoobar', 'NOCACHE'))
print('cached value ("visible" view):  ',
    vars(visibleview).get('testcachedunfifoobar', 'NOCACHE'))
print('cached value ("immutable" view):',
    vars(immutableview).get('testcachedunfifoobar', 'NOCACHE'))

print('')
print('= even if we clear the unfiltered cache')
del repo.__dict__['testcachedunfifoobar']
print('cached value (unfiltered):      ',
    vars(repo).get('testcachedunfifoobar', 'NOCACHE'))
print('cached value ("visible" view):  ',
    vars(visibleview).get('testcachedunfifoobar', 'NOCACHE'))
print('cached value ("immutable" view):',
    vars(immutableview).get('testcachedunfifoobar', 'NOCACHE'))
print('unficalllog:', unficalllog)
print('access ("visible" view):  ', visibleview.testcachedunfifoobar)
print('unficalllog:', unficalllog)
print('cached value (unfiltered):      ',
    vars(repo).get('testcachedunfifoobar', 'NOCACHE'))
print('cached value ("visible" view):  ',
    vars(visibleview).get('testcachedunfifoobar', 'NOCACHE'))
print('cached value ("immutable" view):',
    vars(immutableview).get('testcachedunfifoobar', 'NOCACHE'))
print('access ("immutable" view):', immutableview.testcachedunfifoobar)
print('unficalllog:', unficalllog)
print('cached value (unfiltered):      ',
    vars(repo).get('testcachedunfifoobar', 'NOCACHE'))
print('cached value ("visible" view):  ',
    vars(visibleview).get('testcachedunfifoobar', 'NOCACHE'))
print('cached value ("immutable" view):',
    vars(immutableview).get('testcachedunfifoobar', 'NOCACHE'))
print('access (unfiltered):      ', repo.testcachedunfifoobar)
print('unficalllog:', unficalllog)
print('cached value (unfiltered):      ',
    vars(repo).get('testcachedunfifoobar', 'NOCACHE'))
print('cached value ("visible" view):  ',
    vars(visibleview).get('testcachedunfifoobar', 'NOCACHE'))
print('cached value ("immutable" view):',
    vars(immutableview).get('testcachedunfifoobar', 'NOCACHE'))