Hover performance is still far too slow (and worse with multiple threads)

[mpickering]

There have been previous issues about hover performance in big projects but so far no substantial progress has been made.

I tried again today on ghc/Main.hs with the wip/multi-rebased branch which is based on haskell/ghcide#457 and things seemed very bad still.

• With optThreads = 1 - Hover time was 2.2s
• With optThreads = 0 - Hover time was 6.5s

I tried on the command line and in the editor and could reproduce similar numbers in both, so it's not entirely to do with the FileExists logic which previously closed haskell/ghcide#101.

Here is the profile of performing a single hover request.

https://gist.github.com/mpickering/c12db7d1b9c0724024259f8411189ca6

Load the JSON into speedscope.app in order to view it.

I can't believe that I am the only person who observes this or wants this fixed! But it seems like I am so far the only person to complain about it.

Also see haskell/ghcide#101 and haskell/ghcide#485

[mpickering]

Without profiling turned on the times are

• optThreads = 1 = 1.3s
• optThreads = 0 = 2s

[pepeiborra]

Can you share a Shake profile ?

[mpickering]

Now I have turned off (Haskell) profiling, after the first hover, it seems that the hover call is down to 0.7s which feels more acceptable. I wonder if this was fixed by haskell/ghcide#471

[mpickering]

That is, 0.7s with optThreads = 1, optThreads = 0 is still too slow at over 1.5s.

[mpickering]

Shake profile, it is not very useful imo: https://gist.githubusercontent.com/mpickering/25b13bf30f6558f18487501c3ec4f63b/raw/eff7933fba95d2f148a3ea5256a0a807ed3cecf3/ide-20200323-113440-00006-0.49.html

[pepeiborra]

Shake profile, it is not very useful imo: https://gist.githubusercontent.com/mpickering/25b13bf30f6558f18487501c3ec4f63b/raw/eff7933fba95d2f148a3ea5256a0a807ed3cecf3/ide-20200323-113440-00006-0.49.html

It doesn't tell us the cause, but at least it rules out GetFileExists as the culprit, as the Shake profile shows the only invocations of this rule are for interface files, expected since they do not live in the workspace

[ndmitchell]

Any chance of a normal .prof output? I'm used to reading those and have all the right tools to do so. While this profile view might (or might not) be better, I'd probably want to start with a simpler problem and build up to learning how it works, whereas with this code I'm totally lost.

The code appears to call getSrcSpanInfos which then calls evalGhcEnv multiple times. Why? I have no idea. I guess it's under runGhcEnv somewhere? But each call makes one call to runGhcEnv, so why multiple ones?

Another view has ioMsgMaybe taking all the time. That seems odd.

My guess is I'm not reading the profile right.

[mpickering]

@ndmitchell Nope, not easily because the .prof file is dominated by the initial loading of the project. This profile is for a single hover request which is not easy to isolate in a .prof file.

The first pane does not appear to be very useful here, that's shows an execution trace of the hover. The "left-heavy" pane is like the flamegraph output, similar to what is in a .prof file.

ioMsgMaybe is probably not taking up a lot of time, but there are also probably no cost centres underneath that. The whole call is underneath the getSrcSpanInfos cost centre though, so that will only happen on the first request so probably best to ignore that part of the profile. I would concentrate on the latter half of the left-heavy view, where there is 1s of internal computation which will happen on every hover request.

The other question which can't really be observed in the profile is why optThreads = 1 is so much faster than any other setting I tried.

[ndmitchell]

Thanks @mpickering - looking at it with that information in my brain, I see:

• Would be good to get the second execution. The 1s of internal computation definitely includes things that are only run once, but very hard to figure out which such things they are. My guess is everything under buildOne is a build only, and that subsequent runs don't rebuild - but if they did, that would be the root cause. If you exclude things not under buildOne or the GHC call, you're down to about 100ms, which doesn't match what you are seeing.
• runKey calls nubDepends. That's 161ms, which is awfully heavy. Would be great to get execution counts rather than just times. With that information I'd know how many calls there were to nubDepends and how many to insert. This should be something only called once, but entirely possible it isn't and that's a bug.
• buildRunDependenciesChanged calls fmap which is taking a huge amount of time for an fmap. Would be again good to know how many times it changes, and whether this is on every run or just first time. I have no idea what that fmap is doing.

[mpickering]

Here is the JSON for the second hover. Bare in mind again, that this is with optsThread = 1, which makes the performance close to acceptable.

Profile

• The fmap comes from src/General/Wait.hs, it would be good to know what function this is called with so I can insert more cost centres.

• Looking in the first pane of the profile, I found a call to nubDepends and it is called a lot of times, lasting either 1-2 frames for each call.

• The calls to fmap under buildRunDependenciesChanged seem to happen just after the nubDepends calls and last around 1-3 frames in general.

[mpickering]

Trying on a smaller project (ghcide)

• optThreads = 1 - 0.05 hover response
• optThreads = 0 - 0.35 hover response

Seems like I will be compiling my forks with optThreads = 1 for the foreseeable future.

[mpickering]

Looking in threadscope, it is clear that the work is not split across the available cores. There is barely any overlap between the different HECs which is why the single threaded version is much faster.

[pepeiborra]

Just to add another data point, in our codebase at StanChart, on my Xeon Gold 6234 with 16 physical cores:

• 1 thread: boot time is 2m, hover time is 0.7s
• 16 threads: boot time is ~1m20s, hover time is 1.02s
• 15 threads: boot time is ~1m10s, hover time is 1s
• 4 threads: boot time is 1m30s, hover time is 1s

We know that Shake parallelizes real builds really well, but it seems clear the same strategy doesn't work so well for ghcide where some of the rules are very fast and the overheads of parallelizing them outweigh the benefits. @ndmitchell is there a way to make some rules sequential, like GetFileExists and GetModTime?

[mpickering]

Thanks @pepeiborra, I can also observe in theadscope all cores being utilised during initialisation so your numbers make sense to me.

[mpickering]

@pepeiborra Are those initial hover numbers or subsequent hover numbers after the hover information has been computed and cached?