is ccache working effectively?

Thu Nov 8 18:58:11 UTC 2018

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.

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%

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?

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:

[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