502 timeouts in creating merge requests

As reported by @markglenfletcher and @balameb in https://gitlab.com/gitlab-org/gitlab-ce/issues/13912#note_26319939, some users are experiencing 502 timeouts when creating merge requests in 9.0.

With the help of profile_url.rb, you can see that for the request @markglenfletcher linked, 92% of the time is spent just retrieving each patch:

https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/10251 should help, but loading the JSON data may still time out in this case.

Note that the repo is 1.4+ GB, which may explain why it takes so long to generate this data.

Nope, size of repo shouldn't count here, GL should handle it quicker. Optimization sucks here.

@stanhu how does this compare to the MR create page, and the compare page, for that pair of branches?

@smcgivern We see the same timeouts with the compare branch. I'll admit I was confused over the "From" and "To" nomenclature of the compare page (which is thankfully being resolved in https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/5972#note_24637085).

I think what @yorickpeterse said a year ago holds true more than ever:

The only way to optimize code like this is to either use a faster storage mechanism, or run it directly on the physical disk(s) storing the Git repository. The latter in turn requires some kind of API/service to run on said servers that takes a Git action to run (e.g. via HTTP) and spits out the result.

Rugged::Diff#each and Rugged::Diff#each_patch can be quite slow (up to 30 seconds).

I think this is case where Gitaly will come into play, unless we can somehow optimize libgit2 or NFS. In looking at the strace logs, I believe it just takes a long time to seek/mmap big files over a networked file system, just as we saw in https://gitlab.com/gitlab-org/gitlab-ee/issues/1811#note_26109097. If you look at the strace logs, you see large blocks of time taken like this:

04:17:53 mmap(0x7f87d1800000, 8388608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f87ca200000
04:17:53 munmap(0x7f87ca200000, 8388608) = 0
04:17:53 mmap(NULL, 20971520, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f87c9600000
04:17:54 mmap(0x7f87caa00000, 8388608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f87c8e00000
04:17:54 munmap(0x7f87c8e00000, 8388608) = 0
04:17:54 mmap(NULL, 29360128, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f87c7a00000
04:17:56 mmap(0x7f87ca200000, 25165824, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f87c6200000
04:17:56 munmap(0x7f87c6200000, 25165824) = 0
04:17:56 mmap(NULL, 67108864, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f87c3a00000
04:18:00 mmap(NULL, 83886080, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f87bea00000
04:18:02 madvise(0x7f87d0a0d000, 1052672, MADV_DONTNEED) = 0

libgit2 is trying to memory-map large pack files over NFS, which causes a lot of round-trips and network transfer. The more files there are in the diff, the more times we have to do this dance.

/cc: @andrewn

@stanhu thanks. I can just about tell from the screenshot that the problem appears to be in getting the changes count (?), as we load the changes tab async on the new MR page. I agree with everything in your previous comment, but is there anything here we think was caused by 9.0 specifically?

@smcgivern Probably not. Good call on the changes count. Perhaps we should be pushing that calculation when we update the merge request in Sidekiq?

@stanhu we don't do anything in Sidekiq for creating an MR at the moment, but maybe we could

Good point, we have to do this on-the-fly. It seems to me we really do need to rely on fast diff generation via Gitaly.

mentioned in issue gitlab-foss#27381 (closed)

added Gitaly in GitLab FOSS label

FYI @stanhu this has already been prioritised and some of the analysis work is already underway: see https://gitlab.com/gitlab-org/gitaly/issues/159.

We were blocked on https://gitlab.com/gitlab-org/gitlab-ee/merge_requests/1522 and https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/10291 but these are cleared now so we'll recommence our work.

mentioned in issue gitaly#159 (closed)

Today I encountered this problem. Push branch -> New merge request -> loading.. and 502 -> Reload -> Merge request edit page -> Save -> Done.

mentioned in issue gitlab-foss#36427 (closed)

marked this issue as related to gitlab-foss#36427 (closed)

Adding description from https://gitlab.com/gitlab-org/gitlab-ce/issues/36427 below, as we've had this lots of times in the last week.

---

What

Error 502 when creating a merge request through the UI or API. Some of these are on the gitlab-ce project.

For the UI I've had 502s for #new, when changing source branch and might also have had it for create. For the API it would have been the equivalent of #create.

When

Many times in the last week

• @rdavila had this in https://gitlab.slack.com/archives/C101F3796/p1502726935746318

• @marin in https://gitlab.slack.com/archives/C101F3796/p1502715408307258

• @jamedjo in https://gitlab.slack.com/archives/C101F3796/p1502463184612669

• @jivanvl in https://gitlab.slack.com/archives/C101F3796/p1502461873850261

• @ClemMakesApps in https://gitlab.slack.com/archives/C101F3796/p1502100761221307

• @jameslopez in https://gitlab.slack.com/archives/C101F3796/p1502100768223429

• @yorickpeterse in https://gitlab.slack.com/archives/C02PF508L/p1502983983000601

• @jneen in https://gitlab.slack.com/archives/C02PF508L/p1502909638000107

This may or may not correlate with high load. A few times there have been questions about 502s for merge requests a couple of mins before a more general outage.

marked this issue as related to gitlab-foss#32844 (closed)

I encountered again. Push branch -> New merge request -> Merge request edit page -> Save -> loading.. and 502 -> Reload -> loading.. and 502 -> Reload -> Done.

According to https://performance.gitlab.net/dashboard/db/rails-controllers?orgId=1&var-action=Projects::MergeRequests::CreationsController%23new&var-database=Production&from=now-7d&to=now as much as 12s is spent on Rugged::Diff#find_similar!. @ahmadsherif does gitaly_commit_raw_diffs cover this?

@eReGeBe It covers renames only, not copies.

@ahmadsherif @andrewn do we have then a migration for this case?

@eReGeBe we tend to refer to migrations by their GitLab::Git migration site. Do you know where Rugged::Diff#find_similar! is being called from in our codebase?

@andrewn Gitlab::Git::Repository#diff_patches. I don't see it on the migration board, so I'm guessing we haven't include it. It looks easy to do with gitaly-ruby.

I was able to create a very simple MR only after a fifth try. Should we assign someone to this issue @DouweM @smcgivern @andrewn?

@eReGeBe it needs to be migrated and with gitaly-ruby it is now possible. But the way the code is structured makes it hard as it is. Too many lazy interactions.

@grzesiek see https://gitlab.com/gitlab-org/gitlab-ce/issues/32844#note_37956016 and below. We could pick the MR resulting from that into 9.5, and maybe https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/13416?

mentioned in issue release-tools#109

mentioned in issue gitaly#510

Gitlab::Git::Repository#diff_patches. I don't see it on the migration board, so I'm guessing we haven't include it. It looks easy to do with gitaly-ruby.

Created https://gitlab.com/gitlab-org/gitaly/issues/510 in the Gitaly tracker to track our migration

I ran a profile that seemed to take a long time to generate for the CE repository:

http://profiler.gitlap.com/20170830/7e1c6181-43d3-43bb-a894-9c63c4687727.html.gz

One thing that stuck out was that 19% spent on retrieving suggested approvers. I wonder if this is blocking the whole render pipeline: https://gitlab.com/gitlab-org/gitlab-ee/issues/2080

mentioned in issue gitlab-foss#37477

marked this issue as related to gitlab-foss#32352 (moved)

moved from gitlab-foss#30154 (moved)