Using docker+machine autoscaler the runner creates 1 VM at a time, even if the job queue is long
Summary
If I have a build step with many parallel jobs (in my case an rspec knapsack job with 20 parts done in parallel), then I observe the behaviour of:
- check for job, and 1 job picked up
- docker-machine starts a VM
- nothing happens until the VM is up and running
- now check for another job
I have concurrent = 40, limit = 22, request_concurrency = 20, IdleCount = 1
This staggered start means it takes ~1min per VM to start, so spinning up 20 is slow, when 20 could have started in 1min it takes instead 20+min.
Steps to reproduce
Use docker+machine (on google cloud if important), create a build step with many parallel jobs.
Actual behavior
1 VM is created at a time, instead of N VMs created in one go.
Expected behavior
N VMs created in one go until the jobs queue is empty (or we hit our limit)
Relevant logs and/or screenshots
My logs clearly show that there's never more than 1 "Creating machine.." to "Machine created." section active at any point in time.
The first 2 entries are created on boot (it creates 2 even though IdleCount is 1, seen a ticket elsewhere about this). After that the patterns is pretty clear once I grep only for the interesting messages:
» grep -E '(Creating machine|Checking for jobs|Machine created\" name)' /tmp/logs.txt | uniq 14:28:19
Jul 20 10:42:15 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:42:15Z" level=info msg="Creating machine..." driver=google name=runner-c3580ebd-auto-scale-runner-1532083332-bf615fe7 operation=create
Jul 20 10:42:15 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:42:15Z" level=info msg="Creating machine..." driver=google name=runner-c3580ebd-auto-scale-runner-1532083334-53770e34 operation=create
Jul 20 10:44:34 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:44:34Z" level=info msg="Machine created" name=runner-c3580ebd-auto-scale-runner-1532083332-bf615fe7 now="2018-07-20 10:44:34.056896386 +0000 UTC" retries=0 time=2m21.062253834s
Jul 20 10:45:03 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:45:03Z" level=info msg="Machine created" name=runner-c3580ebd-auto-scale-runner-1532083334-53770e34 now="2018-07-20 10:45:03.466342567 +0000 UTC" retries=0 time=2m48.467388177s
Jul 20 10:49:59 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:49:59Z" level=info msg="Checking for jobs... received" job=83202255 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 10:54:45 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:54:45Z" level=info msg="Checking for jobs... received" job=83202271 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 10:54:46 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:54:46Z" level=info msg="Checking for jobs... received" job=83202267 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 10:54:49 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:54:49Z" level=info msg="Creating machine..." driver=google name=runner-c3580ebd-auto-scale-runner-1532084089-e768bfa5 operation=create
Jul 20 10:56:54 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:56:54Z" level=info msg="Machine created" name=runner-c3580ebd-auto-scale-runner-1532084089-e768bfa5 now="2018-07-20 10:56:54.091660935 +0000 UTC" retries=0 time=2m4.86537009s
Jul 20 10:56:55 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:56:55Z" level=info msg="Checking for jobs... received" job=83202256 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 10:56:57 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:56:57Z" level=info msg="Creating machine..." driver=google name=runner-c3580ebd-auto-scale-runner-1532084217-b65293d6 operation=create
Jul 20 10:59:18 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:59:18Z" level=info msg="Machine created" name=runner-c3580ebd-auto-scale-runner-1532084217-b65293d6 now="2018-07-20 10:59:18.566765086 +0000 UTC" retries=0 time=2m21.325649144s
Jul 20 10:59:19 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:59:19Z" level=info msg="Checking for jobs... received" job=83202257 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 10:59:21 gitlab-runner gitlab-runner[2612]: time="2018-07-20T10:59:21Z" level=info msg="Creating machine..." driver=google name=runner-c3580ebd-auto-scale-runner-1532084361-c8a5c16c operation=create
Jul 20 11:01:36 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:01:36Z" level=info msg="Machine created" name=runner-c3580ebd-auto-scale-runner-1532084361-c8a5c16c now="2018-07-20 11:01:36.885790371 +0000 UTC" retries=0 time=2m15.628492987s
Jul 20 11:01:37 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:01:37Z" level=info msg="Checking for jobs... received" job=83202258 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 11:01:39 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:01:39Z" level=info msg="Creating machine..." driver=google name=runner-c3580ebd-auto-scale-runner-1532084499-7e660c08 operation=create
Jul 20 11:03:29 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:03:29Z" level=info msg="Machine created" name=runner-c3580ebd-auto-scale-runner-1532084499-7e660c08 now="2018-07-20 11:03:29.145125066 +0000 UTC" retries=0 time=1m49.872652351s
Jul 20 11:03:29 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:03:29Z" level=info msg="Checking for jobs... received" job=83202259 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 11:03:31 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:03:31Z" level=info msg="Creating machine..." driver=google name=runner-c3580ebd-auto-scale-runner-1532084611-3aeed62c operation=create
Jul 20 11:05:56 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:05:56Z" level=info msg="Machine created" name=runner-c3580ebd-auto-scale-runner-1532084611-3aeed62c now="2018-07-20 11:05:56.357455053 +0000 UTC" retries=0 time=2m25.073125897s
Jul 20 11:05:58 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:05:58Z" level=info msg="Checking for jobs... received" job=83202260 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 11:06:01 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:06:01Z" level=info msg="Creating machine..." driver=google name=runner-c3580ebd-auto-scale-runner-1532084761-3a728fe8 operation=create
Jul 20 11:07:59 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:07:59Z" level=info msg="Checking for jobs... received" job=83202261 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 11:08:27 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:08:27Z" level=info msg="Machine created" name=runner-c3580ebd-auto-scale-runner-1532084761-3a728fe8 now="2018-07-20 11:08:27.230774908 +0000 UTC" retries=0 time=2m25.923205239s
Jul 20 11:08:27 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:08:27Z" level=info msg="Checking for jobs... received" job=83202262 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 11:08:29 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:08:29Z" level=info msg="Creating machine..." driver=google name=runner-c3580ebd-auto-scale-runner-1532084909-ff5755c3 operation=create
Jul 20 11:10:30 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:10:30Z" level=info msg="Machine created" name=runner-c3580ebd-auto-scale-runner-1532084909-ff5755c3 now="2018-07-20 11:10:30.699363026 +0000 UTC" retries=0 time=2m1.373691135s
Jul 20 11:10:31 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:10:31Z" level=info msg="Checking for jobs... received" job=83202263 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 11:10:33 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:10:33Z" level=info msg="Creating machine..." driver=google name=runner-c3580ebd-auto-scale-runner-1532085033-95afb71d operation=create
Jul 20 11:10:43 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:10:43Z" level=info msg="Checking for jobs... received" job=83202264 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 11:12:44 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:12:44Z" level=info msg="Machine created" name=runner-c3580ebd-auto-scale-runner-1532085033-95afb71d now="2018-07-20 11:12:44.895268324 +0000 UTC" retries=0 time=2m11.551328517s
Jul 20 11:12:45 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:12:45Z" level=info msg="Checking for jobs... received" job=83202265 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 11:12:47 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:12:47Z" level=info msg="Creating machine..." driver=google name=runner-c3580ebd-auto-scale-runner-1532085167-2c2d9ff0 operation=create
Jul 20 11:14:23 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:14:23Z" level=info msg="Checking for jobs... received" job=83202266 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Jul 20 11:15:01 gitlab-runner gitlab-runner[2612]: time="2018-07-20T11:15:01Z" level=info msg="Checking for jobs... received" job=83202268 repo_url="https://gitlab.com/boardiq/portal.git" runner=c3580ebd
Fuller logs: logs.txt
Environment description
Running on google cloud vs gitlab.com
Used GitLab Runner version
Version: 11.0.2
Git revision: 1db57d4a
Git branch: 11-0-stable
GO version: go1.8.7
Built: 2018-07-16T21:46:29+00:00
OS/Arch: linux/amd64