is ccache working effectively?

Thu Nov 8 20:31:01 UTC 2018

Hello,

On 2018-11-08 10:58, Maurizio Cimadamore wrote:
> Hi,
> I've observed that the time spent in C/CPP compilation during a JDK 
> build seems to have crept higher lately. By monitoring processes 
> during the build I found an awful lot of c++ compilations taking 
> place, which was surprising since I'm setup to use ccache.
>
Interesting, I stopped using it myself a long time ago.
> So I decided to run some more precise analysis of what's going on - 
> and I set up builds in two machine (one with Ubuntu 16.04 and another 
> with Ubuntu 18.04) and monitor ccache statistics; the results I got in 
> both machines are very similar, ruling out toolchain issues and the 
> likes (I think).
>
> So, I started up by resetting ccache stats history with
>
> $ ccache -z
>
> then cleared ccache
>
> $ ccache -C
>
> then fired up a release build:
>
> $ make clean images
>
> After which I displayed ccache stats:
>
> $ ccache -s
>
> stats zero time                     Thu Nov  8 18:05:19 2018
> cache hit (direct)                     0
> cache hit (preprocessed)               0
> cache miss                          1747
> cache hit rate                      0.00 %
> cleanups performed                    16
> files in cache                      5222
> cache size                         410.5 MB
> max cache size                       5.0 GB
>
>
> Ok, that's fine, all misses - after all I just cleared up everything. 
> So, I cleaned and built everything again:
>
> $ make clean images
>
> And queried stats from ccache once more:
>
> $ ccache -s
>
> cache hit (direct)                   785
> cache hit (preprocessed)               8
> cache miss                          2701
> cache hit rate                     22.70 %
> cleanups performed                    16
> files in cache                      7126
> cache size                         719.6 MB
> max cache size                       5.0 GB
>
>
> Now, ignoring the percentage displayed by ccache, I think if we put 
> together the numbers in both runs we get a hit ratio of:
>
> (785 + 8) / 1747 = 45.39%
>
While this looks correct, you can reset stats after priming the cache to 
get exactly the numbers you seek.
> So, we get an hit for slightly less than all the compilation that run 
> on ccache; how is that possible since no file in the repo actually 
> changed? I remember than few years ago, doing a clean build with an 
> hot ccache would result in massive speedup, with very very little c++ 
> compilation going on; this is clearly no longer the case; what has 
> changed - and, more importantly, is the change deliberate?
>
Not deliberate, just not noticed and prioritized. ccache only really 
shines if you do clean rebuilds of the same source multiple times. In 
hotspot, the cache is basically invalidated completely as soon as a 
header file is touched, so developers there have no use for it. Same 
thing happens if you pull changes from upstream. Because of this I 
expect that using it is rare, which is also why it hasn't received much 
love lately.
> Btw, I also tried to get ccache to dump whatever it was doing (by 
> exporting the variable CCACHE_LOGFILE) - and I got a lot of stuff like 
> this:
I think we need more details here to figure it out, but it doesn't 
surprise me that hotspot is the part that's failing. Building hotspot is 
way more complex than the rest.

/Erik
>
> [2018-11-08T18:33:17.787569 31608] Preprocessor created 
> ../../build/linux-x86_64-server-slowdebug/hotspot/variant-server/libjvm/objs/weakHandle.d
> [2018-11-08T18:33:17.787621 31608] Object file 
> /home/maurizio/.ccache/6/3/5b851dd4174db423c3fb55fd7f1235-13635.o not 
> in cache
> [2018-11-08T18:33:17.787718 31608] Running real compiler
> -- 
> [2018-11-08T18:33:20.184685 31659] Preprocessor created 
> ../../build/linux-x86_64-server-slowdebug/hotspot/variant-server/libjvm/objs/weakProcessorPhaseTimes.d
> [2018-11-08T18:33:20.184751 31659] Object file 
> /home/maurizio/.ccache/1/7/190bc529eb14c5bda3c89daba9a5e5-50508.o not 
> in cache
> [2018-11-08T18:33:20.184843 31659] Running real compiler
> -- 
> [2018-11-08T18:33:20.247227 31668] Preprocessor created 
> ../../build/linux-x86_64-server-slowdebug/hotspot/variant-server/libjvm/objs/weakProcessorPhases.d
> [2018-11-08T18:33:20.247270 31668] Object file 
> /home/maurizio/.ccache/a/4/80bfe54bd0bf9c021aa7389bd7012f-10398.o not 
> in cache
> [2018-11-08T18:33:20.247349 31668] Running real compiler
> -- 
> [2018-11-08T18:33:21.085803 31692] Preprocessor created 
> ../../build/linux-x86_64-server-slowdebug/hotspot/variant-server/libjvm/objs/workerDataArray.d
> [2018-11-08T18:33:21.085848 31692] Object file 
> /home/maurizio/.ccache/b/1/a69dc0b13132029886e1155b39acd2-24155.o not 
> in cache
> [2018-11-08T18:33:21.085936 31692] Running real compiler
> -- 
> [2018-11-08T18:33:21.184015 31682] Preprocessor created 
> ../../build/linux-x86_64-server-slowdebug/hotspot/variant-server/libjvm/objs/whitebox.d
> [2018-11-08T18:33:21.184060 31682] Object file 
> /home/maurizio/.ccache/3/d/5ebb87455fe07d2a8866ff30c48338-959488.o not 
> in cache
> [2018-11-08T18:33:21.184150 31682] Running real compiler
> -- 
> [2018-11-08T18:33:21.433881 31703] Preprocessor created 
> ../../build/linux-x86_64-server-slowdebug/hotspot/variant-server/libjvm/objs/workgroup.d
> [2018-11-08T18:33:21.433940 31703] Object file 
> /home/maurizio/.ccache/c/8/f2bc626039e475a9a03c8f884ccd3e-32923.o not 
> in cache
> [2018-11-08T18:33:21.434029 31703] Running real compiler
> -- 
> [2018-11-08T18:33:21.684945 31722] Preprocessor created 
> ../../build/linux-x86_64-server-slowdebug/hotspot/variant-server/libjvm/objs/writeableFlags.d
> [2018-11-08T18:33:21.685005 31722] Object file 
> /home/maurizio/.ccache/e/1/ee622e320e77e144a1c731509ef382-26538.o not 
> in cache
> [2018-11-08T18:33:21.685097 31722] Running real compiler
> -- 
> [2018-11-08T18:33:21.704748 31732] Preprocessor created 
> ../../build/linux-x86_64-server-slowdebug/hotspot/variant-server/libjvm/objs/xmlstream.d
> [2018-11-08T18:33:21.704795 31732] Object file 
> /home/maurizio/.ccache/d/0/e1f2fcb99f6a347b712fc7f383d7bf-36122.o not 
> in cache
> [2018-11-08T18:33:21.704886 31732] Running real compiler
> -- 
> [2018-11-08T18:33:21.971913 31742] Preprocessor created 
> ../../build/linux-x86_64-server-slowdebug/hotspot/variant-server/libjvm/objs/yieldingWorkgroup.d
> [2018-11-08T18:33:21.972194 31742] Object file 
> /home/maurizio/.ccache/6/2/237fe491561492c6e06f7b7aaa7fe4-24506.o not 
> in cache
> [2018-11-08T18:33:21.972539 31742] Running real compiler
> -- 
> [2018-11-08T18:33:29.086857 5964 ] Preprocessor created 
> ../../build/linux-x86_64-server-slowdebug/hotspot/variant-server/libjvm/objs/vm_version.d
> [2018-11-08T18:33:29.086879 5964 ] Object file 
> /home/maurizio/.ccache/7/5/9074d92c9248e9b9bb1feb1f2e393e-20939.o not 
> in cache
> [2018-11-08T18:33:29.086926 5964 ] Running real compiler
>
> Eyeballing the results it seems like nearly all hotspot code doesn't 
> make it through ccache, whereas JDK native files do (most hits seem to 
> be in java.base and java.desktop).
>
> Maurizio
>
>