Performance improvement unexpectedly small

[akleber]

After resolving my last issues I got back to do some performance tests on my main project and I see a surprisingly small performance improvement: I am building with ninja on a 24 core machine on a SSD. A build with empty cache takes about 48 min. The rebuild with a full cache takes about 30min. Here are the cache statistics for a cold and warm build.

clcache statistics:
  current cache dir         : D:\j2/clcache
  cache size                : 4,354,861,756 bytes
  maximum cache size        : 10,073,741,824 bytes
  cache entries             : 6476
  cache hits                : 6394
  cache misses
    total                      : 6476
    evicted                    : 0
    header changed             : 40
    source changed             : 6436
  passed to real compiler
    called w/ invalid argument : 0
    called for preprocessing   : 762
    called for linking         : 8
    called for external debug  : 22
    called w/o source          : 0
    called w/ multiple sources : 0
    called w/ PCH              : 0

I profiled both runs: prof4-cold.txt and prof4-warm.txt
If I read the 'warm' one correctly, most of the time is spend in computing file hashes, over 2 million times. Are these all the headers from all files? If this is correct, what I do not understand then, why the 'warm' case has a small amount of more calls to getFileHash() and why it takes more than double the time.
Any ideas or input how I might improve clcaches performance improvements?

FYI: My still unfinished lockfile mode does not change these numbers significantly. Also using xcopy instead of shutil.copyfile() or using readinto() instead of read() in getFileHash() does not change the situation.

[frerich]

Thanks for your thoughtful post! I agree with your initial analysis of the 'warm' profile: most of the time is spent in computing the hashes of about 2.1 million include files. The numbers you got match those you mentioned in an earlier comment of yours -- after working around what seems to be an inefficient usage of threads in the subprocess module, a large proportion of the time is spent in the getFileHash function.

Scrolling down in the profile report, one can see that almost all of the calls to getFileHash are triggered by a list comprehension in clcache.py:242 -- that is in the definition of the ManifestRepository.getIncludesContentHashForFiles method which is given a list of paths and then returns a list of file hashes. This method is called once for each entry in the computed manifest to see whether all include files used by a cache entry still have the last seen hash sum, i.e. to check whether we have a cache hit.

The difference in the number of calls to getFileHash between the warm and the cold profile is also visible in the 'callers' list further down in the profile report. This is the distribution of the calls per caller in the cold report:

clcache.py:747(getFileHash)                             <-    6435    0.555   11.960  clcache.py:224(getManifestHash)
                                                           2080352  145.234 13788.261  clcache.py:1388(<dictcomp>)

...and this is in the warm report:

clcache.py:747(getFileHash)                             <-    6435    0.627   18.588  clcache.py:224(getManifestHash)
                                                           2077999  149.706 29645.308  clcache.py:242(<listcomp>)
                                                             36998    2.241  317.594  clcache.py:1388(<dictcomp>)

That dictionary comprehension in clcache.py:1388 has been removed in the meanwhile, it's in createManifestEntry which is a function relevant when handling cache misses. I.e. even in the case of the 'warm' run, there are still cache misses -- and I think the list of include paths which are hashed is not cleansed from duplicates.

As for how to improve the situation, clearly there are two approaches:

1. Reduce the number of calls to getFileHash. Seeing that ManifestRepository.getIncludesContentHashForFiles is called in a loop (once for each entry in a manifest), there is clearly some chance that multiple entries reference the same includes, or that a single entry (unexpectedly) references to the same include twice. An easy way to improve this might be to use the functools.lru_cache decorator with getFileHash. I just opened Introduce memoization to getFileHash #240 to test this theory -- it would be much appreciated if you could give that PR a try!

   A more aggressive approach which would even avoid re-hashing files across multiple clcache invocations might be to launch a little server script which speaks e.g. JSON over HTTP or something convenient and which allows getting the hash sum of a file. The server could monitor the file system and mark cached hash sums as outdated in case the file on disk was modified.

2. Make getFileHash faster. IIRC, I noticed that exchanging the hash algorithm helped. In particular, sha1 or so was quite a bit faster (30%) than MD5. That aside, it might also be possible to optimize file reading a bit, but I don't know how -- reading the file contents into a data structure and then feeding that to the hashing module seems inefficient in comparison to reading the file contents in small blocks and feeding those to the hashing, but maybe it's not so bad after all.

[akleber]

Thanks for your input. I tried #240 but unfortunately it does not improve my timings. Which is a pitty as I like the idea of the lru_cache decorator very much. I added some lru_cache usage statistics output
cache_info_warm.txt. After each clcache run this statistic is printed, so we have about 6800 outputs (for every invocation). It is the output of a warm cache run and one can see that we have only very few clcache runs where we have lru_cache hits. In the cold case there is not one hit.
You were also right that I was using 3.3.0 before, because I missed the 3.3.1 release. This run here I did with the PR which is based on 3.3.1. As the hashes changed, I did a cold & warm run. They had the same timings as before.

[frerich]

Thanks for trying #240 - I suppose that if it doesn't help, it means that on every individual clcache run, (almost) no include was hashed twice -- which is good. However, seeing how over two million files get hashed when compiling about eight thousand files, I suspect that many source files simply end up using the same includes (e.g. windows.h).

I'm currently experimenting with different approaches to solve this; one thing which @vchigrin implemented about five years ago was a 'daemon' mode in which clcache (among other things) talks to servers via named pipes in order to cache the include hashes - it seems he did this with great success. The code is still available at https://github.com/vchigrin/clcache/tree/cacodaemons it seems.

I'm currently studying @vchigrin 's implementation as well as other local-host IPC mechanisms (TCP sockets appear to be way too slow for our purposes, unless I badly screwed up my usage of the socket API) to see whether there's anything nice.

[inorton]

I wonder if pypy would help hashing performance?

When I started cclash I briefly trialed python (which I love and use constantly for other stuff) but back then c# was somthing like 1000x faster than python at hashing files with md5 or sha1 (I even tried md4 in the quest for more speed).

My only real solution was to memoize the hash results and use a file monitor to re-hash on file changes by adopting a client/server model where the server was long lived and could therefore avoid repeatedly hashing the same windows headers or libs again and again.

[frerich]

@inorton pypy is an interesting idea, I'll give that a try - just for fun.

I looked closer at how the getFileHash function spends its time and had it hash 214 header files (those which are indirectly pulled in by just including windows.h...) a hundred times. This is the profiling output:

    21400    0.451    0.000    3.374    0.000 clcache.py:760(getFileHash)
    21400    0.010    0.000    0.010    0.000 {built-in method _hashlib.openssl_md5}
        1    0.000    0.000    3.461    3.461 {built-in method builtins.exec}
    21400    0.733    0.000    0.733    0.000 {built-in method io.open}
    21400    0.007    0.000    0.007    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
    21400    0.030    0.000    0.030    0.000 {method 'hexdigest' of '_hashlib.HASH' objects}
    21400    0.677    0.000    0.677    0.000 {method 'read' of '_io.BufferedReader' objects}
    21400    1.473    0.000    1.473    0.000 {method 'update' of '_hashlib.HASH' objects}

What's interesting here is that 21% of the time is spent in io.open and 20% is spent in _io.BufferedReader.read, i.e. about 41% is spent in I/O alone. The calls to the update method for updating the hash sum account for another 44% of the runtime. So the majority (85%) of the time is spent half in I/O, and half in computing the hash sums.

I suppose getting a faster hash sum is more likely to happen (in initial experiments, sha1 was faster than md5 for me...) but I wonder how to address the I/O issue. That might be something one indeed only can address by avoiding I/O in the first place and rather caching hash sums -- is that server you wrote which memoizes the hash results available somewhere? I suppose it could be a fairly generic piece of software which just sits somewhere, read from e.g. a named pipe and then replies with a hash sum.

I'll write a little C program for comparison to see how fast it could go if I talk to the Windows API directly.

[frerich]

Alas, the PyPy Download Page has no Windows binaries for PyPy for Python 3, and the page also warns that

this is an alpha release supporting the Python 3.3 language. It's also known to be (sometimes much) slower than PyPy 2

...so I think I'll not pursue that idea further for the time being.

[frerich]

For the record, two C programs I write which perform the same job (generating MD5 hash sums of 216 header files a hundred times) actually did not perform better than Python either: one uses the MD5 support features in the Windows standard libraries (I basically took the code from a Microsoft example) and the other uses the popular Aladdin MD5 code.

The Windows API version was slightly slower, but neither of the two versions was faster than the Python version -- the one based on Aladdin MD5 was actually exactly as fast as the Python version.

Based on this, I think Python itself is not to blame here - there's very little code happening in Python, the hash code calculation is in C (it seems it uses the Aladdin MD5 code) and the rest is I/O waiting for the operating system.

Maybe a viable alternative to a server process would be a database (a single, binary, file) which stores the modification times as well as the hashes of headers. If it was stored efficiently, it might be very fast to open the file, test for membership of a given path in the database, verify that the mtime is unchanged and then (if it is indeed unchanged) reuse the hash.

[akleber]

I took a look at the files getFileHash() hashes in my case. Of the 2 mio files 0.9 mio are system headers and 1.1 mio are files in my project. As the system headers are rarely changing maybe some kind of shortcut could be implemented there?
Might it be possible for example to specify to clcache a list of directories with files that are ignored when computing the resulting hash? Of course the user then whould have to make sure that the whole clcache-cache gets invalidated when the system headers change.

[akleber]

Intuitively I was surprised that generating the hashes would take this much time. To get a better picture I printed all 2 mio filenames passed to getFileHash() into a file. Then I wrote a small python script which reads in the 2 mio lines of filenames (takes less than 2 sec) and passes it to getFileHash(). All in one simple loop, so single threaded! On the same fast machine as before this takes 1000 sec. The profile of the warm cache run says something about 29274 sec for getFileHash() if I read it correctly. Any idea why this might be so much slower in the context of clcache? Maybe generating the hashes from 24 process lead to some kind of congestion? Am I missing something in the profile report?

[akleber]

Just analyzed how multiprocessing influences the numbers for my simple hashing only script. Single threaded: 1000s, 12 Processes: 1400s, 24 Processes: 1500s. I am using multiprocessing.Pool. So I think we see some congestion but nowhere near the numbers from the clcache profile reports.

[frerich]

In your multiprocessing experiment, you're dividing the list of 2M entries by th enumber of processes, right? I.e. a single process needed 1000s, 12 processes hashing ~166k files each take 1400s in total etc.? Two ideas came to my mind

1. There may be an overhead due to seek time, but seeing that you're using an SSD, that's probably not the case.
2. Maybe getFileHash accidentally opens the file for exclusive access, so there was some blocking when having more than one process hash a file, but that does not seem to be the case either.

Right now, I'm thinking about whether this is maybe related to the operating system or the file system. The individual Python processes are perfectly decoupled as far as I can see, but I can imagine that in order to check (or update?) ACLs (this might also be something which an Anti Virus scanner performs as part of it's on-the-fly-scanning) that there is some enforced synchronisation.

[frerich]

In #243 , moving clcache to xxhash was proposed and I already read good things about xxhash in the past. It might be interesting to see how much this can improve the run time for builds with warm caches in your use case.