Identify the reason of slow workspace startup

[skabashnyuk]

Is your task related to a problem? Please describe.

If multiple users would like to start workspaces at the same time, for example, after some announcement, we can observe that some workspaces started very slowly.

Describe the solution you'd like

Identify a bottleneck, propose solution/create and issue to remove them.

Describe alternatives you've considered

n/a

Additional context

n/a

[skabashnyuk]

WorkspaceSharedPool

One of the reason, that affects UX during workspace start is the configuration of WorkspaceSharedPool. Now by default, it's connected to https://github.com/eclipse/che/blob/eb66fee86ffeaa87ce27465edda32845374102c2/wsmaster/che-core-api-workspace/src/main/java/org/eclipse/che/api/workspace/server/WorkspaceSharedPool.java#L67 that is visible for java process.


In these diagrams, it is seen that the pool is configured with two threads which are not enough to handle a massive load. Since Che6 workspace start took about 10-15sec and che7 40-50 or more - the configuration of this pool becomes even more critical.

WaitMachinesStart

That metric should not be related to WorkspaceSharedPool. Since the start is already in progress. It means that doStartMachine aka the start of Pods and PodTemplateSpec are already initiated in https://github.com/eclipse/che/blob/eb66fee86ffeaa87ce27465edda32845374102c2/infrastructures/kubernetes/src/main/java/org/eclipse/che/workspace/infrastructure/kubernetes/KubernetesInternalRuntime.java#L661 and we just waiting for them to start. Due to the lack of traces/logs/metrics, there is nothing that I can say more. That can be a natural process or not a bug or regression in case if the user adds some customization that is long/impossible to deploy.

doStartMachine

The metric by itself doesn't contain any suspicion parts. Usually, it completes less than a second.
https://github.com/eclipse/che/blob/eb66fee86ffeaa87ce27465edda32845374102c2/infrastructures/kubernetes/src/main/java/org/eclipse/che/workspace/infrastructure/kubernetes/KubernetesInternalRuntime.java#L661-L685 I have nothing that can explain 60-sec spikes of this operation execution. Potential suspect OkHttpClient from KubernetesClientFactory https://github.com/eclipse/che/blob/eb66fee86ffeaa87ce27465edda32845374102c2/infrastructures/kubernetes/src/main/java/org/eclipse/che/workspace/infrastructure/kubernetes/KubernetesClientFactory.java#L65-L74

Action items

• Increase che.workspace.pool.exact_size to 30. Add monitoring to track the state Monitoring & Tracing capability for multiple Thread pools of Che Server #14601 Extend the size of the pool that is handling workspace related operations #14884
• Track/monitor/log workspace pod events.
  
• Track/monitor/log broker pod events.
• Track/monitor/log mkdir pod events.
• Add monitoring to OkHttpClient. In theory, we can track K8S api call. It could happen that k8s api is not stable/should be handled differently in some cases.
• More granular tracking of doStartMachine operation
• Add stackid in tracer in cases where it's possible
• In case of failed start(not canceled bu user) add as much as possible information to the logs that help admins to identify the reason for the failed start.