FetchRemoteInternal triggers a high number of reference transaction hooks
In gitlab!49298 (closed), I attempted to use FetchRemoteInternal
to clone a copy of the gitlab-org/gitlab
repo, but it was significantly slower than the CreateFork
RPC for some reason. When I looked at what it was doing, I noticed a flood of ReferenceTransactionHook
logs:
2020-12-06_17:43:32.31861 praefect-gitaly-0 : {"correlation_id":"01ERWJDGWKV3YR1D6C7078MYYS","grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.deadline_type":"none","grpc.method":"ReferenceTransactionHook","grpc.request.fullMethod":"/gitaly.HookService/ReferenceTransactionHook","grpc.request.glProjectPath":"first/second/gitlab","grpc.request.glRepository":"project-243","grpc.request.repoPath":"@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git","grpc.request.repoStorage":"praefect-internal-0","grpc.request.topLevelGroup":"@hashed","grpc.service":"gitaly.HookService","grpc.start_time":"2020-12-06T09:43:32-08:00","grpc.time_ms":0.112,"level":"info","msg":"finished streaming call with code OK","peer.address":"","pid":69227,"span.kind":"server","system":"grpc","time":"2020-12-06T09:43:32.318Z"}
2020-12-06_17:43:32.33819 praefect-gitaly-0 : {"correlation_id":"01ERWJDGWKV3YR1D6C7078MYYS","grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.deadline_type":"none","grpc.method":"ReferenceTransactionHook","grpc.request.fullMethod":"/gitaly.HookService/ReferenceTransactionHook","grpc.request.glProjectPath":"first/second/gitlab","grpc.request.glRepository":"project-243","grpc.request.repoPath":"@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git","grpc.request.repoStorage":"praefect-internal-0","grpc.request.topLevelGroup":"@hashed","grpc.service":"gitaly.HookService","grpc.start_time":"2020-12-06T09:43:32-08:00","grpc.time_ms":0.097,"level":"info","msg":"finished streaming call with code OK","peer.address":"","pid":69227,"span.kind":"server","system":"grpc","time":"2020-12-06T09:43:32.338Z"}
2020-12-06_17:43:32.35806 praefect-gitaly-0 : {"correlation_id":"01ERWJDGWKV3YR1D6C7078MYYS","grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.deadline_type":"none","grpc.method":"ReferenceTransactionHook","grpc.request.fullMethod":"/gitaly.HookService/ReferenceTransactionHook","grpc.request.glProjectPath":"first/second/gitlab","grpc.request.glRepository":"project-243","grpc.request.repoPath":"@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git","grpc.request.repoStorage":"praefect-internal-0","grpc.request.topLevelGroup":"@hashed","grpc.service":"gitaly.HookService","grpc.start_time":"2020-12-06T09:43:32-08:00","grpc.time_ms":0.094,"level":"info","msg":"finished streaming call with code OK","peer.address":"","pid":69227,"span.kind":"server","system":"grpc","time":"2020-12-06T09:43:32.358Z"}
2020-12-06_17:43:32.37691 praefect-gitaly-0 : {"correlation_id":"01ERWJDGWKV3YR1D6C7078MYYS","grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.deadline_type":"none","grpc.method":"ReferenceTransactionHook","grpc.request.fullMethod":"/gitaly.HookService/ReferenceTransactionHook","grpc.request.glProjectPath":"first/second/gitlab","grpc.request.glRepository":"project-243","grpc.request.repoPath":"@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git","grpc.request.repoStorage":"praefect-internal-0","grpc.request.topLevelGroup":"@hashed","grpc.service":"gitaly.HookService","grpc.start_time":"2020-12-06T09:43:32-08:00","grpc.time_ms":0.088,"level":"info","msg":"finished streaming call with code OK","peer.address":"","pid":69227,"span.kind":"server","system":"grpc","time":"2020-12-06T09:43:32.376Z"}
2020-12-06_17:43:32.39541 praefect-gitaly-0 : {"correlation_id":"01ERWJDGWKV3YR1D6C7078MYYS","grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.deadline_type":"none","grpc.method":"ReferenceTransactionHook","grpc.request.fullMethod":"/gitaly.HookService/ReferenceTransactionHook","grpc.request.glProjectPath":"first/second/gitlab","grpc.request.glRepository":"project-243","grpc.request.repoPath":"@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git","grpc.request.repoStorage":"praefect-internal-0","grpc.request.topLevelGroup":"@hashed","grpc.service":"gitaly.HookService","grpc.start_time":"2020-12-06T09:43:32-08:00","grpc.time_ms":0.117,"level":"info","msg":"finished streaming call with code OK","peer.address":"","pid":69227,"span.kind":"server","system":"grpc","time":"2020-12-06T09:43:32.395Z"}
2020-12-06_17:43:32.41484 praefect-gitaly-0 : {"correlation_id":"01ERWJDGWKV3YR1D6C7078MYYS","grpc.code":"OK","grpc.meta.auth_version":"v2","grpc.meta.deadline_type":"none","grpc.method":"ReferenceTransactionHook","grpc.request.fullMethod":"/gitaly.HookService/ReferenceTransactionHook","grpc.request.glProjectPath":"first/second/gitlab","grpc.request.glRepository":"project-243","grpc.request.repoPath":"@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git","grpc.request.repoStorage":"praefect-internal-0","grpc.request.topLevelGroup":"@hashed","grpc.service":"gitaly.HookService","grpc.start_time":"2020-12-06T09:43:32-08:00","grpc.time_ms":0.1,"level":"info","msg":"finished streaming call with code OK","peer.address":"","pid":69227,"span.kind":"server","system":"grpc","time":"2020-12-06T09:43:32.414Z"}
The dtruss
output showed that the git fetch
appears to be taking its time enumerating each ref:
501 96814 69227 0 9:43am ?? 0:01.27 /usr/local/bin/git --git-dir /Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git -c core.hooksPath=/Users/stanhu/gitlab/gdk-ee/gitaly/ruby/git-hooks fetch --prune ssh://gitaly/internal.git +refs/*:refs/* --end-of-options
440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/logs/refs/tags/v8.3.4\0", 0x9, 0x1B6) = -1 ;5�ed2
14836445 lstat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.4\0", 0x7FFEE4B48F60, 0x0) = -1 2
14836569 rename("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.4.lock\0", "/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.4\0") = 0 0
14836626 __pthread_canceled(0x2, 0x0, 0x0) = 0 366b38a5c01b110ae174abc1cb44238.git/logs/refs/tags/v8.17.7-ee0
14837735 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs\0", 0x7FFEE4B48EE0, 0x0) = 0 0
14837740 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags\0", 0x7FFEE4B48EE0, 0x0) = 0 0
14837852 open("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.4-ee.lock\0", 0x1000A02, 0x1B6) = 7 0
14837871 lstat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.4-ee\0", 0x7FFEE4B48E50, 0x0) = -1 2
14837877 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/packed-refs\0", 0x7FFEE4B48C68, 0x0) = -1 2
ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/packed-refs\0", 0x7FFEE4B48D08, 0x0) = -1 2
14837887 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/packed-refs\0", 0x7FFEE4B48D08, 0x0) = -1 2
14837890 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/packed-refs\0", 0x7FFEE4B48CC8, 0x0) = -1 2
14839004 open("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/logs/refs/tags/v8.3.4-ee\0", 0x9, 0x1B6) = -1 2
14839026 lstat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.4-ee\0", 0x7FFEE4B48F60, 0x0) = -1 access2
14839143 rename("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.4-ee.lock\0", "/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.4-ee\0") = 0 0
14840197 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs\0", 0x7FFEE4B48EE0, 0x0) = 0 0
14840202 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags\0", 0x7FFEE4B48EE0, 0x0) = 0 0
14840287 open("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.5.lock\0", 0x1000A02, 0x1B6) = 7 0
14840303 lstat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.5\0", 0x7FFEE4B48E50, 0x0) = -1 2
14840308 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/packed-refs\0", 0x7FFEE4B48C68, 0x0) = -1 2
14840313 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/packed-refs\0", 0x7FFEE4B48D08, 0x0) = -1 2
14840318 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/packed-refs\0", 0x7FFEE4B48D08, 0x0) = -1 2
14840321 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/packed-refs\0", 0x7FFEE4B48CC8, 0x0) = -1 2
14841193 close(0xA) = 0 sitories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.17.30
14841276 open("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/logs/refs/tags/v8.3.5\0", 0x9, 0x1B6) = -1 2
14841296 lstat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.5\0", 0x7FFEE4B48F60, 0x0) = -1 2
14841426 rename("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.5.lock\0", "/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.5\0") = 0 0
14841484 __pthread_canceled(0x2, 0x0, 0x0) = 0 -ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags0
= 0 0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.17.30
14842697 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs\0", 0x7FFEE4B48EE0, 0x0) = 0 0
14842702 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags\0", 0x7FFEE4B48EE0, 0x0) = 0 0
14842792 open("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.5-ee.lock\0", 0x1000A02, 0x1B6) = 7 0
14842808 lstat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/refs/tags/v8.3.5-ee\0", 0x7FFEE4B48E50, 0x0) = -1 2
14842814 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/packed-refs\0", 0x7FFEE4B48C68, 0x0) = -1 2
14842819 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/packed-refs\0", 0x7FFEE4B48D08, 0x0) = -1 2
14842823 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/packed-refs\0", 0x7FFEE4B48D08, 0x0) = -1 2
14842827 stat64("/Users/stanhu/gitlab/gdk-ee/repositories/@hashed/72/44/72440a20f54075ac43f51a2cf0dbb2a14366b38a5c01b110ae174abc1cb44238.git/packed-refs\0", 0x7FFEE4B48CC8, 0x0) = -1 2
When I dropped the mirrorRefSpec
argument in https://gitlab.com/gitlab-org/gitaly/blob/a12e30fa1b2819ba15a77cc2f7dc822bb12fe64a/internal%2Fgitaly%2Fservice%2Fremote%2Ffetch_internal_remote.go#L40, the FetchInternalRemote
finished in less than a second, but there were no references created in the target repository.
I suspect this is significantly slower than the git clone
case because this is iterating through each ref and updating them one at at time in a transaction. @pks-t Is this expected? I can probably use git clone
for my purposes, but anyone using FetchInternalRemote
(e.g. CloneFromPoolInternal
) will see some pretty slow performance when there are a lot of refs.