Bad cache hit rate (ccache)

Travis CI Discussions & Feedback
1

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

2

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

For example the last build cache (Travis CI - Test and Deploy with Confidence) 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 CCACHE(1)

3

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
4

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

5

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

CCACHE(1) 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
6

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.

7
1 Like