High Memory Usage (Timeout behaviour difference)

[kica-z]

We are currently in the process of switching our ccache from integrated http to the storage helper. During our testing we noticed a massive increase in RAM usage on the same build when utilizing the storage helper:
On an identical build with -j20, we observe a ~4.75× increase in peak RAM usage:

Configuration	Peak RAM
ccache built-in HTTP	8 GB
ccache + storage helper	38 GB

Build environment:

• Build system: CMake
• Parallelism: 20 (-j20)
• ccache version: 4.13.1
• Helper version: ccache-storage-http-cpp v0.5 with patches (PR Add netrc authentication support #3 + PR Fix use-after-free in IPC client connection lifetime management #6)

Any Idea where this massive increase in RAM could come from?

[jrosdahl]

This sounds extremely odd. I'm using ccache-storage-http-cpp regularly (for http, not https) and I've only seen it go to at most ≈40 MB (RSS) with 48 parallel compilations.

Or is it the ccache processes that consume more memory, not the helper?

[kica-z]

It might be a side effect actually of the helper having influence on cache efficiency. I did some test runs and when using a remote server the hit-rate was significantly reduced when using the storage-helper:

#################################
# Local               127.0.0.1 #
#################################

CPP:
------------------------------------------
real	4m1.571s
user	42m34.297s
sys	10m45.126s
min: 11371.7MB  max: 19830.7MB
Cacheable calls:   1281 / 1281 (100.0%)
  Hits:            1281 / 1281 (100.0%)
    Direct:        1070 / 1281 (83.53%)
    Preprocessed:   211 / 1281 (16.47%)
  Misses:             0 / 1281 ( 0.00%)
Local storage:
  Cache size (GB):  2.8 / 20.0 (14.03%)
  Hits:              10 / 1281 ( 0.78%)
  Misses:          1271 / 1281 (99.22%)
Remote storage:
  Hits:            1271 / 1271 (100.0%)
  Misses:             0 / 1271 ( 0.00%)


GO: 
------------------------------------------
real	4m7.284s
user	43m41.314s
sys	11m2.407s
min: 11535.5MB  max: 20876.7MB
Cacheable calls:   1281 / 1281 (100.0%)
  Hits:            1281 / 1281 (100.0%)
    Direct:        1070 / 1281 (83.53%)
    Preprocessed:   211 / 1281 (16.47%)
  Misses:             0 / 1281 ( 0.00%)
Local storage:
  Cache size (GB):  2.8 / 20.0 (14.03%)
  Hits:              10 / 1281 ( 0.78%)
  Misses:          1271 / 1281 (99.22%)
Remote storage:
  Hits:            1271 / 1271 (100.0%)
  Misses:             0 / 1271 ( 0.00%)


No Helper:
------------------------------------------
real	4m10.440s
user	44m14.070s
sys	11m8.662s
min: 11248.2MB  max: 20435.9MB
Cacheable calls:   1281 / 1281 (100.0%)
  Hits:            1281 / 1281 (100.0%)
    Direct:        1070 / 1281 (83.53%)
    Preprocessed:   211 / 1281 (16.47%)
  Misses:             0 / 1281 ( 0.00%)
Local storage:
  Cache size (GB):  2.8 / 20.0 (14.03%)
  Hits:              10 / 1281 ( 0.78%)
  Misses:          1271 / 1281 (99.22%)
Remote storage:
  Hits:            1271 / 1271 (100.0%)
  Misses:             0 / 1271 ( 0.00%)


#################################
# Azure Remote Server           #
#################################

No Helper:
------------------------------------------
1.
real	4m38.436s
user	42m3.838s
sys	10m45.254s
min: 12752.9MB  max: 20386.8MB
Cacheable calls:   1281 / 1281 (100.0%)
  Hits:            1281 / 1281 (100.0%)
    Direct:        1070 / 1281 (83.53%)
    Preprocessed:   211 / 1281 (16.47%)
  Misses:             0 / 1281 ( 0.00%)
Local storage:
  Cache size (GB):  2.8 / 20.0 (14.03%)
  Hits:               7 / 1281 ( 0.55%)
  Misses:          1274 / 1281 (99.45%)
Remote storage:
  Hits:            1274 / 1274 (100.0%)
  Misses:             0 / 1274 ( 0.00%)

2. 
real	4m31.901s
user	41m0.510s
sys	10m32.818s
min: 9913.28MB  max: 17564.6MB
Cacheable calls:   1281 / 1281 (100.0%)
  Hits:            1281 / 1281 (100.0%)
    Direct:        1070 / 1281 (83.53%)
    Preprocessed:   211 / 1281 (16.47%)
  Misses:             0 / 1281 ( 0.00%)
Local storage:
  Cache size (GB):  2.8 / 20.0 (14.03%)
  Hits:               6 / 1281 ( 0.47%)
  Misses:          1275 / 1281 (99.53%)
Remote storage:
  Hits:            1275 / 1275 (100.0%)
  Misses:             0 / 1275 ( 0.00%)

GO: 
------------------------------------------
1.
real	26m0.589s
user	416m21.668s
sys	39m51.541s
min: 11595.8MB  max: 58751.5MB
Cacheable calls:   1281 / 1281 (100.0%)
  Hits:             843 / 1281 (65.81%)
    Direct:         759 /  843 (90.04%)
    Preprocessed:    84 /  843 ( 9.96%)
  Misses:           438 / 1281 (34.19%)
Local storage:
  Cache size (GB):  2.8 / 20.0 (14.03%)
  Hits:              10 / 1281 ( 0.78%)
  Misses:          1271 / 1281 (99.22%)
Remote storage:
  Hits:             833 / 1271 (65.54%)
  Misses:           438 / 1271 (34.46%)
  Timeouts:         438

2. 
real	25m46.074s
user	418m25.052s
sys	39m37.098s
min: 10507.1MB  max: 55686MB
Cacheable calls:   1281 / 1281 (100.0%)
  Hits:             830 / 1281 (64.79%)
    Direct:         760 /  830 (91.57%)
    Preprocessed:    70 /  830 ( 8.43%)
  Misses:           451 / 1281 (35.21%)
Local storage:
  Cache size (GB):  2.8 / 20.0 (14.03%)
  Hits:              10 / 1281 ( 0.78%)
  Misses:          1271 / 1281 (99.22%)
Remote storage:
  Hits:             820 / 1271 (64.52%)
  Misses:           451 / 1271 (35.48%)
  Errors:             2
  Timeouts:         449


CPP:
------------------------------------------
1.
real	19m1.777s
user	297m29.774s
sys	26m17.692s
min: 8067.35MB  max: 63008.9MB
Cacheable calls:   1281 / 1281 (100.0%)
  Hits:            1105 / 1281 (86.26%)
    Direct:         969 / 1105 (87.69%)
    Preprocessed:   136 / 1105 (12.31%)
  Misses:           176 / 1281 (13.74%)
Local storage:
  Cache size (GB):  2.8 / 20.0 (14.03%)
  Hits:              10 / 1281 ( 0.78%)
  Misses:          1271 / 1281 (99.22%)
Remote storage:
  Hits:            1095 / 1271 (86.15%)
  Misses:           176 / 1271 (13.85%)
  Timeouts:         176

2.
real	19m55.712s
user	303m40.508s
sys	26m55.643s
min: 7582.69MB  max: 62911.5MB
Cacheable calls:   1281 / 1281 (100.0%)
  Hits:            1100 / 1281 (85.87%)
    Direct:         969 / 1100 (88.09%)
    Preprocessed:   131 / 1100 (11.91%)
  Misses:           181 / 1281 (14.13%)
Local storage:
  Cache size (GB):  2.8 / 20.0 (14.03%)
  Hits:               9 / 1281 ( 0.70%)
  Misses:          1272 / 1281 (99.30%)
Remote storage:
  Hits:            1091 / 1272 (85.77%)
  Misses:           181 / 1272 (14.23%)
  Timeouts:         181

The configuration was exactly the same, the server was exclusively used only for these tests and the runs were executed in close succession. Whilst network could of course have influence on this i think a general pattern is visible that without the helper it seems to be more stable/reliable.

The RAM consumption will probably be due to the additional builds required due to the cache misses. It might also partly be influenced by helper inefficiency but this should be analysed after the general cache-hit issue mentioned above.

The configuration:

CCACHE_SLOPPINESS = "locale,random_seed";
CCACHE_MAXSIZE = "20G";
CCACHE_NOHASHDIR = "true";
CCACHE_RESHARE = "1";
CCACHE_REMOTE_STORAGE = "http://<server>|connect-timeout=500";
CCACHE_DIR="''${CCACHE_BASEDIR}/.ccache" # Expands to ./.ccache basically
CCACHE_LOGFILE="''${CCACHE_DIR}/ccache.log"
CRSH_LOGFILE="''${CCACHE_DIR}/helper.log"

The very basic and crude test script i ran to generate the test output (with very broad whole system RAM analysis):

set -o errexit -o noclobber -o nounset -o pipefail

ccache -z
ccache --clear
mv mem_samples.txt mem_samples.old.txt || true
rm -rf .ccache
rm -rf <cmake-build-dir>
mkdir .ccache
(while true; do
  awk '/MemAvailable/ {print 65256596 - $2}' /proc/meminfo # Adjust max amount of RAM currently hardcoded
  sleep 0.5
done) >mem_samples.txt &
POLLER=$!

time <cmake-command-to-build>

kill $POLLER
awk 'NR==1{min=max=$1} {if($1<min)min=$1; if($1>max)max=$1} END{print "min:", min/1024 "MB  max:", max/1024 "MB"}' mem_samples.txt
ccache --show-stats

[jrosdahl]

The RAM consumption will probably be due to the additional builds required due to the cache misses.

Yes, that explains it. The cache misses are due to timeouts, as can be seen in your statistics.

There are two timeouts in play for the helper:

• data-timeout: Timeout for send/receive data transfer. Resets whenever data is received or can be sent. Default: 1s.
• request-timeout: Timeout for the whole request. Default: 10s.

I chose defaults that at the time made sense to me when I was implementing and testing out the helper mechanism, but I have come to realize that they are too aggressive in scenarios where the system is under high load. I see the same thing on our Windows servers but not on Linux.

Could you try with

CCACHE_REMOTE_STORAGE="http://<server> connect-timeout=500 data-timeout=10s request-timeout=1m"

instead and see if the timeouts disappear?

[jrosdahl]

I've increased timeout defaults in ccache 4.13.5 now.

[kica-z]

Hi @jrosdahl

I did not find the time to look at this last week but will do some tests with the new version this week in order to verify that the timeouts where indeed the problem.

[kica-z]

I just tested it with different timeouts and it worked perfectly. Total build time, cache misses and memory consumption where comparable to a run without the helper. 🥳

However I think i found something which might lead to problems on bigger files (correct me if i misinterpreted something):

With built-in HTTP, ccache's libcurl applies data-timeout as a stall timeout directly on the HTTP connection so the clock resets with every received byte and only fires if the connection goes completely silent.
With the cpp helper, ccache watches the IPC pipe for data instead, and that pipe is silent for the entire duration of the HTTP download because write_callback accumulates the body in memory without forwarding anything. The helper only writes the first byte to the IPC pipe after CURLMSG_DONE fires, meaning the full response has already been buffered locally.
This turns data-timeout from a stall timeout into an effective total-download timeout: an object that downloads in 9.9 s succeeds, one that takes 10.1s fails, even if data is flowing continuously on the HTTP side. The same applies to the go helper.

[jrosdahl]

Great!

I have now released version 0.6 of ccache-storage-http-go with streaming behavior (it was easy to do). However, making ccache-storage-http-cpp streaming is a bit more challenging given libcurl's API, so it will have to stay buffering for now. So data-timeout might have to be adjusted for very large files or slow network when using the C++ helper. 10s is still plenty of time, though, so I don't expect it to be a large problem.

[kica-z]

Nice 👍. A bit unfortunate that the two helpers now handle that timeout differently but i see your point that it is non-trivial to adjust the cpp helper.

Thanks for the help 👍