Global cache lock hurts cache hits during heavily concurrent builds

[Un1oR]

Hi!
I tried to use clcache for my project and found speed up only on 35% (23 min vs 35 min). This result greatly embarrassed me because ccache at Linux and MacOS boost build time more then 10 times. I try change msbuild to ninja, but it gave similar results.
Then I suggested problem in long waits at lock (at other machine I even got crashes by timeouts). I try cut all lock logic and stats file overwriting. See diff below. Then build time became less then 7 min! It's more then 3 times faster. Looks like absolutely unacceptable overhead for writing statistics.
I'm not sure is access to manifests needs lock too, but looks if it is, we can do it more optimal. And about statistics, I think we can write simple server for writing it with locks, and clcache processes will just sent stat to server and exit without waiting responce. Or we can add option to disable statistics (and lock respectively) as quick fix.

--- a/clcache.py
+++ b/clcache.py
@@ -123,6 +123,7 @@ class ObjectCacheLock(object):
     WAIT_ABANDONED_CODE = 0x00000080

     def __init__(self, mutexName, timeoutMs):
+        return
         mutexName = 'Local\\' + mutexName
         self._mutex = windll.kernel32.CreateMutexW(
             wintypes.INT(0),
@@ -133,17 +134,21 @@ class ObjectCacheLock(object):
         assert self._mutex

     def __enter__(self):
+        return
         if not self._acquired:
             self.acquire()

     def __exit__(self, typ, value, traceback):
+        return
         if self._acquired:
             self.release()

     def __del__(self):
+        return
         windll.kernel32.CloseHandle(self._mutex)

     def acquire(self):
+        return
         result = windll.kernel32.WaitForSingleObject(
             self._mutex, wintypes.INT(self._timeoutMs))
         if result not in [0, self.WAIT_ABANDONED_CODE]:
@@ -154,6 +159,7 @@ class ObjectCacheLock(object):
         self._acquired = True

     def release(self):
+        return
         windll.kernel32.ReleaseMutex(self._mutex)
         self._acquired = False

@@ -373,8 +394,9 @@ class PersistentJSONDict(object):

     def save(self):
         if self._dirty:
-            with open(self._fileName, 'w') as f:
-                json.dump(self._dict, f, sort_keys=True, indent=4)
+            pass
+            #with open(self._fileName, 'w') as f:
+            #    json.dump(self._dict, f, sort_keys=True, indent=4)

     def __setitem__(self, key, value):
         self._dict[key] = value

[webmaster128]

I am sure, there is a potential for optimizations, but those timings sound like you have the worst possible setup: multiple parallel build jobs, slow harddisk, CLCACHE_HARDLINK disabled.

Could you add more information about your build setup?

[frerich]

@Un1oR thanks for sharing your findings! It's interesting that your patch actually improves the performance of cache hits so much. I agree that generating the statistics shouldn't have such a significant impact.

I'm curious though: how much does the patch you did to PersistentJSONDict.save help vs. the patches you did to the ObjectCacheLock file? I wonder whether there is indeed a big performance overhead caused by accessing the Windows API in ObjectCacheLock, or whether it just happens that flushing out the statistics in PersistentJSONDict.save is somehow very slow.

Making the generation and calculation of statistics can certainly be made optional if it helps in certain setups, but disabling the locking would really jeopardise correctness in case there are parallel compiler processes adding to or fetching from the object cache.

[Un1oR]

@webmaster128 CLCACHE_HARDLINK no gave appreciable effect. Disk is SSD KINGSTON SV310S37A960G. Number of parallel jobs is 4-16 for MSBuild (/M /MP4 at Xeon E3-1241) or 8 (not sure) for ninja. A smaller number of parallel processes behave in a similar way.

[Un1oR]

@frerich save method was modified only for prevent parallel writing and corruption of stats file (next read of corrupted file was failed). Looks only wait on lock has an impact to speed.

[webmaster128]

ccache uses 16 individual stats files for each cache directory [0-9a-f]. I assume this allows locking per directory, reducing the likelihood of waiting for a lock. The only point where locking the entire cache is needed is when the stats are accumulated for output and during a clean/clear run.
This could be implemented here too. The only difference is that we have 256 top directories, and thus 256 different locks and stats files.

[frerich]

I think having multiple statistics files which are accumulated when actually printing the stats is an interesting idea. Shouldn't be hard to implement!

It's not only the statistics which use the lock though, it's also the actual object cache. I.e. every time an object is to be restored from the cache, we first acquire the lock in order to avoid that some other clcache process removes the object at the same time.

So for the object cache, maybe we should distinguish read and write accesses to improve concurrency:

• A read access only blocks other write accesses, but concurrent read accesses are ok.
• A write access blocks both other write and other read accesses.

So in the case of having a lot of cache hits, you can get a lot more concurrency.

[webmaster128]

I would split the entire logic into 256 locks, including stats as well as writing and restoring objects. Manifests will need some special treatment.

Differentiating read/write is going to be hard, because restoring an object (read) always leads to stats updates (write).

[frerich]

You can use 256 locks for the stats, but you have to use one lock for the entire object cache: and write to the object cache may trigger trimming the cache, which affects the entirety of the object cache - not just a single subdirectory.

If we had a unique ("writer") lock for each of the 256 stats files and then a unique and a shared ("reader") lock for the actual object cache, then two objects could usually safely be restored in parallel because they

• Both only require read access to the object cache
• Both require write access to separate stats files, i.e. they don't block each other.

[webmaster128]

but you have to use one lock for the entire object cache

why?

[frerich]

I wrote it after the colon, but I did a typo: Instead of 'and' I meant to write 'any'. So my sentence should read:

you have to use one lock for the entire object cache: any write to the object cache may trigger trimming the cache, which affects the entirety of the object cache - not just a single subdirectory.

I.e. any write to the cache has the potential to discard the least-recently used objects in the cache, no matter in which of the 256 subdirectories they are.

I guess this means that trimming the cache will also have to lock all 256 stats. Maybe there should be a separate lock for the 'clean' action? My experience though is that more synchronization primitives rather complicate things. :-]

[frerich]

Actually, now that I think more about it, I think 256 plain exclusive locks may work out: when performing a 'clean', we just acquire all 256 of them and only then do our work. Otherwise, we only acquire whatever directory we're writing to.

[webmaster128]

When an object is added and holds one lock, it can easily acquire all 255 other locks in case a clean() needs to be done.

The only thing that is not available at the point before deciding, if clean() is needed: the accumulated cache size. But that can be handled be just performing clean in 1 out of 50 calls or so.

[frerich]

I think now we have an interesting reason to consider something like SQLite. I wonder whether it could efficiently handle write accesses to the same table, assuming that we would have a 'statistics' table where the first column are the two letters of the directory (say, af) and the other columns are the statistics like hits, misses etc..

Alas, on https://www.sqlite.org/lockingv3.html it seems that write accesses lock the entire database. Ugh!

Maybe if we had 256 separate databases? I wonder how trimming would work...

[webmaster128]

If we use Sqlite, we don't need to split stats at all. In WAL mode, you can just throw 100 += 1 operations from 100 processes onto a single cell.

But this only makes sense if we can release the clcache lock while updating stats. But then we risk divergence between objects and stats. (I can't come up with a case where this becomes problematic, but it does not feel right).

[frerich]

Leaving the SQLite idea aside, I think a sensible first step would be to add a performance test which serves as a baseline for how fast a completely cached and heavily concurrent build is (i.e. build a project, make clean, build it again - but with many concurrent processes). So we have a baseline to compare any efforts against.

The second step would be to split off a CacheSection class from ObjectCache. The idea being that a CacheSection corresponds to one of the 256 subdirectories beneath objects. It gets the methods for

• Testing for cache entries (i.e. ObjectCache.hasEntry)
• Fetching cached data (ObjetCache.cachedObjectName, .cachedCompilerOutput, .cachedCompilerStderr)
• Storing cache entries (ObjectCache.setEntry)

The ObjectCache class then provides a new ObjectCache.cacheSection(key) method which provides access to a section for the given key. A lot of the code can then be ported to actually only deal with a specific cache section.

In a third step, the statistics can be split such that CacheStatistics actually takes a CacheSection object. The command line option for dumping the statistics (or erasing them) then iterates over all cache sections and sums the values up.

In a last step, we can then introduce a lock member on CacheSection which can be used to synchronise accesses to just that section. This hopefully improves the performance checked by the test introduced in the beginning.