Patchwork [2,of,2,LOG-SPEED-FIX] repoview: cache filtered changelog

login
register
mail settings
Submitter Pierre-Yves David
Date Jan. 18, 2013, 10:49 p.m.
Message ID <8de68237ff6885eac13b.1358549397@yamac.lan>
Download mbox | patch
Permalink /patch/677/
State Accepted
Commit 4d92e2d75cffac5038b5b23c16f77cee8640dab2
Headers show

Comments

Pierre-Yves David - Jan. 18, 2013, 10:49 p.m.
# HG changeset patch
# User Pierre-Yves David <pierre-yves.david@logilab.fr>
# Date 1358549012 -3600
# Node ID 8de68237ff6885eac13b2c1d64eb3ad8c4cae562
# Parent  b6f71d62f8f7a1fb027891ee0acee2e3a015d8b9
repoview: cache filtered changelog

Creating a new changelog object for each access is costly and prevents efficient
caching changelog side. This introduced a x5 performance regression in log
because chunk read from disk were never reused. We were jumping from about 100
disk read to about 20 000.

This changeset introduce a simple cache mechanism that help the last changelog
object created by a repoview. The changelog is reused until the changelog or the
filtering changes.

The cache invalidation is much more complicated than it should be. But MQ test
show a strange cache desync. I was unable to track down the source of this
desync in descent time so I'm not sure if the issue is in MQ or core. However
given the proximity to the 2.5 freeze, I'm choosing the inelegant but safe route
that makes the cache mechanism safer.
Pierre-Yves David - Jan. 19, 2013, 12:39 a.m.
On 18 janv. 2013, at 23:49, Pierre-Yves David wrote:

> # HG changeset patch
> # User Pierre-Yves David <pierre-yves.david@logilab.fr>
> # Date 1358549012 -3600
> # Node ID 8de68237ff6885eac13b2c1d64eb3ad8c4cae562
> # Parent  b6f71d62f8f7a1fb027891ee0acee2e3a015d8b9
> repoview: cache filtered changelog
> 
> Creating a new changelog object for each access is costly and prevents efficient
> caching changelog side. This introduced a x5 performance regression in log
> because chunk read from disk were never reused. We were jumping from about 100
> disk read to about 20 000.
> 
> This changeset introduce a simple cache mechanism that help the last changelog
> object created by a repoview. The changelog is reused until the changelog or the
> filtering changes.
> 
> The cache invalidation is much more complicated than it should be. But MQ test
> show a strange cache desync. I was unable to track down the source of this
> desync in descent time so I'm not sure if the issue is in MQ or core. However
> given the proximity to the 2.5 freeze, I'm choosing the inelegant but safe route
> that makes the cache mechanism safer.

The Siddharth Agarwal fix for atime (ecba9b0e7672) does not help to remove the crazyness of MQ
Idan Kamara - Jan. 19, 2013, 9:26 a.m.
On Sat, Jan 19, 2013 at 12:49 AM, Pierre-Yves David <
pierre-yves.david@ens-lyon.org> wrote:
>
> # HG changeset patch
> # User Pierre-Yves David <pierre-yves.david@logilab.fr>
> # Date 1358549012 -3600
> # Node ID 8de68237ff6885eac13b2c1d64eb3ad8c4cae562
> # Parent  b6f71d62f8f7a1fb027891ee0acee2e3a015d8b9
> repoview: cache filtered changelog
>
> Creating a new changelog object for each access is costly and prevents
> efficient
> caching changelog side. This introduced a x5 performance regression in log
> because chunk read from disk were never reused. We were jumping from about
> 100
> disk read to about 20 000.
>
> This changeset introduce a simple cache mechanism that help the last
> changelog
> object created by a repoview. The changelog is reused until the changelog
> or the
> filtering changes.
>
> The cache invalidation is much more complicated than it should be. But MQ
> test
> show a strange cache desync. I was unable to track down the source of this
> desync in descent time so I'm not sure if the issue is in MQ or core.
> However
> given the proximity to the 2.5 freeze, I'm choosing the inelegant but safe
> route
> that makes the cache mechanism safer.

Wild guess, but maybe it has something to do with the filecache? You
added another cache here that isn't naturally synced with the underlying
changelog, which could change under your feet.

To test this, try adding the id() of the changelog to your key.

>
> diff --git a/mercurial/repoview.py b/mercurial/repoview.py
> --- a/mercurial/repoview.py
> +++ b/mercurial/repoview.py
> @@ -153,20 +153,43 @@ class repoview(object):
>      """
>
>      def __init__(self, repo, filtername):
>          object.__setattr__(self, '_unfilteredrepo', repo)
>          object.__setattr__(self, 'filtername', filtername)
> +        object.__setattr__(self, '_clcachekey', None)
> +        object.__setattr__(self, '_clcache', None)
>
>      # not a cacheproperty on purpose we shall implement a proper cache
> later
>      @property
>      def changelog(self):
>          """return a filtered version of the changeset
>
>          this changelog must not be used for writing"""
>          # some cache may be implemented later
> -        cl = copy.copy(self._unfilteredrepo.changelog)
> -        cl.filteredrevs = filterrevs(self._unfilteredrepo,
> self.filtername)
> +        unfi = self._unfilteredrepo
> +        unfichangelog = unfi.changelog
> +        revs = filterrevs(unfi, self.filtername)
> +        cl = self._clcache
> +        newkey = (len(unfichangelog), unfichangelog.tip(), hash(revs))
> +        if cl is not None:
> +            # we need to check curkey too for some obscure reason.
> +            # MQ test show a corruption of the underlying repo (in
> _clcache)
> +            # without change in the cachekey.
> +            oldfilter = cl.filteredrevs
> +            try:
> +                cl.filterrevs = ()  # disable filtering for tip
> +                curkey = (len(cl), cl.tip(), hash(oldfilter))
> +            finally:
> +                cl.filteredrevs = oldfilter
> +            if newkey != self._clcachekey or newkey != curkey:
> +                cl = None
> +        # could have been made None by the previous if
> +        if cl is None:
> +            cl = copy.copy(unfichangelog)
> +            cl.filteredrevs = revs
> +            object.__setattr__(self, '_clcache', cl)
> +            object.__setattr__(self, '_clcachekey', newkey)
>          return cl
>
>      def unfiltered(self):
>          """Return an unfiltered version of a repo"""
>          return self._unfilteredrepo
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@selenic.com
> http://selenic.com/mailman/listinfo/mercurial-devel
Pierre-Yves David - Jan. 22, 2013, 1:56 p.m.
On Sat, Jan 19, 2013 at 11:26:20AM +0200, Idan Kamara wrote:
> On Sat, Jan 19, 2013 at 12:49 AM, Pierre-Yves David <
> pierre-yves.david@ens-lyon.org> wrote:
> >
> > # HG changeset patch
> > # User Pierre-Yves David <pierre-yves.david@logilab.fr>
> > # Date 1358549012 -3600
> > # Node ID 8de68237ff6885eac13b2c1d64eb3ad8c4cae562
> > # Parent  b6f71d62f8f7a1fb027891ee0acee2e3a015d8b9
> > repoview: cache filtered changelog
> >
> > Creating a new changelog object for each access is costly and prevents
> > efficient
> > caching changelog side. This introduced a x5 performance regression in log
> > because chunk read from disk were never reused. We were jumping from about
> > 100
> > disk read to about 20 000.
> >
> > This changeset introduce a simple cache mechanism that help the last
> > changelog
> > object created by a repoview. The changelog is reused until the changelog
> > or the
> > filtering changes.
> >
> > The cache invalidation is much more complicated than it should be. But MQ
> > test
> > show a strange cache desync. I was unable to track down the source of this
> > desync in descent time so I'm not sure if the issue is in MQ or core.
> > However
> > given the proximity to the 2.5 freeze, I'm choosing the inelegant but safe
> > route
> > that makes the cache mechanism safer.
> 
> Wild guess, but maybe it has something to do with the filecache? You
> added another cache here that isn't naturally synced with the underlying
> changelog, which could change under your feet.
>
> To test this, try adding the id() of the changelog to your key.

We are making a copy of the changelog and keep this copy in cache.
We have a cache key to detect when the underlying changelog has changed and make a new copy.

The issue here is that the cached copy got altered become out of sync with the
cache key It may comes from something altering the copy directly instead of
touching the original or from the copy reading some data with a different timing.

The behavior is shown by `test-mq.t` at about 60% of the test a qrefresh fails
because the repoview.changelog have 2 changesets instead of 3.

The corruption seems to be trackable back to line 1554 of `mercurial/patch.py`:

    node1 = repo.dirstate.p1()

After this line, repo.changelog have a truncated concent. Reading
repo.changelog before the line make the error vanish.

It definitly looks some kind of racy cache stuff.

To reproduce this you just need to disable the double check of the value in
addition of the cache key (In `mercurial/repoview.py`)

Patch

diff --git a/mercurial/repoview.py b/mercurial/repoview.py
--- a/mercurial/repoview.py
+++ b/mercurial/repoview.py
@@ -153,20 +153,43 @@  class repoview(object):
     """
 
     def __init__(self, repo, filtername):
         object.__setattr__(self, '_unfilteredrepo', repo)
         object.__setattr__(self, 'filtername', filtername)
+        object.__setattr__(self, '_clcachekey', None)
+        object.__setattr__(self, '_clcache', None)
 
     # not a cacheproperty on purpose we shall implement a proper cache later
     @property
     def changelog(self):
         """return a filtered version of the changeset
 
         this changelog must not be used for writing"""
         # some cache may be implemented later
-        cl = copy.copy(self._unfilteredrepo.changelog)
-        cl.filteredrevs = filterrevs(self._unfilteredrepo, self.filtername)
+        unfi = self._unfilteredrepo
+        unfichangelog = unfi.changelog
+        revs = filterrevs(unfi, self.filtername)
+        cl = self._clcache
+        newkey = (len(unfichangelog), unfichangelog.tip(), hash(revs))
+        if cl is not None:
+            # we need to check curkey too for some obscure reason.
+            # MQ test show a corruption of the underlying repo (in _clcache)
+            # without change in the cachekey.
+            oldfilter = cl.filteredrevs
+            try:
+                cl.filterrevs = ()  # disable filtering for tip
+                curkey = (len(cl), cl.tip(), hash(oldfilter))
+            finally:
+                cl.filteredrevs = oldfilter
+            if newkey != self._clcachekey or newkey != curkey:
+                cl = None
+        # could have been made None by the previous if
+        if cl is None:
+            cl = copy.copy(unfichangelog)
+            cl.filteredrevs = revs
+            object.__setattr__(self, '_clcache', cl)
+            object.__setattr__(self, '_clcachekey', newkey)
         return cl
 
     def unfiltered(self):
         """Return an unfiltered version of a repo"""
         return self._unfilteredrepo