Investigate reasons for Request timeouts during AttachVisualizationHandler

[hubertp]

#6724 (comment) lists that Request timeouts happen frequently under heavy workload. Increasing timeouts (as in #6972) is unlikely to fix the underlying problem.

A request for attaching visualization should be handled rather swiftly (compared to sending data for the visualization).

[hubertp]

One thing which stands out when I'm reading the code is why are we requesting writeCompilation lock for that job. This will contend with for example compilation job which can certainly take a lot of time.

[JaroslavTulach]

Having a job that, as a first operation, tries to obtain a compiler lock, is a sign of poor design. If the lock isn't available, the job shall not be scheduled at all. Jobs that require some information from compiler or need the compiler to be idle are so common, that they need support in the infrastructure. It shouldn't be the job that requires the lock - the infrastructure shall realize that compilation is over and invoke the job at that moment.

NetBeans editing infrastructure has an intricate system of "phases". Jobs register for individual phases and get invoked when such (compiler) phase is finished. For example identifying local variables happens sooner than resolving and binding imports.

Regardless of the infrastructure we select, the more lock free code of regular tasks is, the better. Locks belong to the infrastructure.

[enso-bot]

Hubert Plociniczak reports a new STANDUP for yesterday (2023-06-12):

Progress: Investigating timeouts for visualizations. Having trouble with reproduction as the problem does not happen reliably. Adding more logs to find out the source of the delay. It should be finished by 2023-06-14.

Next Day: Next day I will be working on the #7005 task. Continue investigation.

[hubertp]

I can confirm that acquisition of locks in

• ModifyVisualisationCmd
• AttachVisualisationCmd
• UpsertVisualisationJob

is the real reason for the delays in handling those requests, ending up eventually as timeouts.

[hubertp]

Another insight: it seems we can also easily experience thread starvation in our JobExecutionEngine.
E.g.
A request comes from IDE for executionContext/attachVisualisation. It is handled by the handlers and eventually lands in AttachVisualisationCmd as executed by CommandExecutionEngine. The latter is executed and submits UpsertVisualisationJob. But the job is only started 5 seconds(!) later and this is the job that produces a response for the IDE. Hence the timeout in handler.

[hubertp]

Another insight: it seems we can also easily experience thread starvation in our JobExecutionEngine.

And just to add more info. On startup, at some point we can have 60+ threads in the command pool and have only 1 thread in job pool:

That can certainly lead to some bottleneck.

[JaroslavTulach]

FYI: Mutex - my implementation of read/write lock with "post-when unlocked" methods. Probably more flexible than our current Locking , but still my preferred architectural solution is to hide all locks.

[JaroslavTulach]

Another insight: it seems we can also easily experience thread starvation in our JobExecutionEngine.

And just to add more info. On startup, at some point we can have 60+ threads in the command pool and have only 1

Having 60 threads that exclude each other by synchronizing on a lock is a sign of a poor design.

[hubertp]

Another insight: it seems we can also easily experience thread starvation in our JobExecutionEngine.

And just to add more info. On startup, at some point we can have 60+ threads in the command pool and have only 1

Having 60 threads that exclude each other by synchronizing on a lock is a sign of a poor design.

Command pool is (almost) unlimited while job pool apparently defaults to 1. So in the case of sudden bursts of visualization requests, we run a ton of command handlers which can submit various jobs that are then queued until resources are available.

Won't comment on the design as I wasn't the one who did it and there might have been different requirements 3 years ago.

[enso-bot]

Hubert Plociniczak reports a new STANDUP for yesterday (2023-06-13):

Progress: There are 2 problems leading to request timeouts. 1) Lock contention between commands and jobs 2) Thread starvation for job executor. We can have tens of commands submitted, most of them handled relatively quickly but they are submitting further jobs. Then we end up with a single executor for the jobs, which is the real bottleneck and the source of the problem. Will need figure how to improve the current status quo, hopefully without rewriting all that logic. It should be finished by 2023-06-14.

Next Day: Next day I will be working on the #7005 task. Figure out changes to improve the design.

[hubertp]

Note that "job parallelism" is adapted during bootstrapping to read the number of available processors. That code should just work except when I actually log the value that is retrieved I get 1(!). The availableProcessors() method seems to be rather sensitive to the current state of OS, so probably a poor choice.

Edit: I was wrong, Runtime.getRuntime().availableProcessors() returns the desired value. It's the value that ends up in the context's options appears to be wrong and always 1. This is a problem somehow option descriptors.

[enso-bot]

Hubert Plociniczak reports a new STANDUP for yesterday (2023-06-14):

Progress: Been debugging our usage of Truffle's OptionDescriptors and came to the conclusion that our job processing never had more than 1 thread in the created threadpool. Once I fixed that, contention for locks became more visible. Considering sending replies earlier to avoid request timeouts. Needs more debugging. It should be finished by 2023-06-14.

Next Day: Next day I will be working on the #7005 task. Continue perf improvements and reducing lock contention.

[enso-bot]

Hubert Plociniczak reports a new 🔴 DELAY for yesterday (2023-06-15):

Summary: There is 2 days delay in implementation of the Investigate reasons for Request timeouts during AttachVisualizationHandler (#7005) task.
It will cause 0 days delay for the delivery of this weekly plan.

Delay Cause: Discovered some serious flaws in the existing design of job execution that needed to be addressed.

[enso-bot]

Hubert Plociniczak reports a new STANDUP for yesterday (2023-06-15):

Progress: Continue my investigation with speeding up execution/preventing timeouts. Sending replies to IDE from commands (rather than jobs triggered by them) both, improved and deteroriated the situation. We could have a request to modify the visualization before it was fully attached. Had to figure how to detect in-progress visualizations and add the additional checks. Created draft PR in which no request timeouts happen to me. It should be finished by 2023-06-16.

Next Day: Next day I will be working on the #7005 task. Cleanup up the PR, address review, more testing.

[enso-bot]

Hubert Plociniczak reports a new STANDUP for the provided date (2023-06-16):

Progress: Cleaned up the PR, more testing and (eventually) merged it. Rebased #6774 (for #6875) but realized that it is probably not an issue. Looking at our logging service and thinking if we can simplify it with plain log4j loggers. Started looking at adding retries to GraalVM updater. It should be finished by 2023-06-16.

Next Day: Next day I will be working on the #6880 task. Continue with adding retries to the updater.