Loading an issue take more than 20 secs

Description

This issue, which has ~50 comments and images, takes more than 20 seconds to load usually.

On the time of the recording, it took more than 30 seconds.

The browser almost seems to suffer from loading all the content. Moreover, the page keeps jumping (as we load images).

It seems that we

• load too many assets
• do not set the image height for the img tag, which makes the page to jump when we load images.

We should do something about this.

cc @stanhu

Status changed to closed

Status changed to reopened

Added ~18308 ~19492 labels

@regisF sorry, I fat fingered closing the issue.

Milestone changed to %8.13

Added ~127616 label

@regisF can you record again? I don't know if this is something that got improved by the patch release we deployed since this issue was created, but loading the issue seems pretty responsive for me, and the timings in my machine are around 6s even with cache disabled:

@eReGeBe not for me :-)

Just to make it crystal clear: I take this screenshot once the loading icon of the tab in Chrome disappears and shows the favicon.

Thanks @blackst0ne

@pcarranza @eReGeBe so this is super interesting.

By mistake I've loaded a very heavy page in the Invisible mode in Chrome. And actually, when we are logged out, those super heave pages load really, really fast.

I did the test with the same page logged, and it takes forever to load them.

In the example above, logged out, the page takes less then 4 seconds to load. When logged, > 30 seconds.

@yorickpeterse also.

@regisF Seeing the large number of participants that may be due to GitLab checking if you're subscribed to the issue (which involves building the list of participants). This doesn't happen when you're not logged in.

@yorickpeterse building the list of participants where? On the sidebar? When we do @ in the comment box? What can we do to improve this?

@regisF Right, we're aware that the performance is different based on permissions of the user. For example, since you have Master access, the "Edit" note button is available to you. This causes us to render a hidden Markdown element for every note (see gitlab-org/gitlab-ce#23227), which is slow. Let me get you the backend profile on that issue with an authenticated user.

@regisF In the sidebar to display it, and another time to check if you're subscribed via a mention.

Attached is the profile of that issue with a Master user. Here's the high-level breakdown:

• 17% spent rendering the participants for the sidebar (#23206 (closed))
• 12% spent rendering the layout partials (mostly Hamlit stuff , navigation links?)
• 11% spent rendering for the "Edit" button (#23227 (closed))
• 11% spent rendering the Markdown in the notes
• 9% spent rendering the award emojis (#23226 (moved), #23241 (moved))

issue985.zip

The previous benchmark is simply the time it takes for the backend to return the full HTML to display. The above doesn't cover the time it takes to load the images and display them in the browser.

For me, the backend takes 1.5-2 s to download the page, so for once I think the slowness is due to all the assets and DOM rendering. :)

/cc: @jschatz1

@stanhu I think you are right. I'll see if I can dig deeper to see what is causing it on the frontend side.

@regisF something isn't right here, at all. autocomplete_sources shouldn't be loading more than once and it definitely shouldn't be blocking the page render. What happens if you disable all your extensions? Are you on the latest version of Chrome? (53 or 54 should be fine)

@jschatz1 seems to be autocomplete_sources, which I have railed against before :) #18435 (closed)

It shouldn't be blocking page render though, so this is weird. It's also not happening when I try to load the page.

@regisF @eReGeBe @blackst0ne would you mind running a speed test? Either Regis' internet is bad or our lack of CDN is affecting the results depending on location.

Mine:

@connorshea my internet is crazy fast. This is not the issue.

This is my test, logged , on a fresh installation of Google Canary without any plugins. autocomplete_sources is executed multiple times. And Canada shouldn't be that far from the datacenter.

As GitHub famously said, it's not shipped until it's fast.

@regisF that's super weird, I don't understand why you're the only one who can reproduce it :/

What if you clear your cache?

Cache has been cleared. FYI I have 3 computers and they all have the same behaviour with this issue.

@regisF can you make a GIF or YouTube video of what happens as you load that issue, both in the browser and in the Network panel?

So take a look at this. The browser seems to suffer so much. Happens on Safari too, by the way.

The recording stopped when the browser asked to save the password, so it actually took longer than 34 secs to render the page.

https://gfycat.com/WholeWelcomeCrane

@regisF does it happen on WiFi networks other than your own?

@connorshea
From YS (where I am in right now) to Denver, CO (Anaxa LLC) I have these speedtests:

Result of page loading in a new incognito page with disabled cache:

@connorshea haven't tested on another network. I can try to load this in another place.

Another issue that makes my browser totally suffer like crazy: https://gitlab.com/gitlab-org/gitlab-ce/issues/21747

@connorshea unlogged, this is crazy fast to load. I don't think my connection is the issue here, really.

@regisF, is that page being loaded quite faster if you try to load it as a guest (not logged in)?

Ah, just got your comment.

I don't understand why it only happens to you though, no one else can seem to reproduce it, and it definitely shouldn't be trying to load the autocomplete_sources file more than once.

@connorshea just tried on Firefox (without plugins), logged, I get this:

Autocomplete just does not work. I hope I'm the only one who has this problem.

I also don't have any plugins, any adblocker, nothing in /etc/hosts that could f**k up loading the resources.

Well we're loading the script from the same URL. I wonder if the SHA hash is different for yours for some reason? Being modified in-transit by the ISP or something?

I'm grasping at straws here, this makes no sense!

@regisF Can you download the script, save it to the desktop or whatever and then run shasum filename.js?

I get b0bd61b6871931d330d6d696d9c4698dee43d1d7

By "the script" I mean the application-RANDOMCHARACTERS.js

I get the same b0bd61b6871931d330d6d696d9c4698dee43d1d7

@regisF okay, last idea. What if you log into a different account?

Let's think through the problem here: Regis is seeing autocomplete_sources load multiple times. It's possible there's a bug that only happens in certain circumstances. In the code, we see:

$ git grep autocomplete_sources
app/controllers/projects_controller.rb:  def autocomplete_sources
app/views/layouts/_init_auto_complete.html.haml:  GitLab.GfmAutoComplete.dataSource = "#{autocomplete_sources_namespace_project_path(project.namespace, project, type: noteable_type, type_id: params[:id])}"

Let's look at the HAML: https://gitlab.com/gitlab-org/gitlab-ce/blob/master/app/views/layouts/_init_auto_complete.html.haml#L7

Inline JavaScript. This smells like a problem where there the same initializer gets run again. Who uses this layout?

$ git grep auto_complete
app/assets/javascripts/notes.js:/*= require gfm_auto_complete */
app/views/projects/_zen.html.haml:  = render "layouts/init_auto_complete" if current_user && (@target_project || @project)

Ah, ZenMode, indeed: https://gitlab.com/gitlab-org/gitlab-ce/blob/master/app/views/projects/_zen.html.haml#L11-12

The content_for :scripts_body means that anytime :scripts_body is used, this layout will be rendered. But what happens if :scripts_body is already defined? It gets APPENDED by default, unless the :flush option is used. Look at this line: https://github.com/rails/rails/blob/76c385709c873a7105e3a267d84c4e70417a15e2/actionview/lib/action_view/helpers/capture_helper.rb#L156

Also see: http://api.rubyonrails.org/classes/ActionView/Helpers/CaptureHelper.html#method-i-content_for

So I think it's very possible that we render multiple copies of the JavaScript here, causing what Regis sees.

http://api.rubyonrails.org/classes/ActionView/Helpers/CaptureHelper.html#method-i-content_for describes the issue quite well about the data being appended. Now I have to ask: how did this ever work normally?

I see gitlab-org/gitlab-ce!6569 may solve this to address https://gitlab.com/gitlab-org/gitlab-ce/commit/b66a8203ca66f6a5e70e4c0bfcb07a0385560591, but I have to wonder: is the right solution really in the JavaScript or should we be cleaning up how we render these JavaScript lines?

/cc: @brycepj, @rspeicher

Wow, I looked at the page source in my dev environment. Talk about repetition:

/cc: @iamphill

Added ~17876 label

!6207 (merged) caused this duplicate JavaScript issue.

Mentioned in issue #22011 (closed)

Ideally we'd handle this in the JavaScript and not have any inline JS :)

That still doesn't make sense to me though, why did it only effect Regis?

One reason is that he is has Master privileges, and the JavaScript is rendered for each note that he can edit. If I look at the HTML of my page, I see the duplicate JavaScript. When I put breakpoints on the page, I definitely see GitLab.GfmAutoComplete.setup(); being called multiple times.

@stanhu, I guess #22802 (closed) is relevant here, just as @brycepj guessed.

Mentioned in issue #22802 (closed)

@stanhu i'll submit a fix

Mentioned in commit 0250482e

Mentioned in merge request !6840 (merged)

@stanhu Here are my notes on the problem, when I encountered it a couple of weeks ago https://gitlab.com/gitlab-org/gitlab-ce/issues/22704#note_16132971 I included a screenshot of my devtools profiler there, which hones in precisely on the source of the lag.

tldr: It's not a network problem, it's an insane amount of DOM operations being inadvertantly run for every editable diff note on a page. If you're not looking at a page with lots of comments/notes, you won't be able to to reproduce. (cc: @connorshea )

Calls to GfmAutoComplete.setup were inlined as part of an effort to avoid loading gfm resources on pages where we don't need them. That made the slowdown more noticeable because it was run for each diff note.

I refactored setup a bit, to avoid running DOM operations for gfm more than once. Removing inline calls isn't a clean fix because setup is often called from multiple places on a page, other than the offending inline calls. setup needs to be a better gatekeeper.

Anyway, there's some discussion on this in the MR (https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/6569). The fix was merged to master a few days ago. Once it's put in production, I believe what @regisF is seeing will be solved completely.

@brycepj can/should we backport that to 8.12?

@connorshea I assume so... I don't know a lot about how deployment works here yet, but I'd say we want to get it into anything that came after https://gitlab.com/gitlab-org/gitlab-ce/commit/b66a8203ca66f6a5e70e4c0bfcb07a0385560591.

Milestone changed to %8.12

Mentioned in commit 7d418631

@brycepj Thanks for making GfmAutoComplete.setup a better gatekeeper. It does seem, however, that the root cause is that we were inadvertently including duplicate calls to GfmAutoComplete.setup. This happens usually when the user can edit notes (e.g. Master privileges). I think @iamphill's attempt to address this in !6840 (merged) is a better fix for 8.12 since it changes fewer things to fix the crux of the issue.

@stanhu that's fine with me. I agree that the many additional calls made by editable diff notes really made this problem a problem.

Afaik the number of unnecessary DOM setup interactions (the source of the lag) will still be n^2 - n, where n is the number of times setup is called. I believe this fix will keep n to 4. Not good, but definitely not as bad as n growing indefinitely.

If we do backport @iamphill's new MR ( !6840 (merged)), does that mean it will also be merged into master? If so, we should probably revisit the issues that https://gitlab.com/gitlab-org/gitlab-ce/commit/b66a8203ca66f6a5e70e4c0bfcb07a0385560591 was meant to fix, since !6840 (merged) reverts them.

@stanhu just tested to load the issue that caused problems, I think you've pushed a fix to production (you or someone else), because it loads super fast now. Thanks!!!!

Perfect.

I let you, gentlemen, close this issue if you have finished talking about whatever you were talking.

8.13 RC2 was deployed, and Bryce's fix (!6569 (merged)) solves the load time problem. However, the duplicate JavaScript code still remains, and I think we want to fix this for 8.12. I recommend that we keep this issue open until we address the root cause.

@stanhu I agree let's keep this open until !6840 (merged) lands on the next 8.12 patch (and it will obviously be included in the next 8.13 RC).

Reassigned to @iamphill

Mentioned in commit 270434f7

Mentioned in commit ed81fb4c

Mentioned in commit 42195ff6

!6840 (merged) is now included in 8.12.7 (to be announced in a few hours).

Status changed to closed

@rymai