Cache task is slow and unreliable #10935

wichert · 2019-07-18T10:08:16Z

Required Information

Entering this information will route you directly to the right team and expedite traction.

Question, Bug, or Feature?
Type: Bug

Enter Task Name: CacheBeta@0

Environment

Server: Azure Pipelines
Agent: Hosted macOS-10.14

Issue Description

The cache unfortunately appears to be slow and unreliable. I just tried it with a project that uses a fair bit of node_modules. On the first test:

With empty cache, installing all packages using yarn took 54 seconds
Saving the cache took 106 seconds
Loading the cache in the next build failed after 121 seconds with [error]One or more errors occurred. (Service Unavailable) (Service Unavailable) after downloading 359Mb of of 497Mb (72%)

On a second test:

Loading the cache succeeded in 54 seconds
Yarn install time with loaded cache: 18 seconds

Which means the overall build time is still 16 seconds longer than without a cache.

Task logs

##[section]Starting: Cache Yarn packages
==============================================================================
Task         : Cache (Beta)
Description  : Cache files between runs
Version      : 0.1.0
Author       : Microsoft Corporation
Help         : https://aka.ms/pipeline-caching-docs
==============================================================================
Information, Using the following fingerprint argument (yarn) as a string value.
Information, Using the following fingerprint argument (Darwin) as a string value.
Information, Using the following fingerprint argument (/Users/vsts/agent/2.154.3/work/1/s/yarn.lock) as a file.
Information, Using the following fingerprint argument (/Users/vsts/agent/2.154.3/work/1/s/crypho.core/yarn.lock) as a string value.
Information, Using the following fingerprint argument (/Users/vsts/agent/2.154.3/work/1/s/crypho.core/xmpp.js/yarn.lock) as a string value.
Information, Generated fingerprint: BAB1179CEC7C8D8463877AD0B78C37BE3C65AA9B4145C2D55E60DF463EE811B200
Information, Getting a pipeline cache artifact with the following fingerprint: BAB1179CEC7C8D8463877AD0B78C37BE3C65AA9B4145C2D55E60DF463EE811B200
Information, There is a cache hit.
Manifest ID is: 2491EB794C0F22AE55A93EA7DC512F7ED56FF030F0BB539D9FDFA6D4CE53084302
Information, DedupManifestArtifactClient will correlate http requests with X-TFS-Session 2443ef72-699d-4368-b62b-c83b27983069
Information, Could not initialize dataport.
Information, Downloaded 0.0 MB out of 497.5 MB (0%).
Information, Downloaded 0.0 MB out of 497.5 MB (0%).
Information, Downloaded 0.0 MB out of 497.5 MB (0%).
Information, Downloaded 0.0 MB out of 497.5 MB (0%).
Information, Downloaded 0.0 MB out of 497.5 MB (0%).
Information, Downloaded 0.0 MB out of 497.5 MB (0%).
Information, Downloaded 0.0 MB out of 497.5 MB (0%).
Information, Downloaded 0.0 MB out of 497.5 MB (0%).
Information, Downloaded 0.0 MB out of 497.5 MB (0%).
Information, Downloaded 2.4 MB out of 497.5 MB (0%).
Information, Downloaded 20.8 MB out of 497.5 MB (4%).
Information, Downloaded 35.2 MB out of 497.5 MB (7%).
Information, Downloaded 58.3 MB out of 497.5 MB (12%).
Information, Downloaded 131.3 MB out of 497.5 MB (26%).
Information, Downloaded 244.7 MB out of 497.5 MB (49%).
Information, Downloaded 249.7 MB out of 497.5 MB (50%).
Information, Downloaded 254.8 MB out of 497.5 MB (51%).
Information, Downloaded 315.3 MB out of 497.5 MB (63%).
Information, Downloaded 317.3 MB out of 497.5 MB (64%).
Information, Downloaded 354.5 MB out of 497.5 MB (71%).
Information, Downloaded 354.5 MB out of 497.5 MB (71%).
Information, Downloaded 359.7 MB out of 497.5 MB (72%).
##[error]One or more errors occurred. (Service Unavailable) (Service Unavailable)
##[section]Finishing: Cache Yarn packages

The text was updated successfully, but these errors were encountered:

johnterickson · 2019-07-18T15:51:45Z

Thanks for reporting! The moment of your cache retrieval coincided with load on that scale unit quadrupling in load. Our automatic scaleout trigger, but had some lag. We'll see what tweaks we can make to make this better.

Can you confirm you are not seeing this consistently?

johnterickson · 2019-07-18T16:05:44Z

Possibly the same as #10917

wichert · 2019-07-18T17:15:04Z

I haven't seen the Serve Unavailable error anymore. The performance seems to vary a bit. From what I gather you are currently uploading files separately? If so uploading a tarball with fast compression might help a lot when you have lots of small files.

johnterickson · 2019-07-18T17:25:01Z

👍 #10925

johnterickson · 2019-07-24T14:37:59Z

@wichert Given the tarball is in #10925 and the service issue was remedied in #10917 , is this issue in a good place to close?

wichert · 2019-07-24T14:38:57Z

Yes, I think so. If I hit this again we can always revisit.

Fallback keys: microsoft/azure-pipelines-tasks#10842 input globbing: microsoft/azure-pipelines-tasks#10859 Relative paths: microsoft/azure-pipelines-tasks#10858 Only save when restore runs: microsoft/azure-pipelines-tasks#10907 Retries on timeouts: microsoft/azure-pipelines-tasks#10935

* New features for Pipline Cachings: Fallback keys: microsoft/azure-pipelines-tasks#10842 input globbing: microsoft/azure-pipelines-tasks#10859 Relative paths: microsoft/azure-pipelines-tasks#10858 Only save when restore runs: microsoft/azure-pipelines-tasks#10907 Retries on timeouts: microsoft/azure-pipelines-tasks#10935 * Some PR feedback

douglasjunior · 2022-04-18T20:25:08Z

For me, yarn install without cache takes 30s on average.

      - task: NodeTool@0
        inputs:
          versionSpec: '16.x'
        displayName: 'Install Node.js'

      - script: yarn
        displayName: Yarn install

      - script: yarn lint
        displayName: Run linting

And with Cache takes 30s + 30s on average.

variables:
  YARN_CACHE_FOLDER: $(Pipeline.Workspace)/.yarn

# ....

      - task: NodeTool@0
        inputs:
          versionSpec: '16.x'
        displayName: 'Install Node.js'

      - task: Cache@2
        inputs:
          key: 'yarn | "$(Agent.OS)" | yarn.lock'
          restoreKeys: |
            yarn | "$(Agent.OS)"
            yarn
          path: $(YARN_CACHE_FOLDER)
        displayName: Cache Yarn packages

      - script: yarn
        displayName: Yarn install

      - script: yarn lint
        displayName: Run linting

I followed the cache documentation. Am I doing something wrong?

Pentadome · 2022-11-04T12:42:30Z

Expected size to be downloaded: 297.8 MB
Downloaded 0.0 MB out of 297.8 MB (0%).
Downloaded 22.8 MB out of 297.8 MB (8%).
Downloaded 58.6 MB out of 297.8 MB (20%).
Downloaded 82.9 MB out of 297.8 MB (28%).
Downloaded 87.3 MB out of 297.8 MB (29%).
Downloaded 104.3 MB out of 297.8 MB (35%).
Downloaded 122.2 MB out of 297.8 MB (41%).
Downloaded 122.4 MB out of 297.8 MB (41%).
Downloaded 129.7 MB out of 297.8 MB (44%).
Downloaded 145.3 MB out of 297.8 MB (49%).
Downloaded 149.0 MB out of 297.8 MB (50%).
Downloaded 149.1 MB out of 297.8 MB (50%).
Downloaded 149.1 MB out of 297.8 MB (50%).
Downloaded 149.1 MB out of 297.8 MB (50%).
Downloaded 149.1 MB out of 297.8 MB (50%).
Downloaded 149.1 MB out of 297.8 MB (50%).
Downloaded 149.1 MB out of 297.8 MB (50%).
Downloaded 149.1 MB out of 297.8 MB (50%).
Downloaded 167.5 MB out of 297.8 MB (56%).
Downloaded 168.2 MB out of 297.8 MB (56%).
Downloaded 168.3 MB out of 297.8 MB (57%).
Downloaded 168.3 MB out of 297.8 MB (57%).
Downloaded 190.7 MB out of 297.8 MB (64%).
Downloaded 191.1 MB out of 297.8 MB (64%).
Downloaded 191.1 MB out of 297.8 MB (64%).
Downloaded 191.1 MB out of 297.8 MB (64%).
Downloaded 213.9 MB out of 297.8 MB (72%).
Downloaded 213.9 MB out of 297.8 MB (72%).
Downloaded 213.9 MB out of 297.8 MB (72%).
Downloaded 215.5 MB out of 297.8 MB (72%).
Downloaded 251.6 MB out of 297.8 MB (84%).
Downloaded 256.8 MB out of 297.8 MB (86%).
Downloaded 267.9 MB out of 297.8 MB (90%).
Downloaded 268.4 MB out of 297.8 MB (90%).
Downloaded 268.5 MB out of 297.8 MB (90%).
Downloaded 285.8 MB out of 297.8 MB (96%).
Downloaded 288.1 MB out of 297.8 MB (97%).
Downloaded 288.5 MB out of 297.8 MB (97%).
Downloaded 292.9 MB out of 297.8 MB (98%).
Downloaded 297.7 MB out of 297.8 MB (100%).
Downloaded 297.8 MB out of 297.8 MB (100%).

Download statistics:
Total Content: 297.8 MB
Physical Content Downloaded: 75.7 MB
Compression Saved: 222.1 MB
Local Caching Saved: 0.0 MB
Chunks Downloaded: 3,393
Nodes Downloaded: 7

The caching Task often seems to pause for no reason at all. This happens on multiple agents...

ghost added bug route labels Jul 18, 2019

joshmgross added Area: PipelineCaching and removed route labels Jul 18, 2019

johnterickson mentioned this issue Jul 18, 2019

Proposals/pipeline caching microsoft/azure-pipelines-yaml#113

Merged

willsmythe assigned johnterickson Jul 19, 2019

johnterickson mentioned this issue Jul 23, 2019

Pipeline Caching CacheBeta 1.0 agent changes microsoft/azure-pipelines-agent#2358

Merged

wichert closed this as completed Jul 24, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Cache task is slow and unreliable #10935

Cache task is slow and unreliable #10935

wichert commented Jul 18, 2019

johnterickson commented Jul 18, 2019

johnterickson commented Jul 18, 2019

wichert commented Jul 18, 2019

johnterickson commented Jul 18, 2019 •

edited

Loading

johnterickson commented Jul 24, 2019

wichert commented Jul 24, 2019

douglasjunior commented Apr 18, 2022

Pentadome commented Nov 4, 2022

Cache task is slow and unreliable #10935

Cache task is slow and unreliable #10935

Comments

wichert commented Jul 18, 2019

Required Information

Environment

Issue Description

Task logs

johnterickson commented Jul 18, 2019

johnterickson commented Jul 18, 2019

wichert commented Jul 18, 2019

johnterickson commented Jul 18, 2019 • edited Loading

johnterickson commented Jul 24, 2019

wichert commented Jul 24, 2019

douglasjunior commented Apr 18, 2022

Pentadome commented Nov 4, 2022

johnterickson commented Jul 18, 2019 •

edited

Loading