Projects::PipelinesController#index (pipelines.json) is calling Gitaly n+1 times per invocation
When visiting pipelines page for a project, the ajax request to grab all of the pipelines will fail with a 500 internal server error and I can never see any pipelines listed
- GitLab CE
master
,$GDK/gitlab
, gitlab-ce@aec1586c05f30c1a81928b441cd63e422752e56c -
$GDK/gitaly/src/gitlab.com/gitlab-org/gitaly
, 3cec5a47
Visit <namespace>/<project>/pipelines
-> Ajax GET <namespace>/<project>/pipelines.json?scope=all&page=1
Gitlab::GitalyClient::TooManyInvocationsError in Projects::PipelinesController#index
GitalyClient#migrate called 31 times from single request. Potential n+1?
The following call site called into Gitaly 16 times:
/Users/eric/Documents/gitlab/gitlab-development-kit/gitlab/lib/gitlab/gitaly_client.rb:131:in `migrate'
/Users/eric/Documents/gitlab/gitlab-development-kit/gitlab/lib/gitlab/git/repository.rb:1088:in `gitaly_migrate'
/Users/eric/Documents/gitlab/gitlab-development-kit/gitlab/lib/gitlab/git/commit.rb:63:in `find'
/Users/eric/Documents/gitlab/gitlab-development-kit/gitlab/app/models/repository.rb:105:in `commit'
/Users/eric/Documents/gitlab/gitlab-development-kit/gitlab/app/models/project.rb:517:in `commit'
/Users/eric/Documents/gitlab/gitlab-development-kit/gitlab/app/models/ci/pipeline.rb:293:in `latest?'
/Users/eric/.rvm/gems/ruby-2.3.3/gems/grape-entity-0.6.0/lib/grape_entity/delegator/plain_object.rb:6:in `delegate'
/Users/eric/.rvm/gems/ruby-2.3.3/gems/grape-entity-0.6.0/lib/grape_entity/entity.rb:490:in `delegate_attribute'
/Users/eric/.rvm/gems/ruby-2.3.3/gems/grape-entity-0.6.0/lib/grape_entity/exposure/delegator_exposure.rb:6:in `value'
/Users/eric/.rvm/gems/ruby-2.3.3/gems/grape-entity-0.6.0/lib/grape_entity/exposure/base.rb:79:in `valid_value'
/Users/eric/.rvm/gems/ruby-2.3.3/gems/grape-entity-0.6.0/lib/grape_entity/exposure/base.rb:63:in `serializable_value'
/Users/eric/.rvm/gems/ruby-2.3.3/gems/grape-entity-0.6.0/lib/grape_entity/exposure/nesting_exposure.rb:61:in `block (2 levels) in serializable_value'
It looks like Gitaly is running,
ps aux | grep gitaly
eric 4020 0.1 0.1 2626420 12216 s005 S+ 12:47PM 0:31.84 bin/gitaly-ruby 4000 /var/folders/z_/_m9m0xpn0kb_pl20hh5pvvnh0000gn/T/gitaly-ruby872112313/socket
eric 21123 0.0 0.1 556652352 13772 s002 S+ 3:53PM 0:00.29 gitaly/bin/gitaly /Users/eric/Documents/gitlab/gitlab-development-kit/gitaly/config.toml
GDK log around the request
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg=spawn args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 4b7766eea985318b7c5435fc1ec22f705584aad7 --]" grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= pid=21563 span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="finished unary call" grpc.code=OK grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService grpc.time_ms=8 peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="spawn complete" args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 4b7766eea985318b7c5435fc1ec22f705584aad7 --]" command.exitCode=0 command.inblock=0 command.maxrss=1515520 command.oublock=0 command.real_time_ms=8.432604 command.system_time_ms=1.119 command.user_time_ms=2.275 grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg=spawn args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 investigate-empty-artifacts --]" grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= pid=21564 span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="finished unary call" grpc.code=OK grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService grpc.time_ms=7 peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="spawn complete" args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 investigate-empty-artifacts --]" command.exitCode=0 command.inblock=0 command.maxrss=1507328 command.oublock=0 command.real_time_ms=8.062746 command.system_time_ms=1.229 command.user_time_ms=2.2110000000000003 grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg=spawn args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 23d1b20f4f6a0b4049851a2563aff30bdbaf2fae --]" grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= pid=21565 span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="finished unary call" grpc.code=OK grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService grpc.time_ms=7 peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="spawn complete" args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 23d1b20f4f6a0b4049851a2563aff30bdbaf2fae --]" command.exitCode=0 command.inblock=0 command.maxrss=1507328 command.oublock=0 command.real_time_ms=7.674937000000001 command.system_time_ms=0.93 command.user_time_ms=2.0380000000000003 grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg=spawn args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 investigate-empty-artifacts --]" grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= pid=21566 span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="finished unary call" grpc.code=OK grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService grpc.time_ms=9 peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="spawn complete" args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 investigate-empty-artifacts --]" command.exitCode=0 command.inblock=0 command.maxrss=1593344 command.oublock=0 command.real_time_ms=9.617705 command.system_time_ms=1.957 command.user_time_ms=2.4160000000000004 grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg=spawn args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 6aff23b5a948698624271a919bab04ccdda43057 --]" grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= pid=21567 span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="finished unary call" grpc.code=OK grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService grpc.time_ms=8 peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="spawn complete" args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 6aff23b5a948698624271a919bab04ccdda43057 --]" command.exitCode=0 command.inblock=0 command.maxrss=1507328 command.oublock=0 command.real_time_ms=8.736335000000002 command.system_time_ms=1.122 command.user_time_ms=2.174 grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg=spawn args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 investigate-empty-artifacts --]" grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= pid=21568 span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="finished unary call" grpc.code=OK grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService grpc.time_ms=7 peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="spawn complete" args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 investigate-empty-artifacts --]" command.exitCode=0 command.inblock=0 command.maxrss=1511424 command.oublock=0 command.real_time_ms=7.352393 command.system_time_ms=1.1800000000000002 command.user_time_ms=2.157 grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg=spawn args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 d5b2847d74e1f57fa43a7f128e8105d41821f67f --]" grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= pid=21569 span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="finished unary call" grpc.code=OK grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService grpc.time_ms=6 peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="spawn complete" args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 d5b2847d74e1f57fa43a7f128e8105d41821f67f --]" command.exitCode=0 command.inblock=0 command.maxrss=1507328 command.oublock=0 command.real_time_ms=6.995571000000001 command.system_time_ms=0.8870000000000001 command.user_time_ms=1.9790000000000003 grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg=spawn args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 investigate-empty-artifacts --]" grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= pid=21570 span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="finished unary call" grpc.code=OK grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService grpc.time_ms=7 peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="spawn complete" args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 investigate-empty-artifacts --]" command.exitCode=0 command.inblock=0 command.maxrss=1507328 command.oublock=0 command.real_time_ms=7.551 command.system_time_ms=1.0040000000000002 command.user_time_ms=2.019 grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg=spawn args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 84cb4a6623f7c4cc8706db65e05f59d338e23d18 --]" grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= pid=21571 span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="finished unary call" grpc.code=OK grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService grpc.time_ms=7 peer.address= span.kind=server system=grpc
15:55:26 gitaly.1 | time="2017-09-29T15:55:26-05:00" level=info msg="spawn complete" args="[/usr/bin/git --git-dir /Users/eric/Documents/gitlab/gitlab-development-kit/repositories/root/playing-with-selenium.git log -z --pretty=format:%H%x1f%s%x1f%B%x1f%an%x1f%ae%x1f%aI%x1f%cn%x1f%ce%x1f%cI%x1f%P --max-count=1 84cb4a6623f7c4cc8706db65e05f59d338e23d18 --]" command.exitCode=0 command.inblock=0 command.maxrss=1515520 command.oublock=0 command.real_time_ms=7.593891 command.system_time_ms=0.9380000000000001 command.user_time_ms=2.045 grpc.method=FindCommit grpc.request.repoPath=root/playing-with-selenium.git grpc.request.repoStorage=default grpc.request.topLevelGroup=root grpc.service=gitaly.CommitService path=/usr/bin/git peer.address= span.kind=server system=grpc
15:55:26 gitlab-workhorse.1 | 192.168.1.135:3000 192.168.1.135:50426 - - [2017-09-29 15:55:25.570253 -0500 CDT] "GET /root/playing-with-selenium/pipelines.json?scope=all&page=1 HTTP/1.1" 500 165913 "http://192.168.1.135:3000/root/playing-with-selenium/pipelines" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.38 Safari/537.36" 1.306455
<img src="https://i.imgur.com/0Teoc0q.png" width=50%">
I tried with rails console
-> Feature.disable(:gitaly_tags)
and without, Feature.enable(:gitaly_tags)
.
Workaround
If it’s blocking you from getting any work done, as a temporary measure, return early in
GitalyClient.enforce_gitaly_request_limits
That’ll help you workaround the issue while I finish off https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/14451
-- @andrewn, https://gitlab.slack.com/archives/C3ER3TQBT/p1506719216000296
cc @andrewn