Bad cache hit rate (ccache)

I recently added ccache to the repo

But the cache hit rate (with a hot cache) is more then bad:
https://travis-ci.com/github/LimitlessGreen/OpenHDKernelBuilder/jobs/363184845#L8718

cache directory                     /home/travis/.ccache
primary config                      /home/travis/.ccache/ccache.conf
secondary config      (readonly)    /etc/ccache.conf
stats updated                       Tue Jul 21 07:32:09 2020
cache hit (direct)                   551
cache hit (preprocessed)              21
cache miss                         13001
cache hit rate                      4.21 %
called for link                     4050
called for preprocessing            1059
preprocessor error                   322
unsupported source language            6
autoconf compile/link                  9
unsupported code directive             9
no input file                       2538
cleanups performed                     0
files in cache                     38652
cache size                         518.3 MB
max cache size                       5.0 GB

If I building on my local machine it looks more like this:

    stats updated                       Mon Jul 20 12:42:28 2020
    cache hit (direct)                 48189
    cache hit (preprocessed)             143
    cache miss                         13180
    cache hit rate                     78.57 %
    called for link                    84581
    called for preprocessing           21319
    compiler produced empty output       210
    preprocessor error                   469
    unsupported code directive            49
    no input file                       5210
    cleanups performed                     0
    files in cache                     36100
    cache size                         518.7 MB

Any hints?
Maybe separate caches for buster and stretch, but the wiki isn’t very helpful at this point.

Best regards,
Green

I’m not sure how ccache match the files (path, hash?), but it clearly doesn’t match it.

For example the last build cache (https://travis-ci.com/github/LimitlessGreen/OpenHDKernelBuilder/jobs/363408979) took at the beginning 1.2GB, that’s much more then it normally take. And at the end of the build it increased to 1.4GB.


Maybe this could be a hint. I found this in the manual of ccache https://ccache.dev/manual/3.7.10.html

It improved by adding

before_install:
  - ccache --set-config=compiler_check=content

https://travis-ci.com/github/LimitlessGreen/OpenHDKernelBuilder/jobs/363729464

cache directory                     /home/travis/.ccache
primary config                      /home/travis/.ccache/ccache.conf
secondary config      (readonly)    /etc/ccache.conf
stats updated                       Wed Jul 22 10:24:49 2020
cache hit (direct)                  4770
cache hit (preprocessed)              24
cache miss                          4416
cache hit rate                     52.05 %
called for link                     2707
called for preprocessing             718
preprocessor error                   220
unsupported source language            3
autoconf compile/link                 18
unsupported code directive             6
no input file                       1798
cleanups performed                     0
files in cache                     13068
cache size                         181.0 MB
max cache size                       5.0 GB

But still not as good as a local build

1 Like

Oh wait, this is exactly what I got locally.
Just compared it to the wrong build :smiley:

Bottom line: you need to ensure that arm-linux-gnueabihf-gcc's mtime stays the same across builds, or adjust the compiler_check CCache setting.


I see that the cache is being stored and fetched correctly despite the creating directory /home/travis/.ccache message (previously, it only appeared if the directory wasn’t in the cache. Now, it seems to appear always).

I’ve run the build 4 times and got roughly 4x the number of files in the cache. This suggests that the files you are compiling are somehow different every time from CCache’s POV.

Running the build with CCache’s debugging enabled confirms this:

(archive from run) home0\travis\build\native-api\OpenHDKernelBuilder\linux-pi\arch\arm\boot\compressed\ashldi3.o.ccache-log:

[2020-07-22T23:51:11.456842 70290] Object file /home/travis/.ccache/8/e/3c14806e2159480833df9ebd6b1ba2-7525.o not in cache

(archive from rerun) home\travis\build\native-api\OpenHDKernelBuilder\linux-pi\arch\arm\boot\compressed\ashldi3.o.ccache-log:

[2020-07-23T01:15:49.008481 70362] Object file /home/travis/.ccache/8/5/55653f667b39bf6393bff4a6228fef-7525.o not in cache


https://ccache.dev/manual/3.7.7.html#_common_hashed_information explains what goes into the cache ID hash.

A closer inspection shows that compiler mtime is different (see the above-mentioned CCache debugging link on what this file is):

> xxd home0\travis\build\native-api\OpenHDKernelBuilder\linux-pi\arch\arm\boot\compressed\ashldi3.o.ccache-input-c
00000000: 3300 6343 6143 6845 0065 7874 0073 0063  3.cCaChE.ext.s.c
00000010: 4361 4368 4500 6363 5f6d 7469 6d65 0028  CaChE.cc_mtime.(
00000020: 470b 0038 cc18 5f00 6343 6143 6845 0063  G..8.._.cCaChE.c
00000030: 635f 6e61 6d65 0061 726d 2d6c 696e 7578  c_name.arm-linux
00000040: 2d67 6e75 6561 6269 6866 2d67 6363 0063  -gnueabihf-gcc.c
00000050: 4361 4368 4500 4c41 4e47 0065 6e5f 5553  CaChE.LANG.en_US
00000060: 2e55 5446 2d38 0063 4361 4368 4500 4c43  .UTF-8.cCaChE.LC
00000070: 5f43 5459 5045 0065 6e5f 5553 2e55 5446  _CTYPE.en_US.UTF
00000080: 2d38                                     -8

> xxd home\travis\build\native-api\OpenHDKernelBuilder\linux-pi\arch\arm\boot\compressed\ashldi3.o.ccache-input-c
00000000: 3300 6343 6143 6845 0065 7874 0073 0063  3.cCaChE.ext.s.c
00000010: 4361 4368 4500 6363 5f6d 7469 6d65 0028  CaChE.cc_mtime.(
00000020: 470b 00de df18 5f00 6343 6143 6845 0063  G....._.cCaChE.c
00000030: 635f 6e61 6d65 0061 726d 2d6c 696e 7578  c_name.arm-linux
00000040: 2d67 6e75 6561 6269 6866 2d67 6363 0063  -gnueabihf-gcc.c
00000050: 4361 4368 4500 4c41 4e47 0065 6e5f 5553  CaChE.LANG.en_US
00000060: 2e55 5446 2d38 0063 4361 4368 4500 4c43  .UTF-8.cCaChE.LC
00000070: 5f43 5459 5045 0065 6e5f 5553 2e55 5446  _CTYPE.en_US.UTF
00000080: 2d38                                     -8

> cmp -c home0\travis\build\native-api\OpenHDKernelBuilder\linux-pi\arch\arm\boot\compressed\ashldi3.o.ccache-input-c home\travis\build\native-api\OpenHDKernelBuilder\linux-pi\arch\arm\boot\compressed\ashldi3.o.ccache-input-c
home0\travis\build\native-api\OpenHDKernelBuilder\linux-pi\arch\arm\boot\compressed\ashldi3.o.ccache-input-c home\travis\build\native-api\OpenHDKernelBuilder\linux-pi\arch\arm\boot\compressed\ashldi3.o.ccache-input-c differ: byte 36, line 1 is  12 ^J 336 M-^

Indeed, unexpectedly enough, Git doesn’t save mtime (unlike e.g. tar)! So if you git clone your compilation tools rather than unpack them from a tarball, the compiler will have a different mtime each time!

1 Like

Thank you @native-api for tracking this problem down :+1:

For me this looks like compiler_check=content should be enabled by default.
I’m sure, I not the only one with this problem out there.

1 Like
Imprint