Dart formatter Keeps running endlessly

[dewbambs]

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

[DanTup]

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!

[DanTup]

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.

[dewbambs]

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.

[DanTup]

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}

[DanTup]

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.

[DanTup]

@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).

[bwilkerson]

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.

[DanTup]

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.