Gitaly durations aren't accurate for streaming responses
From https://gitlab.com/gitlab-org/gitlab-ce/issues/64920#note_194538615, I've found cases where the Gitaly durations aren't accurate for streaming RPCs because we only take into account the time it takes for the initial RPC, not for the time it takes to produce and consume the RPC from Gitaly. For example, in CommitService#find_commits
, we do the following in https://gitlab.com/gitlab-org/gitlab-ce/blob/6c04066d4599af2efd4db43b2933003b8493e8dd/lib/gitlab/gitaly_client/commit_service.rb#L336-338:
response = GitalyClient.call(@repository.storage, :commit_service, :find_commits, request, timeout: GitalyClient.medium_timeout)
consume_commits_response(response)
Even though these two lines collectively took 30 seconds, the performance bar showed it only took 0.583 s because it was only counting the execution time of the first line.
However, inside consume_commits_response
, response.flat_map
actually causes the RPC to do something:
def consume_commits_response(response)
response.flat_map do |message|
message.commits.map do |gitaly_commit|
Gitlab::Git::Commit.new(@repository, gitaly_commit)
end
end
end
I think we should just instrument the two lines as a block rather than only consider the GitalyClient.call
timing.