SRTP with large overload sets and errors leads to very high compilation load

[abelbraaksma]

EDIT (22 May): A repro that exhibits the likely cause of this bug (albeit not exactly the described sluggish behavior), was finally found by me after a week or so and 70+ helpful comments and traces. Instead of reading all, new visitors should probably just go to #9201 (comment). Please try the repro, I'm very curious whether it's reproducible.

---

A project that takes roughly 1 min to compile, after loading it in VS 2019, I first compiled it and then decided to measure how long it took for coloring, tooltips etc appear:

• After about 5 minutes, coloring appears
• About 10 or so minutes, the first type-tooltip appears
• About 20 or so minutes, the first error (I had only the file open that would show the first error shown in the build output window)
• Moving from one identifier to another, it takes between 30s and 2 minutes before a type popup appears
• Similarly, the "Error list" window very slowly builds up with errors long known from compiling (just now, 42 minutes after opening, it shows 8 of 10 errors it should show).

GIF animation of first 30-something minutes, click to start from the beginning, and grab some crisps and 3 beers before you start ;).

Repro steps

Reproducible with my project and possibly with other large projects, I'd be interested if others have seen similar behavior.

At 34 minutes, it showed 22 tasks in background queue
At 53 minutes, it showed 19 tasks in background queue
At 56 minutes, it showed 0 tasks (finished) and mouseovers were responsive again (until I edit anything, one letter took another 5+ minutes with 6 tasks in queue ...).

Expected behavior

While I can understand that building up the IDE can take a bit longer than a simple rebuild-all, I don't expect it to take the same time I'd normally tend to fall asleep in a Vin Diesel movie. Making the screen-capture was just about similarly entertaining ;).

Actual behavior

As described above. Slooooow. For fair comparison, I opened only one VS IDE, and disabled most, but not all, 3rd party extensions.

In the Task Manager I can see devenv.exe at 4% CPU, which is effectively one CPU core on my machine. Memory for devenv.exe in those 40+ minutes went from 1.4GB to 1.6GB. Traditionally, I only notice extreme sluggishness after it reaches 2.8GB or higher.

Known workarounds

Strangely, I don't always see this behavior, though it has been like this for a few weeks now. I'm now going to restart, remove any auxiliary files, clean everything and start afresh, see if it still happens. As it is now, it is absolutely unworkable.

Related information

I'd be very interested in getting to the bottom of this, if you need any traces (I assume you do) or anything else, I'm more than willing to provide those.

• VS 2019 non-preview, most recent.

[abelbraaksma]

Few hours later, I have submitted a trace (took long, because, well, typing one character takes 20 minutes at least...). I made the trace after: restart computer, removed *.user files, clean solution. I then waited for all background processes to stop (over 30 minutes this time around) and started the trace.

The trace collected data for another 35 minutes or so (the time it took to type one character and wait for the again-started background processes to stop and VS to become responsive again). I added comments in the trace for actions I did.

The trace is attached to https://developercommunity.visualstudio.com/content/problem/1034777/typing-in-an-f-solution-takes-minutes-to-get-type.html and most likely only viewable to MS employees (@KevinRansom, @dsyme, @cartermp, I assume you are able to access this?).

All fun and pun aside, as it is now I cannot develop anything seriously anymore... :S (though, gotta admit, if you type one char per 30 minutes, your code quality greatly improves! As does my coffee addiction).

My next steps: disabling everything in VS that could hog the CPU, installing latest previews to see if that improves things etc etc (I severely hope it is some extension I overlooked). Somehow I need to be able to get back to work ;).

[cartermp]

@abelbraaksma I'm looking at the trace, and it's ... weird. I'm not sure if I can say anything at his point, but in the trace, literally nothing is showing as being allocated until 24 minutes into the trace. After that, there's data about allocations. When looking at CPU stacks, it's not until 29 minutes into the trace that anything is registered.

This is pending some more investigation, but the CPU and memory usage items actually look fairly normal if I slice the sample to a period where there's actually data. Though it would be indicate of the compiler simply having to process a lot of F# code, since top allocations are from strings and tuples used deep in the guts of the compiler. CPU stacks show a similar story.

What's most telling about something being off here is that 1.4GB is nowhere near enough memory usage for devenv.exe to go haywire due to exceeding memory limitations, and 4% CPU is also not a whole lot of work going on. It's almost as if there's some enormous Thread.Sleep() getting called somewhere.

[abelbraaksma]

Ok, bunch of tests further and a bit wiser (and a bit more confused). I did the following things:

• Really turned off all extensions, incl. the ones that shouldn't interfere. Restarted, and instead of 20-40 min background time, it went down to 2-5 minutes (still way too long, but a clear improvement).
• Turned back on all extensions: the times stayed at 2-5 minutes (background tasks time after each edit) and ~20s for tooltips to appear. This was the confusing bit, apparently disabling and re-enabling all extensions (of one in particular, I don't know which) has cleared some kind of cache or setting that was persistent through restarts, Clean Build etc.
• Turned of all F# options that could have some influence on performance, including scrollbar-as-map, guidelines etc. This had a huge impact, after restarting VS, same code showed tooltips in 2-4s first time, and henceforth immediate. Red squigglies in 7 sec after restart. Coloring and tooltips in opening other files was almost instantenous. At least this showed that the issue wasn't with my own code or edits per se.
• Turned options on one by one. This showed that the following option (Enable in-memory cross-project references) was causing all problems:

I repeated this a few times to be sure. I know that in the past this setting was set to 200 and enabled and that it caused a lot of performance problems. Several issues on github were reported on it and @cartermp (iirc) showed me back then to lower the number to 3 or 4. It has since been 3 and until recently this didn't give me real problems.

I thought that if I disabled this option, that tooltips wouldn't work on types that are not defined in the current project, but in a project-to-project reference (at least that is how I remembered it: disabling completely was a bad idea in the past). But I seem to have been wrong, or behavior has changed. I couldn't (yet) find any behavior difference with caching on or off, except for extreme (200-500x) performance degradation. And let's be fair, "caching" suggests speed-up, not speed-down.

If you read my reports thus far, I'll summarize the remaining questions:

1. The extreme performance degradation mentioned in the original report (and with the trace), what could cause this and how can we prevent it? One additional observation: the solution had an added project which lies in-between in the references-chain. If anything, that's the only "big" change from recent weeks, perhaps this confused this feature?
2. How is this feature supposed to work and shouldn't it improve performance (until memory gets in the way, but here we saw memory between 1.2Gb and 1.6Gb, nothing extreme)? And if its only effect is to downgrade performance 400x, what feature does it enable or improve that warrants such perf timings?
3. Conversely: what will stop working if this feature is disabled? (so far it's the opposite, I have my supercool F# experience back and it's faster than ever!!!!)

Until it happens again, I won't be able to get the 40-minutes start-up performance and 20-minutes per-edit performance back, as my actions seem to have changed it, hopefully forever. Hopefully the report, however, can help analyze what happened here and prevent it from happening to others.

[abelbraaksma]

and 4% CPU is also not a whole lot of work going on

@cartermp, thanks for looking at this! You may read/interpret this wrong (if you got it from the trace), because I could see clearly in Process Explorer that a single thread was running 100% on a single CPU Core. Since I have 24 cores over 2 physical CPUs, that comes down to 4% (since part are virtual cores, sometimes it is reported as 8%).

Bottom line: of the list of threads, there was one that was doing all the work, the rest was sitting idly by (I would assume the busy thread was not a background thread, because these should be independent of the rest, but I couldn't verify, they were all _CorExeMain).

I'm looking at the trace, and it's ... weird. I'm not sure if I can say anything at his point, but in the trace, literally nothing is showing as being allocated until 24 minutes into the trace.

Somehow this doesn't surprise me, as I was also looking live at the CLR traces (again: Process Explorer) and the allocations were very, very low for such a big application and all that CPU.

My gut told me there's a wait-loop somewhere and the thing it is waiting on gets released, but only very slowly. And this happens often. This could mean a (semi-) race-condition, a file on disk that is shared and not released properly, a memory mapped file, mutex etc etc.

Though I don't think it is caused by something in memory (well, not from the start). The behavior survived restarts of the computer, updates of Windows and basically over a week of doing all sorts of stuff. Only until I disabled (not removed) all extensions, the behavior changed (to 2-4 minutes). This behavior is reproducible with my current code and settings. The previous behavior isn't.

I've read online that there were some issues with Live Share. I am not using it, not even logged in, but the extension was enabled. Could the extreme delay been caused by waiting on network services or even a log-in that never happened and has to time out several times?

[KevinRansom]

@abelbraaksma , can you share some details of the project/solution that you have loaded. Does it have a lot of projects or is it a single project? Is it netsdk or dotnet framework project? Is it on github somewhere that we can load?

Thanks

Kevin

[abelbraaksma]

@KevinRansom, I can certainly share the project in confidence, or we can set up a remote call with shared screens if that helps (it is mostly closed source, but they won't be too fuzzy sharing it under conditions). The solution I tested this with and used for the trace has 11 projects. Since I had issues with performance in F# long before as well, I have split the "big solution" into a bunch of smaller ones, depending on what part I am working on. I rarely work on my all.sln, because it's too slow, generally anyway.

The main solution has 34 projects (not all of which are very significant).

I've estimated the LOC at some 150k lines, but depending on how you count you may find a different number.

All projects are (unf.) still legacy projects. There was something in the new project format that blocked me from changing (we tried), atm. I can't remember what that was. However, there aren't any really fancy things going on: each project is .NET Framework 4.6.1 (we build libraries and cannot update to latest all the time), each compiles to a library, three compile to an EXE. There is a handful of C# projects, but these are comparatively small.

There are two "heavy" projects: lots of source lines, quite a bit of SRTP-style inline (but again, nothing out of the ordinary, I think) and compiled binary size of all builds up to ~13MB Release Build (only counting DLLs, not counting test projects). Those 2 "heavy" projects are 5.5MB and 2.7MB resp. after compilation.

A clean build takes around 2-3 min (dep. on whether or not tests are included) on my system.

I think this all counts as "big" but not "huge" or "extreme". Another C# project I manage has 110 projects in the main solution, with 10 min clean build time.

[cartermp]

Well looky here:

26% of CPU time in the sample is spent checking if a file exists. Ooof.

I'm still not quite confidence in the trace data I'm looking at since there's such a massive gap of time before there's anything going on here. However, the data I'm looking at doesn't look abormal. So I'm not terribly surprised with what I'm seeing, especially if your codebase makes use of a lot of assembly references @abelbraaksma

[KevinRansom]

Does it use typeproviders? And I would really appreciate if you could remember what blocked the conversion, because we are no longer shipping legacy project format templates. They will still load and edit, but we don't really want new projects created using that format if we can avoid it.

[abelbraaksma]

but we don't really want new projects created using that format if we can avoid it.

I know. But this project has been in development for > 7 years, and has some MSBuild dependencies baked in. I'm sure it can all be converted eventually and we really should. But we spent a few days trying and gave up. It is not a trivial conversion (and so much even MS admits on the pages dedicated to moving over to the new format).

But there's a big upside with conversion that we certainly recognize: multi-targeting. Currently, that's a mess and we really want to target .NET Framework and .NET Core (reason: customers ask for it), which currently isn't easy to do.

Does it use typeproviders?

Nope, none. There are some quotations though (test prj with UnQuote).

[KevinRansom]

So ... perfectly straightforward medium sized solution ide goes super slow .... eek. Did you ever see this type of behaviour with our oss VisualFSharp solution ?

[cartermp]

@abelbraaksma Regarding in-memory cross-project references: when the number of projects held in the cache is only 3 (which is small) and there are a lot of project references, this can actually lead to more memory and CPU consumption over time since the IDE is constantly recomputing things u necessarily. I'd be curious about your experience if you turned it back on and then set the value to something high like 200.

[abelbraaksma]

26% of CPU time in the sample is spent checking if a file exists. Ooof.

@cartermp If so much time is spent there, and there's probably IO involved which doesn't show in the CPU trace, that can surmount together as "was virtually doing nothing" for a long time, right?

This suggests that it was looking for a file that wasn't there, was corrupted or otherwise time-consuming to retrieve. Since the whole performance changed dramatically after I changed the extensions (disable, re-enable), I doubt it is the extensions themselves that cause the strange performance, but what if (thinking out of the box) the MS extensions share a file with (binary) settings that in turn cause this file-checking to go so slow?

Btw, the full ist of assemblies include a bunch of System.XXX, FParsec, Netwonsoft, NodaTime, FSharp.Core. The majority being System, which is a lot of files, but only 3.3MB.

[abelbraaksma]

PS: since we're all online debating this, would it perhaps be more efficient to set up a call?

However, the data I'm looking at doesn't look abormal. So I'm not terribly surprised with what I'm seeing, especially if your codebase makes use of a lot of assembly references

@cartermp I don't understand this, because:

1. Editor used to show near-direct responsiveness when typing (this was different in 2015, but your efforts have really paid off and I am generally very, very happy with the improved performance). Some exceptions could be observed if editing the most-common reference, and then swapping to the least-common (i.e., the final exe). Other than that, performance has been really very good recently.
2. The whole project is not absurdly large (I think), and doesn't do any crazy stuff (afaik)
3. The total number of references is not that much for the project I profiled. Here's the list, the ones starting with Exselt are project-to-project references:
   
4. Nothing is anywhere near "normal", I think, when you needed to wait 10-20 minutes after each keystroke... Right? I'm not sure why the trace doesn't show it, do you have the full 35-or-so minutes?

Which begs the question, how can it spent so much CPU time in that method if there aren't that many files to load? Or: these files it tries to load have nothing to do with F# or my project? Some inner process going berserk? ;)

[KevinRansom]

@abelbraaksma phillip was referring to the trace .. your experience is actually scary.

[abelbraaksma]

ah, got it! 👍

Yep, it was scary indeed ;). So scary it got funny, and then scary again :P