setup-node icon indicating copy to clipboard operation
setup-node copied to clipboard

Heavy cache miss count

Open iBotPeaches opened this issue 2 years ago • 10 comments

Description: A large collection of "cache miss" and only a handful of "cache hit".

Action version: actions/setup-node@v3

Platform:

  • [x] Ubuntu
  • [ ] macOS
  • [ ] Windows

Runner type:

  • [x] Hosted
  • [ ] Self-hosted

Tools version:

    - name: Setup node
      uses: actions/setup-node@v3
      with:
        node-version: 18
        cache: 'npm'

Repro steps:

    - name: Setup node
      uses: actions/setup-node@v3
      with:
        node-version: ${{ inputs.node-version }}
        cache: 'npm'

    - run: npm ci --verbose
      shell: bash

Expected behavior: A restore of previously downloaded artifacts

Actual behavior:

npm http fetch GET 200 https://registry.npmjs.org/locate-path 2237ms (cache miss)
npm http fetch GET 200 https://registry.npmjs.org/json-stable-stringify-without-jsonify 2232ms (cache miss)
npm http fetch GET 200 https://registry.npmjs.org/yocto-queue/-/yocto-queue-0.1.0.tgz 777ms (cache hit)
npm http fetch GET 200 https://registry.npmjs.org/update-browserslist-db 2424ms (cache miss)
npm http fetch GET 200 https://registry.npmjs.org/mime-types 2300ms (cache miss)
npm http fetch GET 200 https://registry.npmjs.org/lodash.merge 2297ms (cache miss)
npm http fetch GET 200 https://registry.npmjs.org/json-schema-traverse 2291ms (cache miss)
npm http fetch GET 200 https://dl.fontawesome.com/signed/fontawesome-pro/npm/fortawesome/fontawesome-common-types/6.4.0/fortawesome-fontawesome-common-types-6.4.0.tgz?created=xxx&expires=xxx&source=xxx&signature=xxx 6157ms (cache miss)
  • tons and tons of cache miss.

Like why was yocto-queue a hit but not fontawesome?


So this is being reported because you get charged for using bandwidth when using Font Awesome. Sadly in our case - the basic example used here does not properly cache all items and I'm not following why. We get a hit restoring the cache blob, but it appears its quite small to what I expect.

/home/runner/.npm
Received 24691139 of 24691139 (100.0%), 30.4 MBs/sec
Cache Size: ~24 MB (24691139 B)
Cache restored successfully
Cache restored from key: node-cache-Linux-npm-912ac010d33c9c8d3694535a04cbea9be930f020a6b09d60b707ae2ce2d4db8b

I know this action does NOT cache node_modules, but then I struggle to understand the benefit I'm gaining here. Its clearly caching and restoring something, but since it doesn't cache the thing that costs us money then :(

We then get billed for overages and Font Awesome support just tells us to follow this guide which we clearly do.

Screenshot 2023-08-22 at 10 14 02 AM

iBotPeaches avatar Aug 22 '23 14:08 iBotPeaches

So the large collection of misses was resolved by manually deleting/purging all the caches from that repository. The default cache key I assume is the lockfile hash, so why this happened - I'm not sure. Now the only thing not caching is the links from a private registry.

This private registry (Font Awesome) does not appear to ever successfully cache itself. I assume since the non node_modules cache is HTTP responses and these expire after 20 minutes. So the cache is respecting the TTL and thus becoming misses on builds.

I don't know if this means we should go back to rolling our own cache - (caching node_modules, skipping install if cache hit, etc) or just missing something here.

iBotPeaches avatar Aug 22 '23 19:08 iBotPeaches

Hello, @iBotPeaches ! Thanks for reporting this issue, we will take a closer look and see what can be done :)

dusan-trickovic avatar Aug 23 '23 07:08 dusan-trickovic

I too am experiencing this same issue with FontAwesome. It is having a large impact on us and our budgets with overage charges. We have many repositories that are facing this issue.

The only difference that I can see is that we are using yarn rather than npm.

codepuncher avatar Oct 09 '23 13:10 codepuncher

@codepuncher - I dug into this a lot with FA, who honestly just kept redirecting me back to official GitHub docs on caching. You can't really use setup-node, etc with FA Pro and expect to keep your bandwidth.

We mixed two forms of cache now.

    - name: Setup node
      uses: actions/setup-node@v3
      with:
        node-version: ${{ inputs.node-version }}
        cache: 'npm'

    - uses: actions/cache@v3
      id: npm-cache
      with:
        path: node_modules
        key: ${{ inputs.node-version }}-node-${{ hashFiles('**/package-lock.json') }}
        restore-keys: ${{ inputs.node-version }}-node-${{ hashFiles('**/package-lock.json') }}

    - run: npm ci
      if: steps.npm-cache.outputs.cache-hit != 'true'
      working-directory: ${{ inputs.directory }}
      shell: bash

(this is in a composite action)

We restore cache using regular setup-node, but then we attempt to restore a 1-1 cache based on the exact hash of the lock file. If we find a match for that, we skip npm ci - which is what would eventually hit FA Pro servers again and bleed bandwidth due to what I described above.

If that cache is a miss, we already restored the npm global cache (the 1st cache) so our cold/miss timing is still pretty fast as we are just installing the FA Pro, the private packages and whatever caused the miss (new version, etc)

This has kept us under the 2gb bandwidth limit for Sept.

iBotPeaches avatar Oct 09 '23 13:10 iBotPeaches

Hello @iBotPeaches,

The problem is not reproducible

1st run https://github.com/akv-demo/setup-node-test/actions/runs/7251833566/job/19755011576#step:4:9

Run npm ci --verbose
...
npm http fetch GET [20](https://github.com/akv-demo/setup-node-test/actions/runs/7251833566/job/19755011576#step:4:21)0 https://registry.npmjs.org/font-awesome/-/font-awesome-4.7.0.tgz 93ms (cache miss)
npm http fetch POST 200 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk 357ms

2nd run

Run npm ci --verbose
...
npm http fetch POST [20](https://github.com/akv-demo/setup-node-test/actions/runs/7251833566/job/19755025500#step:4:21)0 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk 127ms

The idea of action is to cahce ~/.npm directory which contains downloaded packages. Caching the node_modules does not seem a good idea because they its content can be out of sync.

It is impossible to find the exact reason why the ~/.npm directory does not contain the whole bunch of packages but in the theory it can be caused the repository has outdated package-lock.json.

Did it help?

dsame avatar Dec 18 '23 17:12 dsame

Hi @dsame,

My experience was more for the Pro/Private option of FA, which does not appear to be cachable. Your test appears to be the public version of Font Awesome - so I don't think a true comparable replicable test.

I'm not saying my method is the cleanest, but it did solve our immediate problem of exceeding rate limits

Screenshot 2023-12-18 at 1 21 09 PM

Since my comment I've yet to hit a month where we exceed limits. I don't want to cache node_modules, but I did what I had to stay under usage limits.

iBotPeaches avatar Dec 18 '23 18:12 iBotPeaches

Hello @iBotPeaches, thank you for the clarification, i supposed there's something related to the private package and wanted to get the confirmation.

Nevertheless, it puzzles me with the dependencies from https://registry.npmjs.org are not cached as well despite I expect them to be stored in ~/.npm folder and cached.

I understand you've solved the problem with the workaround, but can you please double check does the build on the local host has to reload the awesomefonts npm with its dependencies? I still suspect the action has some flaw with the generating .npmrc config that might cause the problem.

In case if the local build has the same problem or you don't have a time, please let us to close the issue with "it does not relate to the action"

dsame avatar Dec 19 '23 10:12 dsame

Hi @dsame,

I ran a few tests in a private repo like your configuration. With each change I got closer to our affected application, but each time I re-ran it - it seemed fine.

npm verb cli /opt/hostedtoolcache/node/18.19.0/x64/bin/node /opt/hostedtoolcache/node/18.19.0/x64/bin/npm
npm info using [email protected]
npm info using node@v1[8](https://github.com/sourcetoad/actions-node-test/actions/runs/7264253745/job/19791375113#step:5:9).1[9](https://github.com/sourcetoad/actions-node-test/actions/runs/7264253745/job/19791375113#step:5:10).0
npm verb title npm ci
npm verb argv "ci" "--loglevel" "verbose"
npm verb logfile logs-max:[10](https://github.com/sourcetoad/actions-node-test/actions/runs/7264253745/job/19791375113#step:5:11) dir:/home/runner/.npm/_logs/2023-[12](https://github.com/sourcetoad/actions-node-test/actions/runs/7264253745/job/19791375113#step:5:13)-19T15_53_14_549Z-
npm verb logfile /home/runner/.npm/_logs/2023-12-19T15_53_14_549Z-debug-0.log
npm http fetch POST 200 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk 494ms
npm info run @fortawesome/[email protected] postinstall node_modules/@fortawesome/fontawesome-common-types node attribution.js
npm info run @fortawesome/[email protected] postinstall node_modules/@fortawesome/fontawesome-svg-core node attribution.js
npm info run @fortawesome/[email protected] postinstall { code: 0, signal: null }
npm info run @fortawesome/[email protected] postinstall { code: 0, signal: null }
{
  "dependencies": {
    "@fortawesome/fontawesome-svg-core": "^6.5.1",
    "@fortawesome/pro-solid-svg-icons": "^6.5.1"
  }
}
@fortawesome:registry=https://npm.fontawesome.com
//npm.fontawesome.com/:_authToken=${FONTAWESOME_NPM_AUTH_TOKEN}

This worked fine. So I removed my workaround on the actual affected application and it was immediate misses again. Unfortunately the difference between the real affected application and this sample is 98,000~ different node packages.

So at this point - I can't replicate in my test, but my real application continues to replicate. I'm happy with a workaround, but I understand if you can't replicate - you can't fix.

I'll close this and if others stumble upon this with FA Pro and have the same bandwidth overage issue - maybe they can use my sample that works and/or discover the root cause themselves.

Thanks

iBotPeaches avatar Dec 19 '23 15:12 iBotPeaches