Dart formatter Keeps running endlessly

Issue Type: Bug

It's random.
At times when you save dart code. Dart formatter starts running and do not stops for several minutes (around 5 minutes minimum). I have to cancel it and save again and same thing happens.
Only solution is restart VScode or sometimes restart the PC.

Extension version: 3.21.1
VS Code version: Code 1.55.1 (08a217c4d27a02a5bcde898fd7981bda5b49391b, 2021-04-07T15:06:02.360Z)
OS version: Windows_NT x64 10.0.19041

System Info

Item	Value
CPUs	Intel(R) Core(TM) i7-8550U CPU @ 1.80GHz (8 x 1992)
GPU Status	2d_canvas: enabled gpu_compositing: enabled multiple_raster_threads: enabled_on oop_rasterization: enabled opengl: enabled_on protected_video_decode: enabled rasterization: enabled skia_renderer: enabled_on video_decode: enabled vulkan: disabled_off webgl: enabled webgl2: enabled
Load (avg)	undefined
Memory (System)	7.89GB (1.46GB free)
Process Argv	--crash-reporter-id fd9ee2dd-443c-41b6-b90c-1cb615a784b2
Screen Reader	no
VM	0%

A/B Experiments

vsliv368:30146709
vsreu685:30147344
python383cf:30185419
vspor879:30202332
vspor708:30202333
vspor363:30204092
vstry244:30276681
pythonvsdeb440:30248342
pythonvsded773:30248341
pythonvspyt875:30259475
pythontb:30283811
openwsldoc:30282072
vspre833cf:30267465
pythonptprofiler:30281270
vshan820cf:30276953
pythondataviewer:30285071
vscus158:30286553

Can you confirm which Flutter SDK version you're on, and whether LSP is enabled (hover over the SDK version in the status bar to see whether it says "DAS" or "LSP").

I've seen this before (and a few others have noted it), although I've never been able to get a log file or repro it. If you're able to get a log when this occurs, that may be useful in tracking it down. Thanks!

FWIW - some performance improvements have landed in Flutter master recently that may impact this, though it's hard to be sure since I haven't been able to repro.

Recently the same issue did not come up. It used to happen when I used Alt + shift + f in VScode. Anytime soon I get the same Issue I will post the logs.

I may have a repro for this.

I'm using SDK:

Loc: /Users/danny/Dev/Dart SDKs/nightly-2021-04-06
Ver: 2.13.0-edge.fc349bdbb5f9c6d4680c11858459abcb96670227

I'm opening the SDK analysis_server + analyzer packages from the SDK at version e0bfa18c7c6 (using my usual .code-workspace) then opening lib/lsp_protocol/protocol_generated.dart and making any change and pressing Save.

The file is very large (35k lines) so it might not be the same issue seen on smaller files, but it's definitely way slower than I would expect - 22 seconds in this example (which produced 0 edits because the change was in a comment):

https://gist.github.com/DanTup/05e61e341998ab2c94aed3053899c997

# client request formatting (10:23:21.982)
1618478601982:Req:{"jsonrpc"::"2.0","id"::12,"method"::"textDocument/formatting","params"::{"textDocument"::{"uri"::"file::///Users/danny/Dev/Google/dart-sdk/sdk/pkg/analysis_server/lib/lsp_protocol/protocol_generated.dart"},"options"::{"tabSize"::2,"insertSpaces"::true,"insertFinalNewline"::true}}}

# formatting response (10:23:43.529 = 22 seconds)
1618478623529:Res:{"id"::12,"jsonrpc"::"2.0","result"::null}

@munificent

Looks like this time is actually spent in the formatting and not where I thought it might be (generating minimal edits). I'm not sure if this is expected performance though.

@munificent I'm not sure what the expected timings are for a large file like this - it's about 20 seconds for 35k lines. It's definitely a large file (and therefore may be unrelated to the original issue raised here), but I thought it worth checking. It's the same on stable 2.12.0 SDK (v1.3.11 of the formatter) and a recent nightly with v2.0.0 of the formatter.

Repo:

~/Dev/Dart\ SDKs/nightly-2021-04-06/bin/dart format --version
# 2.0.0

cd /tmp

curl https://raw.githubusercontent.com/dart-lang/sdk/fc349bdbb5f9c6d4680c11858459abcb96670227/pkg/analysis_server/lib/lsp_protocol/protocol_generated.dart > test.dart

~/Dev/Dart\ SDKs/nightly-2021-04-06/bin/dart format -o none test.dart
# Formatted 1 file (0 changed) in 20.71 seconds.

Edit: A comment at dart-lang/dart_style#864 (comment) suggests the whole Flutter repo could be formatted in around 10-12 seconds, so it does seem like this might not be expected.

Here's a CPU profile trace exported from DevTools:

https://gist.github.com/DanTup/567ebca5f20c3cd4c647dfdc6a3b56cf

Which looks like this:

Perhaps this 1903 character statement isn't helping (I'm now more convinced this is unrelated to the original issue - I don't think most people have code like this!):

final documentChanges = (json['documentChanges'] is List && (json['documentChanges'].every((item) => TextDocumentEdit.canParse(item, nullLspJsonReporter))))
        ? Either2<List<TextDocumentEdit>, List<Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>>>.t1(
            json['documentChanges']
                ?.map((item) =>
                    item != null ? TextDocumentEdit.fromJson(item) : null)
                ?.cast<TextDocumentEdit>()
                ?.toList())
        : ((json['documentChanges'] is List && (json['documentChanges'].every((item) => (TextDocumentEdit.canParse(item, nullLspJsonReporter) || CreateFile.canParse(item, nullLspJsonReporter) || RenameFile.canParse(item, nullLspJsonReporter) || DeleteFile.canParse(item, nullLspJsonReporter)))))
            ? Either2<List<TextDocumentEdit>, List<Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>>>.t2(json['documentChanges']
                ?.map((item) => TextDocumentEdit.canParse(item, nullLspJsonReporter)
                    ? Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>.t1(
                        item != null ? TextDocumentEdit.fromJson(item) : null)
                    : (CreateFile.canParse(item, nullLspJsonReporter)
                        ? Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>.t2(item != null ? CreateFile.fromJson(item) : null)
                        : (RenameFile.canParse(item, nullLspJsonReporter) ? Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>.t3(item != null ? RenameFile.fromJson(item) : null) : (DeleteFile.canParse(item, nullLspJsonReporter) ? Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>.t4(item != null ? DeleteFile.fromJson(item) : null) : (item == null ? null : (throw '''$item was not one of (TextDocumentEdit, CreateFile, RenameFile, DeleteFile)'''))))))
                ?.cast<Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>>()
                ?.toList())
            : (json['documentChanges'] == null ? null : (throw '''${json['documentChanges']} was not one of (List<TextDocumentEdit>, List<Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>>)''')));

@munificent

@munificent I'm not sure what the expected timings are for a large file like this - it's about 20 seconds for 35k lines.

Even very large files should be quite fast to format, but there are corner cases where a file that contains a large number of pathologically complex expressions can get pretty slow.

Perhaps this 1903 character statement isn't helping (I'm now more convinced this is unrelated to the original issue - I don't think most people have code like this!):

final documentChanges = (json['documentChanges'] is List && (json['documentChanges'].every((item) => TextDocumentEdit.canParse(item, nullLspJsonReporter))))
        ? Either2<List<TextDocumentEdit>, List<Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>>>.t1(
            json['documentChanges']
                ?.map((item) =>
                    item != null ? TextDocumentEdit.fromJson(item) : null)
                ?.cast<TextDocumentEdit>()
                ?.toList())
        : ((json['documentChanges'] is List && (json['documentChanges'].every((item) => (TextDocumentEdit.canParse(item, nullLspJsonReporter) || CreateFile.canParse(item, nullLspJsonReporter) || RenameFile.canParse(item, nullLspJsonReporter) || DeleteFile.canParse(item, nullLspJsonReporter)))))
            ? Either2<List<TextDocumentEdit>, List<Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>>>.t2(json['documentChanges']
                ?.map((item) => TextDocumentEdit.canParse(item, nullLspJsonReporter)
                    ? Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>.t1(
                        item != null ? TextDocumentEdit.fromJson(item) : null)
                    : (CreateFile.canParse(item, nullLspJsonReporter)
                        ? Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>.t2(item != null ? CreateFile.fromJson(item) : null)
                        : (RenameFile.canParse(item, nullLspJsonReporter) ? Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>.t3(item != null ? RenameFile.fromJson(item) : null) : (DeleteFile.canParse(item, nullLspJsonReporter) ? Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>.t4(item != null ? DeleteFile.fromJson(item) : null) : (item == null ? null : (throw '''$item was not one of (TextDocumentEdit, CreateFile, RenameFile, DeleteFile)'''))))))
                ?.cast<Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>>()
                ?.toList())
            : (json['documentChanges'] == null ? null : (throw '''${json['documentChanges']} was not one of (List<TextDocumentEdit>, List<Either4<TextDocumentEdit, CreateFile, RenameFile, DeleteFile>>)''')));

You wouldn't believe the things I've seen. That one is definitely pretty bad, but generated code often looks like this and dartfmt is supposed to handle it well.

@munificent

@munificent is it worth me filing an issue in dart_style about that? (do you think it's likely significant gains could be made?). I could also tweak this generated code (I'm generating it), although my concern was less about this specific file than whether there's a more general issue other users may also see.

If not, I wonder if the analysis server should offload this to another isolate, since it's currently synchronous in the main isolate that will block all other language server requests for the duration (@bwilkerson any thoughts?).

Although, I don't think either of those resolve the original issue here. I'm not sure it's just slow formatting, but suspect the server was busy with something else (perhaps rebuilding contexts it didn't need to - which hopefully is now fixed).

If we're sure that dart_style is causing the issue (and not something else in server), then it might well make sense to run dart_style asynchronously with a timeout. I'm not convinced that a separate isolate is the right choice because I think that would require parsing the AST again, but I don't have a strong opinion about it either.

If we're sure that dart_style is causing the issue (and not something else in server)

I'm not sure it's the cause of the original issue raised here - I think I just happened to see the same behaviour but it was caused by the big file. I don't expect many users have code like generated code above, but it would be nice not to improve the experience if they did.

it might well make sense to run dart_style asynchronously with a timeout. I'm not convinced that a separate isolate is the right choice because I think that would require parsing the AST again, but I don't have a strong opinion about it either.

If I understand correctly, I think it may be parsing currently anyway?

https://github.com/dart-lang/dart_style/blob/f17c23e0eea9a870601c19d904e2a9c1a7c81470/lib/src/dart_formatter.dart#L116-L121

Is it possible to run dart_style asynchronously? I thought it was all synchronous and CPU bound. If it can be run asynchronously (whether in an isolate or otherwise), I'd prefer to support cancellation than add a timeout (at least for LSP). Timeouts can be frustrating because in some cases users might want to wait for an operation to complete (because the result are more important than it being fast). As long as it's running asynchronously, for LSP we can receive cancellation requests from the client and could abort - that way the user is in control of whether they wait of cancel, rather than it being a fixed time (which could have different cut-offs in terms of file size/complexity based on how powerful the users machine is).

This is probably moot if Bob thinks this could be much faster (in which case I'll file a dart_style issue with the repro above), though otherwise I could file an SDK issue about handling this better and we can figure out the best way there.

I'll leave this issue open for now either way, as I think there's another issue - which may or may not be fixed by the context rebuild changes - that's causing people to see what looks like slow formatting but might not be.

If I understand correctly, I think it may be parsing currently anyway?

Yes, it looks that way. I'd assumed that we'd ask the AnalysisSession for the parsed AST and that it would most likely be cached because it would be a priority file. But that assumption appears to have been wrong.

Is it possible to run dart_style asynchronously?

Probably not.

... for LSP we can receive cancellation requests ...

The legacy protocol doesn't support that, so we might have to have a timeout there, or just let the client (IntelliJ) handle the timeout.

This issue has been marked stale because it is tagged awaiting-info for 20 days with no activity. Remove the stale label or comment to prevent the issue being closed in 10 days.

Having the same issues with the following -

Flutter 2.8.0 • channel stable • https://github.com/flutter/flutter.git
Framework • revision cf44000065 (6 days ago) • 2021-12-08 14:06:50 -0800
Engine • revision 40a99c5951
Tools • Dart 2.15.0

@temitopeog

@temitopeog can you reproduce it reliably? Is it with particular files? (If so, are you able to share one so that I can reproduce)?

Removing all package files from the project and deleting local VS Code files (package files etc.) and reinstalling them worked for me idk why.

I can't explain that either, but if you see this come back, please do file a new issue so we can do some digging. Thanks!

I am getting this issue alot. I need to use various flutter versions of flutter including 2.2.0. Restarting the window with cmd-R helps at lest temporarily.

My log file has no error messages:
!! PLEASE REVIEW THIS LOG FOR SENSITIVE INFORMATION BEFORE SHARING !!

Dart Code extension: 3.34.0
Flutter extension: 3.34.0 (activated)

App: Visual Studio Code
Version: 1.64.0
Platform: mac

Workspace type: Flutter
Analyzer type: LSP
Multi-root?: false

Dart SDK:
Loc: /Users/me/Development/Dev/fvmhome/versions/2.2.1/bin/cache/dart-sdk
Ver: 2.13.1
Flutter SDK:
Loc: /Users/me/Development/Dev/fvmhome/versions/2.2.1
Ver: 2.2.1

HTTP_PROXY: undefined
NO_PROXY: undefined

Logging Categories:
General, Analyzer, CommandProcesses, DartTest, DAP, VmService, DevTools, FlutterDaemon, FlutterRun, FlutterTest, WebDaemon

Fri Feb 04 2022 [14:23:27 GMT-0500 (Eastern Standard Time)] Log file started
Fri Feb 04 2022 [14:23:58 GMT-0500 (Eastern Standard Time)] Log file ended

@Cory-FanDemand

@Cory-FanDemand the log you included doesn't seem to have captured anything - did you start capturing before saving/formatting?

I see you're not on the latest version of Flutter (you have v2.2.1, the latest is v2.10). There have been many fixes to the LSP server since then - please try upgrading to the latest version and it may be that the problem goes away.

@DanTup

@DanTup Yes I did, next time it starts happening - if I'm on 2.10 at the time - I'll try to capture again.

@Cory-FanDemand

@Cory-FanDemand thanks - you ned to start capturing before the format request is sent (and ideally, leave it for until it completes). You can set logging to run all the time using settings on this page:

https://dartcode.org/docs/logging/#analyzer

Although the files can get quite large, so you should keep an eye on them.

FYI - the analysis server logs will contain parts of your source code, so they may need reviewing/redacting before sharing.

I was facing the same issue and noticed it would only happen when my internet connection was slow or down. For me, disabling analytics solved the problem:

dart --disable-analytics

@grlduarte

@grlduarte can you reliably reproduce this? (for example if you manually disconnect your internet, does it occur?)

There are some things I'm aware of where the server will try to connect to the internet (such as caching Pub package names to use in code completion) but I didn't think it was currently sending any analytics. I'm surprised that disabling analytics would fix formatting getting stuck. Has it been long since you disabled them? Is it possible it be intermittent and you've just been lucky since disabling it?

If you can reproduce the issue, I'd be interested in a new issue opening (here or in dart-lang/sdk and CCing me) so we can capture some logs and understand what's happening.

(@bwilkerson FYI)

@DanTup

@DanTup I have had this problem on and off for some time. Using Vim + Dart plugin I noticed every time my internet was down the editor would stuck on save.

Today I tried what you suggested and: TA-DA. Once the problem was isolated, I don't know what led me to it, but I disabled analytics and the problem was gone.

There's more, I didn't mention in the previous answer but every dart command gets stuck with analytics enabled and internet down, even dart --help.

Also worth mentioning that my SDK is pretty outdated (2.18.2).

I will open a new issue in dart-lang/sdk since this does not seems to be related to Dart Code

@grlduarte

@grlduarte

If this hang still occurs on the latest SDK, I would certainly file an issue in dart-lang/sdk about it. Analytics and no internet should defintely not prevent these commands from working.

If the dart language_server command is hanging, that could certainly also affect editor functionality - although I'd expect far more than formatting to not work, I would expect general editor functionality to suffer too. If you can reproduce issues where general editor functionality (like code completion) works and only formatting is broken in that case, I'd be interested in an additional issue opened here in the Dart-Code repo so we can get some logs to see what's happening there, since it could be a different issue. Thanks!

Navigation Menu

Repository navigation

Dart formatter Keeps running endlessly #3270

72 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Dart formatter Keeps running endlessly #3270

Description

Activity

DanTup commented on Apr 13, 2021

DanTup commented on Apr 13, 2021

dewbambs commented on Apr 15, 2021

DanTup commented on Apr 15, 2021

DanTup commented on Apr 15, 2021

munificent commented on Apr 20, 2021

DanTup commented on Apr 21, 2021

bwilkerson commented on Apr 21, 2021

DanTup commented on Apr 21, 2021

bwilkerson commented on Apr 21, 2021

72 remaining items

github-actions commented on Aug 10, 2021

temitopeog commented on Dec 14, 2021

DanTup commented on Dec 14, 2021

karascr commented on Jan 26, 2022

DanTup commented on Jan 27, 2022

Cory-FanDemand commented on Feb 4, 2022

DanTup commented on Feb 4, 2022

Cory-FanDemand commented on Feb 7, 2022

DanTup commented on Feb 7, 2022

grlduarte commented on Feb 14, 2023

DanTup commented on Feb 14, 2023

grlduarte commented on Feb 14, 2023

DanTup commented on Feb 14, 2023

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions