Improve trace diagnostics for compiler service #3061
Merged
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Contributor
Author
|
For example, this is the trace output for one character input ("space") in a small file with a couple of errors. |
Contributor
Author
|
Original comment: There are a few interesting things there like brace matching... where I wouldn't have expected these things to appear when pressing "space". Actually I investigated that and it was driver error - the "CacheMiss" was driver error. |
Contributor
Author
|
@vasily-kirichenko - From I'm pretty happy with what I'm seeing above - It's now much clearer that each diagnostic service is making one request and that things are progressing fast. |
Contributor
Author
|
Here's the trace on a QuickInfo mouse geture - all looks OK |
Contributor
Author
|
Here's the trace for typing a line of text, for those interested :) |
Contributor
Author
|
@vasily-kirichenko The above trace was generated from fairly rapid typing. I have to say that seeing multiple The above trace was also generated with a So looking at this I do recommend putting the |
Contributor
|
This looks really useful 👍 Do you plan on adding the sleep into the low-priority diagnostics? I think that would be a great help to perf - I'd maybe make it even longer. |
Contributor
Author
|
@saul Knowing causality is a useful thing :) Especially in a system full of "async"! |
Contributor
Author
|
Here's a trace of some quick typing once the three "Async.Sleep 500/1000" are in place for the lower-priority analyzers. Note that now none of these analyzers appear active at the start of the trace, and instead we only see CompletionProvider and BraceMatching. DiagnosticsAnalyzer then also kicks in, then the other lower priority one
|
Contributor
|
It may be worth only showing things that take >16ms? Or something around that? A frame on a 60Hz monitor is 16ms... there's too much noise in the log - seeing that something takes 1.3ms adds no value other than showing that it's fast. |
saul
reviewed
May 16, 2017
src/fsharp/vs/service.fs
Outdated
| member bc.MatchBraces(filename:string, source, options)= | ||
| reactor.EnqueueAndAwaitOpAsync("MatchBraces " + filename, fun ctok -> | ||
| member bc.MatchBraces(filename:string, source, options, userOpName) = | ||
| reactor.EnqueueAndAwaitOpAsync(userOpName, "MatchBraces ", filename, fun ctok -> |
Contributor
Author
|
@saul I added this to allow us to grep for long pauses (see end of long line) |
Contributor
|
Thanks for cleaning up so much code :) |
Contributor
|
@dsyme yeah that looks better - I'd maybe re-order some of the things we're formatting so that more important information is at the start of the line. Such as remaining queue length at the start (e.g., |
Contributor
Author
|
@saul @vasily-kirichenko Somewhat orthogonally I'd request your consideration of this: Basically FCS has a feature where you can have it check a max-memory condition (for the whole process) and have it automatically shrink all the FCS caches if the condition is reached. It does this once, and never tries again, the idea is basically to hold fewer project-builds strongly, We added this feature when fighting memory issues with VFPT, but never had proof that it was really effective. Now that we've got more of a grip on memory and tracing I wonder if we should consider activating this. Anyway, think it over - I don't want to add anything too complex - equally I'm aware that when devenv.exe gets above around 2.3GB it's just very difficult to use. |
Contributor
It's OK (for me) if such "advanced" (read: slow) analyzers are delayed longer than more important stuff like colorization or completion. |
Contributor
|
Yeah @dsyme I noticed that in the diff and saw it commented out - considering VS is a 32-bit process and we're doing all of this in memory, I don't think it's a bad idea and it could be helpful. However why does it only do this once and never again? It could be useful to allow repeated cache cleardowns, but only every n minutes (where n is quite high, say 20/30 minutes). We need some proper metrics on memory usage before we do that though. |
Contributor
|
@dsyme As far as I remember, I was testing this feature and it did release some memory, but it strangely did not help much with VFPT usability and I had to restart VS very soon anyway. So I quite pessimistic about re-enabling it again. |
Contributor
It does not clear the caches, it shrinks their sizes to 1. |
Contributor
Author
Yeah, I remember. At the time we tried it I think we were still fighting a long build-up of items int he operations queue, and so nothing was going to help us until we fixed that. Maybe now is the time to think about it again (perhaps with a different set of rules for when/how it is activated) |
Contributor
Author
OK, I suggest these delays:
|
Contributor
|
|
Contributor
I agree :) |
Contributor
Author
fixed, thanks |
Contributor
|
I tried to type code in the exp instance to which a debugger is attached. It's still impossible. I've no idea why attaching the debugger makes so huge difference. |
Contributor
Author
|
@vasily-kirichenko I'm only launching "Release" mode (Configuration Release, Start Debugging). That is fast for me |
Contributor
|
Hmm. I believed you cannot debug anything if it's built in release configuration... |
Contributor
Author
|
Here is a trace from the startup of VisualFSharp.sln until the point that semantic coloriation appears in the first file in FSharp.Compiler project https://gist.github.com/dsyme/e3e9f7e9159bfe68c5f92f9d956aa43f |
Contributor
|
It took ~7 seconds to update error squiggles on a tiny file :(
|
Contributor
|
Ah, you seem to not touch DocumentDiagnosticAnalyzer in this PR, so it's Roslyn :( |
Contributor
|
It's really unhealthy. |
Contributor
Author
Right. Though it's pretty fast for me on my machine (about 2-3 sec) |
Contributor
|
Interesting. I have a pretty fast machine (i7-4790K). It's strange. |
Contributor
|
However, these artificial delays... They are not any different than the Roslyn ones, which we are trying to mitigate by asking Roslyn team to provide options to tweak them. What was the initial cause of this PR? Did typing was slow and now it's faster? Anything else has been improved? I'm just trying to avoid the situation when VS feels "slow" and "sluggish" consuming very little CPU. VS is already slow (thanks Roslyn and VS itself) and making it feel even slower isn't the way to go I think. I was working in VS 2015 at work all the day after a two weeks vocation and it feels much, much faster: tooltips popped up instantly, symbols highlighted instantly, red squiggles appeared almost instantly... VS 2017 feels as a significant regression and we should not make things even worse. Everything should work as fast as the user's machine allow, not slower. |
Contributor
Author
|
@vasily-kirichenko Using a Roslyn mechanism would be my preference. But I would still propose to tune it roughly as in the PR https://github.com/Microsoft/visualfsharp/pull/3061/files#diff-338b77df6ee1ebc28d8ec242e98d6234R11 I thought a lot about your comment - you make good points. The thing it really made me think about was this: I can see the value in zero here, and I have changed to that. There are likewise no delays on
They all follow your rule - "as the user's machine allow". The purpose of the PR is really to make these (and typing) go faster - i.e. to prioritize those over "unused declarations", "unused opens" and "simplify names". on the assumption that FCS queue contention happens (and there is surely at least minor contention on the FCS queue, as I think the logs show). But the main purpose of the PR is really the logging. TBH I can already see some other major problems - I saw one example (starting VisuaLFSharp.sln where a single file from FSharp.Editor is showing by default) where a single step of the background processor took 30 seconds, which is a long pause without intellisense. So I'm happy with the PR and think we should put it in - but
|
saul
reviewed
May 16, 2017
src/fsharp/vs/Reactor.fs
Outdated
| //if span.TotalMilliseconds > 100.0 then | ||
| let taken = span.TotalMilliseconds | ||
| Trace.TraceInformation("Reactor: <-- {0}.{1}, took {2} ms {3}", userOpName, opName, span.TotalMilliseconds, (if taken > 10000.0 then "CATASTROPHIC" elif taken > 3000.0 then "AGONIZING" elif taken > 1000.0 then "SLOW" elif taken > 500.0 then "SPLUTTER" else "")) | ||
| let msg = (if taken > 10000.0 then "BAD-OP: >10s " elif taken > 3000.0 then "BAD-OP: >3s " elif taken > 1000.0 then "BAD-OP: SLOW > 1s" elif taken > 500.0 then "BAD-OP: >0.5s" else "") |
Contributor
There was a problem hiding this comment.
Inconsistent trailing whitespace in these strings
saul
reviewed
May 16, 2017
|
|
||
| module DefaultTuning = | ||
| let SemanticColorizationInitialDelay = 500 (* milliseconds *) | ||
| let SemanticColorizationInitialDelay = 0 (* milliseconds *) |
Contributor
There was a problem hiding this comment.
Instead of having comments here we could just suffix the value with Msecs? Just a minor style point
This was referenced May 16, 2017
Merged
nosami
pushed a commit
to xamarin/visualfsharp
that referenced
this pull request
Jan 26, 2022
* cleanup * cleanup * diagnostics * cleanup diagnostics * even cleaner diagnostics * cleanup diagnostics * default tuning * adjust tuning, more logging * add test, fix whitespace
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
4 participants
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
This shows more useful information in the trace window by pushing a "user operation name" (userOpName) string down to each FCS operation. This lets us see what IDE-level feature FCS operations are associated with.