DetachVisualisationHandler request timeout

[xvcgreg]

Entering grouped nodes seems slow and renders errors. See the attached video and log.

[xvcgreg]

2302230824_DetachVisualisationHandler.request.timeout.mp4

2302230824_DetachVisualisationHandler request timeout.txt

[farmaazon]

@xvcgreg What do you mean by "renders errors."? Despite the errors in the log, I see on the screencast that nodes are displayed properly, and connections are properly colored.

[farmaazon]

I reproduced the detach visualization error. It's not easy, as it seemingly needs a big project to show.

The one reproduction scenario I find quite reliably is opening this project
Bookclub_Week_5.zip

And getting out of func1 (double-click on the background).

At this point, IDE is bombarding the engine with attach/detach visualization requests, as we see many new nodes now and each node want's to ask about its widgets.

[farmaazon]

The timeout seems to be a some internal engine timeout, not the IDE one:

{"jsonrpc":"2.0","id":28,"error":{"code":11,"message":"Request timeout"}}

We receive this message before the IDE timeout is reached.

[JaroslavTulach]

I am trying to reproduce the problem with Bookclub_Week_5.zip, but so far no luck. Can you reproduce it again and collect profiling data?

When I follow the engine profiling instructions and launch the project-manager as:

project-manager -vv --no-log-masking \
  --profiling-path collapse.npss \
  --profiling-events-log-path collapse.log \
  --profiling-time 60

I get following two files packaged into a single collapse.zip. Opening them in graalvm/bin/jvisualvm I can see that sendVisualizationUpdate is invoking Enso interpreter in "uncached" (e.g. slow) mode:

That is a problem. Also the findModuleByExpressionId seems to be slow. Reporting as:

• UpsertVisualizationJob slowed down by findModuleByExpressionId  #5781
• ExecutionService.execute is running in uncached (e.g. slow) mode #5782

Whether or not that is causing the "Request timeout" needs to be verified. Please generate your profiling data with "Request timeout" message included.

[farmaazon]

I tried to reproduce it on newest nightly (2023-03-01), and I failed. Something was speeded up in the meanwhile. Good job!

I have found a new scenario, however: I opened the COVID project and there was many timeouts on startup (but this may be another issue), causing initial visualizations to close. Also, I got one request timeout when stepping in and out of a collapsed node.

Here are profiler logs, project manager console logs (stdout and stderr combined) and the project where I reproduced the issue.

Colorado_COVID_and_pm_profiling.zip

[hubertp]

I tried to reproduce it on newest nightly (2023-03-01), and I failed. Something was speeded up in the meanwhile. Good job!

I have found a new scenario, however: I opened the COVID project and there was many timeouts on startup (but this may be another issue), causing initial visualizations to close. Also, I got one request timeout when stepping in and out of a collapsed node.

Here are profiler logs, project manager console logs (stdout and stderr combined) and the project where I reproduced the issue.

I had a look at the logs and the logs on startup are actually fine. The connection exceptions listed there are part of a normal workflow where we wait for Language Server to standup.

Ditto about timeouts to AttachVisualization. I would suggest to file a separate ticket and I will investigate more.
Apologies for not looking into it earlier. It somehow not landed on my radar.

We've made a ton of improvements since, so I wouldn't be surprised if the original issue is resolved.

[hubertp]

I think it's possible the AttachVisualization jobs that did timeout are possible duplicates. When we receive requests for such jobs that are supposed to be unique, the previous ones get cancelled. And I think I'm seeing that in the logs.
We could probably improve the logs to avoid unnecessary reports.

[JaroslavTulach]

We've made a ton of improvements since, so I wouldn't be surprised if the original issue is resolved.

Yes, that's my expectation as well. Now when #5781 and #5782 are integrated, we can close this issue.

[hubertp]

Confirmed with @4e6 regarding spurious Request Timeout errors. Filed #5985