Processing web console line queue takes long time to stop in self hosted runner

[jdsdc]

Running a workflow with action actions/cache@v2 takes a long time to execute when job is run in self hosted mode. Works fine when running on github servers. From what i can see in the log the action itself seems to work fine but takes several minutes to finish cause of wait for a web console line queue. When running on github it takes about 1 minute.

The self hosted runner environment:

OS: Ubuntu 20.04
Runner version: 2.263.0

As you can see from this log line an action is taken to stop a queue.

[2020-06-10 14:46:37Z INFO JobServerQueue] Stop aggressive process web console line queue.

And the nex log line:

[2020-06-10 14:50:32Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'a04c83ac-b35b-5e6c-22c8-b60f8cc735cb', success rate: 1/1.

And the time to finish for the action it takes about 4 minutes. And i don't know why there is such a long wait time for this web console line queue.

Extract from the log:

[2020-06-10 14:45:43Z INFO ProcessInvokerWrapper]   File name: '/opt/actions-runner/externals/node12/bin/node'
[2020-06-10 14:45:43Z INFO ProcessInvokerWrapper]   Arguments: '"/opt/actions-runner/_work/_actions/actions/cache/v2/dist/restore/index.js"'
[2020-06-10 14:45:43Z INFO ProcessInvokerWrapper]   Working directory: '/opt/actions-runner/_work/hello-github-actions/hello-github-actions'
[2020-06-10 14:45:43Z INFO ProcessInvokerWrapper]   Require exit code zero: 'False'
[2020-06-10 14:45:43Z INFO ProcessInvokerWrapper]   Encoding web name:  ; code page: ''
[2020-06-10 14:45:43Z INFO ProcessInvokerWrapper]   Force kill process on cancellation: 'False'
[2020-06-10 14:45:43Z INFO ProcessInvokerWrapper]   Redirected STDIN: 'False'
[2020-06-10 14:45:43Z INFO ProcessInvokerWrapper]   Persist current code page: 'False'
[2020-06-10 14:45:43Z INFO ProcessInvokerWrapper]   Keep redirected STDIN open: 'False'
[2020-06-10 14:45:43Z INFO ProcessInvokerWrapper]   High priority process: 'False'
[2020-06-10 14:45:43Z INFO ProcessInvokerWrapper] Updated oom_score_adj to 500 for PID: 54246.
[2020-06-10 14:45:43Z INFO ProcessInvokerWrapper] Process started with process id 54246, waiting for process exit.
[2020-06-10 14:45:43Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'e4b38c0f-6035-56ec-f78c-2cac0ce98d59', success rate: 1/1.
[2020-06-10 14:45:43Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'a04c83ac-b35b-5e6c-22c8-b60f8cc735cb', success rate: 1/1.
[2020-06-10 14:45:43Z INFO JobServerQueue] Try to upload 1 log files or attachments, success rate: 1/1.
[2020-06-10 14:45:43Z INFO AddMaskCommandExtension] Add new secret mask with length of 267
[2020-06-10 14:46:37Z INFO JobServerQueue] Stop aggressive process web console line queue.
[2020-06-10 14:50:32Z INFO JobServerQueue] Try to append 1 batches web console lines for record 'a04c83ac-b35b-5e6c-22c8-b60f8cc735cb', success rate: 1/1.
[2020-06-10 14:50:34Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2020-06-10 14:50:34Z INFO ProcessInvokerWrapper] STDOUT/STDERR stream read finished.
[2020-06-10 14:50:34Z INFO ProcessInvokerWrapper] Finished process 54246 with exit code 0, and elapsed time 00:04:51.7603645.

This is the relevant action part from the workflow file;

- name: Cache 
        id: cache
        uses: actions/cache@v2
        env:
          cache-name: cache
        with:
          path: |
             ${{ env.DOCKER_CACHE }}
          key: ${{ runner.os }}- ${{ env.DOCKER_CACHE }}

Is there some configuration i need to change when running with a self-hosted runner? It seems to me that there is som lag in the communication between the self hosted runner and github.

[TingluoHuang]

@jdsdc those log means the runner didn't receive any output from the action. can you try to enable step debug to see whether the action will print out more outputs to tells you where is the time spent?

[jdsdc]

@TingluoHuang , thanks for the quick answer.

I have a clue where the time is spent. When i look in the log it seems like the cache is not on the local machine.

Does the cache action save to this url:

https://artifactcache.actions.githubusercontent.com/

If so that might explain the time delay?

2020-06-10T19:58:33.8995403Z ##[debug]Evaluating condition for step: 'Cache'
2020-06-10T19:58:33.9000511Z ##[debug]Evaluating: success()
2020-06-10T19:58:33.9001197Z ##[debug]Evaluating success:
2020-06-10T19:58:33.9003017Z ##[debug]=> true
2020-06-10T19:58:33.9003850Z ##[debug]Result: true
2020-06-10T19:58:33.9005760Z ##[debug]Starting: Cache
2020-06-10T19:58:33.9031950Z ##[debug]Register post job cleanup for action: actions/cache@v2
2020-06-10T19:58:33.9077477Z ##[debug]Loading inputs
2020-06-10T19:58:33.9081014Z ##[debug]Evaluating: format('{0}
2020-06-10T19:58:33.9081329Z ##[debug]', env.DOCKER_CACHE)
2020-06-10T19:58:33.9081692Z ##[debug]Evaluating format:
2020-06-10T19:58:33.9082053Z ##[debug]..Evaluating String:
2020-06-10T19:58:33.9082435Z ##[debug]..=> '{0}
2020-06-10T19:58:33.9082711Z ##[debug]'
2020-06-10T19:58:33.9083811Z ##[debug]..Evaluating Index:
2020-06-10T19:58:33.9084354Z ##[debug]....Evaluating env:
2020-06-10T19:58:33.9084732Z ##[debug]....=> Object
2020-06-10T19:58:33.9085301Z ##[debug]....Evaluating String:
2020-06-10T19:58:33.9085646Z ##[debug]....=> 'DOCKER_CACHE'
2020-06-10T19:58:33.9086575Z ##[debug]..=> '/tmp/.docker-cache'
2020-06-10T19:58:33.9087090Z ##[debug]=> '/tmp/.docker-cache
2020-06-10T19:58:33.9087285Z ##[debug]'
2020-06-10T19:58:33.9087531Z ##[debug]Result: '/tmp/.docker-cache
2020-06-10T19:58:33.9087726Z ##[debug]'
2020-06-10T19:58:33.9089094Z ##[debug]Evaluating: format('{0}- {1}', runner.os, env.DOCKER_CACHE)
2020-06-10T19:58:33.9089347Z ##[debug]Evaluating format:
2020-06-10T19:58:33.9089581Z ##[debug]..Evaluating String:
2020-06-10T19:58:33.9089815Z ##[debug]..=> '{0}- {1}'
2020-06-10T19:58:33.9090178Z ##[debug]..Evaluating Index:
2020-06-10T19:58:33.9090398Z ##[debug]....Evaluating runner:
2020-06-10T19:58:33.9090631Z ##[debug]....=> Object
2020-06-10T19:58:33.9090888Z ##[debug]....Evaluating String:
2020-06-10T19:58:33.9091107Z ##[debug]....=> 'os'
2020-06-10T19:58:33.9091935Z ##[debug]..=> 'Linux'
2020-06-10T19:58:33.9092214Z ##[debug]..Evaluating Index:
2020-06-10T19:58:33.9092460Z ##[debug]....Evaluating env:
2020-06-10T19:58:33.9092704Z ##[debug]....=> Object
2020-06-10T19:58:33.9092932Z ##[debug]....Evaluating String:
2020-06-10T19:58:33.9093155Z ##[debug]....=> 'DOCKER_CACHE'
2020-06-10T19:58:33.9093502Z ##[debug]..=> '/tmp/.docker-cache'
2020-06-10T19:58:33.9093772Z ##[debug]=> 'Linux- /tmp/.docker-cache'
2020-06-10T19:58:33.9094027Z ##[debug]Result: 'Linux- /tmp/.docker-cache'
2020-06-10T19:58:33.9095542Z ##[debug]Loading env
2020-06-10T19:58:33.9107646Z ##[group]Run actions/cache@v2
2020-06-10T19:58:33.9107860Z with:
2020-06-10T19:58:33.9108068Z   path: /tmp/.docker-cache

2020-06-10T19:58:33.9108279Z   key: Linux- /tmp/.docker-cache
2020-06-10T19:58:33.9108477Z env:
2020-06-10T19:58:33.9108668Z   CACHE_KEY: docker-4.7
2020-06-10T19:58:33.9108875Z   DOCKER_CACHE: /tmp/.docker-cache
2020-06-10T19:58:33.9109778Z   DOCKER_IMAGE: ***.azurecr.io/test-sdc/test:4.7.110.32.2
2020-06-10T19:58:33.9110019Z   cache-name: cache
2020-06-10T19:58:33.9110228Z ##[endgroup]
2020-06-10T19:58:33.9909792Z ::save-state name=CACHE_KEY::Linux- /tmp/.docker-cache
2020-06-10T19:58:33.9910831Z ##[debug]Save intra-action state CACHE_KEY = Linux- /tmp/.docker-cache
2020-06-10T19:58:33.9917273Z ##[debug]Resolved Keys:
2020-06-10T19:58:33.9918644Z ##[debug]["Linux- /tmp/.docker-cache"]
2020-06-10T19:58:33.9922524Z ##[debug]Checking zstd --version
2020-06-10T19:58:34.0053748Z ##[debug]*** zstd command line interface 64-bits v1.4.4, by Yann Collet ***
2020-06-10T19:58:34.0073222Z ##[debug]Resource Url: https://artifactcache.actions.githubusercontent.com/QLVnfwLpxuLAFASFDSAFSUtluiammS1l73AcecvmMb0UyZ1eYGRoP9ckl/_apis/artifactcache/cache?keys=Linux-%20%2Ftmp%2F.docker-cache&version=ca4de5cffa53faefd9b903bc0777e136027c6afa433386ab38a30ADFASFD35dad72bb8a
2020-06-10T19:58:34.5356017Z ::add-mask::***
2020-06-10T19:58:34.5362524Z ##[debug]Cache Result:
2020-06-10T19:58:34.5366360Z ##[debug]{"scope":"refs/heads/master","cacheKey":"Linux- /tmp/.docker-cache","cacheVersion":"ca4de5cffa53faefd9b903bc0777e136027c6afa4486ab38a308035dad72bb8a","creationTime":"2020-06-10T13:55:25.78Z","archiveLocation":"***"}
2020-06-10T19:58:34.5381884Z ##[debug]Archive Path: /opt/actions-runner/_work/_temp/a740fd3a-acd2-48fd-b348-bccec5a1cf6a/cache.tzst
2020-06-10T20:03:17.2594788Z Cache Size: ~573 MB (601272398 B)
2020-06-10T20:03:17.2645604Z [command]/usr/bin/tar --use-compress-program zstd -d -xf /opt/actions-runner/_work/_temp/a740fd3a-acd2-48fd-b348-bccec5a1cf6a/cache.tzst -P -C /opt/actions-runner/_work/hello-github-actions/hello-github-actions
2020-06-10T20:03:20.2733357Z ::save-state name=CACHE_RESULT::Linux- /tmp/.docker-cache
2020-06-10T20:03:20.2734219Z ##[debug]Save intra-action state CACHE_RESULT = Linux- /tmp/.docker-cache
2020-06-10T20:03:20.2738315Z ::set-output name=cache-hit::true
2020-06-10T20:03:20.2794653Z ##[debug]steps['cache']['outputs']['cache-hit']='true'
2020-06-10T20:03:20.2795949Z Cache restored from key: Linux- /tmp/.docker-cache
2020-06-10T20:03:20.2812523Z ##[debug]Node Action run completed with exit code 0
2020-06-10T20:03:20.2814876Z ##[debug]Finishing: Cache

[chrispat]

In general the cache action is really meant for the hosted runners that are new for each invocation. It runs in Azure along with the rest of our runner infrastructure so it’s network close.

If you have your own self-hosted machines that are largely static I would expect the normal tool caches to still be present between runs.

[jdsdc]

@chrispat, i see what you mean. I should have some sort of local storage that i manage myself, fileserver or some local docker repository to store images.

With normal tool chains i guess you mean gradle caches and the likes.

Thanks. Think this can be closed now and conclude that the action cache is not the best solution for self hosted runners.