dart-lang / sdk

The Dart SDK, including the VM, JS and Wasm compilers, analysis, core libraries, and more.
https://dart.dev
BSD 3-Clause "New" or "Revised" License
10.23k stars 1.57k forks source link

Analysis server sends Analyzing=true frequently during flutter builds #31564

Open DanTup opened 6 years ago

DanTup commented 6 years ago

In Dart Code we show "Analyzing..." in the status bar whenever the analysis server says it's analyzing. I noticed it flickers a lot during Flutter builds, even though (at least as far as the user is concerned) nothing is changing.

Would it simple/reasonable to avoid sending these when modifications on disk are unrelated?

Here's an example snippet from the instrumentation log:

1512584383484:Watch:/Users/danny/Dev/Testing/flutter_gallery:/Users/danny/Dev/Testing/flutter_gallery/build/ios/iphonesimulator/Runner.app/Frameworks/Flutter.framework/Info.plist:modify
1512584383484:Watch:/Users/danny/Dev/Testing/flutter_gallery:/Users/danny/Dev/Testing/flutter_gallery/build/ios/iphonesimulator/Runner.app/Frameworks/App.framework/_CodeSignature/CodeResources:modify
1512584383485:Watch:/Users/danny/Dev/Testing/flutter_gallery:/Users/danny/Dev/Testing/flutter_gallery/build/ios/iphonesimulator/Runner.app/Frameworks/App.framework/App:modify
1512584383485:Watch:/Users/danny/Dev/Testing/flutter_gallery:/Users/danny/Dev/Testing/flutter_gallery/build/ios/iphonesimulator/Runner.app/Frameworks/App.framework/Info.plist:modify
1512584383485:Watch:/Users/danny/Dev/Testing/flutter_gallery:/Users/danny/Dev/Testing/flutter_gallery/build/ios/iphonesimulator/Runner.app/Frameworks/url_launcher.framework/_CodeSignature/CodeResources:modify
1512584383485:Watch:/Users/danny/Dev/Testing/flutter_gallery:/Users/danny/Dev/Testing/flutter_gallery/build/ios/iphonesimulator/Runner.app/Frameworks/url_launcher.framework/url_launcher:modify
1512584383485:Watch:/Users/danny/Dev/Testing/flutter_gallery:/Users/danny/Dev/Testing/flutter_gallery/build/ios/iphonesimulator/Runner.app/Frameworks/url_launcher.framework/Info.plist:modify
1512584383489:Noti:{"event"::"server.status","params"::{"analysis"::{"isAnalyzing"::false}}}
1512584383581:Watch:/Users/danny/Dev/Testing/flutter_gallery:/Users/danny/Dev/Testing/flutter_gallery/build/ios/iphonesimulator/Runner.app/AppIcon20x20~ipad.png:modify
1512584383581:Watch:/Users/danny/Dev/Testing/flutter_gallery:/Users/danny/Dev/Testing/flutter_gallery/build/ios/iphonesimulator/Runner.app/AppIcon20x20@2x~ipad.png:modify
1512584383582:Noti:{"event"::"server.status","params"::{"analysis"::{"isAnalyzing"::true}}}
1512584383582:Watch:/Users/danny/Dev/Testing/flutter_gallery:/Users/danny/Dev/Testing/flutter_gallery/build/ios/iphonesimulator/Runner.app/Info.plist:modify
1512584383582:Watch:/Users/danny/Dev/Testing/flutter_gallery:/Users/danny/Dev/Testing/flutter_gallery/build/ios/iphonesimulator/Runner.app/PkgInfo:modify
1512584383582:Watch:/Users/danny/Dev/Testing/flutter_gallery:/Users/danny/Dev/Testing/flutter_gallery/build/ios/iphonesimulator/Runner.app/AppIcon76x76~ipad.png:modify
1512584383584:Noti:{"event"::"server.status","params"::{"analysis"::{"isAnalyzing"::false}}}

I don't know if the files listed here are what triggered it, or whether it was before this (the log is quite long) but lmk if you need more info I can dig further.

(cc @bwilkerson)

devoncarew commented 6 years ago

I believe we de-bounce the notifications a bit in IntelliJ - which is why we don't see this - but it seems reasonable to not send notifications until we hit a file which might need analysis.

DanTup commented 6 years ago

Now you mention it, Dart Code does the same so not sure why I'm seeing this. I'll do some digging.

I think it'll still be good to filter these out (stuff improved in the analyzer avoids work by all clients) but if there's just something wrong with our debounce code it should be easily fixable in Dart Code.

DanTup commented 6 years ago

Ok, here's why I still see it:

[20:07:35.350]: <== {"event":"server.status","params":{"analysis":{"isAnalyzing":false}}}
[20:07:41.857]: <== {"event":"analysis.flushResults","params":{"files":["/Users/danny/Dev/Google/flutter/examples/stocks/build/flx/LICENSE"]}}
[20:07:41.857]: <== {"event":"analysis.flushResults","params":{"files":["/Users/danny/Dev/Google/flutter/examples/stocks/build/flx/AssetManifest.json"]}}
[20:07:41.858]: <== {"event":"server.status","params":{"analysis":{"isAnalyzing":true}}}
[20:07:42.409]: <== {"event":"analysis.flushResults","params":{"files":["/Users/danny/Dev/Google/flutter/examples/stocks/build/flx/FontManifest.json"]}}
[20:07:42.409]: <== {"event":"analysis.flushResults","params":{"files":["/Users/danny/Dev/Google/flutter/examples/stocks/build/flx/fonts/MaterialIcons-Regular.ttf"]}}
[20:07:43.531]: <== {"event":"server.status","params":{"analysis":{"isAnalyzing":false}}}

The timestamps on the last true/false are [20:07:41.858] and [20:07:43.531]. We're only debouncing at 250ms so this (almost two seconds) still causes the flicker.

I'm running this on my MacBook. It might not be the most powerful dev machine but this probably also isn't the biggest Flutter app I'm building (Stocks example). I might increase the timeout to 500ms-1s (I don't think below that it's particularly useful to the user) but obviously it'll still occur a little (for me on this machine, at least).

Still, I don't consider this hugely important; it's just a minor annoyance (mainly because when we're building Flutter apps there is other text in the status bar, and the two labels together look wonky!). If it bugs me enough, I'll see if I can easily suppress the analyzing ones while the other is visible (or, if this change isn't difficult and you can point me in the right direction, I can take a stab).

devoncarew commented 6 years ago

Yeah, likely some work on our side. I think we shouldn't be sending analysis.flushResults notifications for files we haven't previously sent notifications for, and we likely should send notifications for files we're never going to analyze (like ttf files).

DanTup commented 6 years ago

@bwilkerson @devoncarew Is this something I could easily do? It bugs me that our status bar shows two things during build (Analyzing... and the build progress) but fixing on my side will be a kludge!

bwilkerson commented 6 years ago

Sorry for the delay in responding.

The instrumentation log doesn't explain why server is switching state to analyzing and back. It should be ignoring watch events for anything other than .dart or .yaml files, and I don't see those in the log.

Not knowing what's causing this, I don't know how easy it will be for anyone to fix. I suppose I would probably start by writing a test to try to reproduce the behavior. Without a way to reproduce it it will probably be fairly difficult to fix.

DanTup commented 6 years ago

I think I found two causes!

In Driver there's a driver.hasFilesToAnalyze that checks _fileTracker.hasChangedFiles which checks a hashset it's keeping of files. That hashset contains files we don't want to analyze. Here's a stack of where they're added:

Adding file m:\Coding\Applications\flutter\examples\flutter_gallery\ios\Runner\GeneratedPluginRegistrant.m to changed files
#0      FileTracker.changeFile (package:analyzer/src/dart/analysis/file_tracker.dart:169:39)
#1      AnalysisDriver._changeFile (package:analyzer/src/dart/analysis/driver.dart:1119:18)
#2      AnalysisDriver.changeFile (package:analyzer/src/dart/analysis/driver.dart:567:5)
#3      ContextManagerImpl._handleWatchEventImpl (package:analysis_server/src/context_manager.dart:1479:18)
#4      ContextManagerImpl._handleWatchEvent (package:analysis_server/src/context_manager.dart:1356:5)
#5      _rootRunUnary (dart:async/zone.dart:1134)

Looking inside _handleWatchEventImpl in context_manager.dart there is some code handling adds that looks like:

if (resource is File) {
  File file = resource;
  if (_shouldFileBeAnalyzed(file)) {
    info.analysisDriver.addFile(path);
  }
}

Note the call to _shouldFileBeAnalyzed. However the code for modify is just:

case ChangeType.MODIFY:
  for (AnalysisDriver driver in driverMap.values) {
    driver.changeFile(path);
  }
  break;

So, I think cause 1 is that we're not checking files should be analyzed if they're modified. I think a fix would be wrapped the loop with:

Resource resource = resourceProvider.getResource(path);
if (resource is File) {
  File file = resource;
  if (_shouldFileBeAnalyzed(file)) {

(Note: as well as adding _shouldFileBeAnalyzed here, this is also adding a file check which doesn't exist before - I don't know if that's correct).

So, I changed that locally anyway and I still saw the issue (though on a smaller scale). So, I added some more logging and found:

+++ Analyzing.
    Adding file m:\Coding\Applications\flutter\examples\flutter_gallery\build\app\intermediates\assets\debug\flutter_assets\lib\gallery\example_code.dart to changed files
--- Analyzing in 740 ms.

So in this case, it is a dart file which is deployed as part of the build (it's the flutter gallery app which ships example code in a dart file into the app to show the user how things were achieved):

flutter:
  assets:
    - lib/gallery/example_code.dart

So, I'm not sure how that one can be fixed without some sort of assumption about the build folder.

@bwilkerson If the above to the file modification watching looks good, lmk and I'll submit a review for it. The second issue I'm not sure what you want to do - it's a complete fluke I happened to test with a project that has .dart files in its output. The impact here is much less (this is very unlikely), though I don't know if it's a waste of resources (or may result in sending errors to the editor) that we don't want.

bwilkerson commented 6 years ago

The file modification looks good to me. Please add scheglov@ to the review; he's more familiar with this code than I am.

As for the other, I don't want to have an assumption about the build directory, but if it's a standard output location for Flutter apps, then it seems like we ought to handle it automatically. Is it always named build, or is it configurable?

(A short term work around would be for users to explicitly ignore the directory in the analysis options file.)

devoncarew commented 6 years ago

It is the standard output location for flutter; it's not configurable. I'm not sure how I feel about hardcoding knowledge about build/ either, but will note that it's also the output location that pub build uses.

bwilkerson commented 6 years ago

I suppose for Flutter, we could add an "excludes" list that contains build (to the analysis options file) when generating a new project, but that will only help people that use flutter to create new projects. It won't help other Flutter uses, nor pub build users.

But if we hardcode the handling of build and have users that have non-generated code in build, then we'd stop analyzing it, with no way for them to work around it. And a unlikely as those conditions seem, we thought the same thing about users having a directory named packages and we saw that happen.

DanTup commented 6 years ago

The file modification looks good to me

Cool; I'll try and put a failing test in first so this is covered. I can see a somewhat related test test_watch_modifyFile which is marked TODO without an assert so I'll see if I can make that work and then copy/adapt for this.

And a unlikely as those conditions seem, we thought the same thing about users having a directory named packages and we saw that happen.

Yeah, let's at least fix that one before we replace it with another :D

I have no strong opinion on this; I'm not concerned about it for the original issue (few people will have Dart files in their Flutter build output) but I don't know of other implications of it analysing build output, you two are much better positioned to decide than I. (Though I reserve the right to become upset about it if/when we one day have pub build in Dart Code ;-))

devoncarew commented 6 years ago

But if we hardcode the handling of build and have users that have non-generated code in build

Flutter does manage the build/ dir, and will delete content out of it (and, flutter clean will delete it completely). So, the problem of non-generated code in build will self-correct periodically :)

bwilkerson commented 6 years ago

Minor edit:

So, the problem of non-generated code in {the build directory of a flutter package} will self-correct periodically.

If we can identify which packages are Flutter packages (such as by looking for a dependency on flutter), then we could use that to solve one part of the issue.

Is there a similar technique we can use to identify a package that is using pub build?

devoncarew commented 6 years ago

Not sure re: auto-detection, however, some options I can think of to address reacting to changes in the build/ folder:

DanTup commented 6 years ago

I've fixed the issue with non-Dart files trigger this in https://dart-review.googlesource.com/c/sdk/+/44421/

Do you want this case keeping open (or perhaps another creating?) for the build output folders?