[server] Investigate server event loop lag

[geropl]

We see an accumulating node.js event loop lag increase:
This is bad, because it is a min. (!!!) static addition to every API call.

(Source: Grafana)

[geropl]

/schedule

[roboquat]

@geropl: Cannot schedule issue - issue does not belong to a team. Use /team to specify one.

In response to this:

/schedule

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[geropl]

/schedule

[roboquat]

@geropl: Issue scheduled in the meta team (WIP: 0)

In response to this:

/schedule

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[geropl]

/assign

[geropl]

Not fixed yet.

[geropl]

Taking CPU profiles reveals some candidates for improvements, but nothing explaining the accumulating lag, yet:

• HostContextProviderImpl (38ms): setTimeout(..., 2000) does O(n²) sync work rather often (source). Also, uses encrypted columns, which is expensive
• strategy.pass (7.7ms): two calls here, sees to be too expensive
• guessGitTokenScopes
• CodeSyncService fetch
• spawning oci-tool (40ms)
• prometheus metrics (17ms)

[AlexTugarev]

@geropl, happy to discuss findings and provide any details on the first two.

[JanKoehnlein]

Let's not close this before the lag has disappeared.

[JanKoehnlein]

Removed priority label, because the user impact is currently mitigated by on-call. Doesn't mean we're not working on this.

[geropl]

Dropping assignment, as I'm not actively working on this.

[geropl]

Update

For what has happened during the last weeks on this:

• we identified several source of bad performance/CPU spikes/long sync blocks and merged/shipped fixes [1, 2]
  • some are still outstanding, but can be continued after blockers have been addressed by platform
• @geropl: investigated of setTimeout/setInterval calls might be causing the slowly accumulating event loop lag. tl;dr: no, those are constant over time, or linear to #of API calls and did not accumulate (measured over the course of one day)
  • code: https://github.com/gitpod-io/gitpod/tree/gpl/lag-timeout
• increased # of pods (and nodes, we're running on smallish n4 nodes): https://github.com/gitpod-io/ops/pull/1230
• @AlexTugarev: merged a way to gather CPU profiles at runtime: [server] add cpu profiler #8284
• @geropl: set timeouts on all outgoing fetch calls in server ([ts] Update network-facing libs like express (et al.), node-fetch, p-… #8312)
• @geropl and @AlexTugarev: looked at recent (18.02) CPU profiles captured by attaching the Chrome debugger to the pod for ~5mins at runtime

  • the Chrome remote debugger does not show anything, and looks rather empty apart from known short spikes, which are partly already addressed above. Those are a problem in itself, but not the general problem we're looking at. The biggest time consumer seems to be the GC:
    

  • opening the same profile with the new, in-page Devtools visualization shows a big of a different picture (happened by accident 🙄 ):
    
    All long-running calls are ending in I/O bounds methods (writev, send, etc.): in the first visualization this were all shown to be blocked by the GC

  • this lead us to believe we might have a problem not (so much) with our code, but with the small VMs we're running on. We know from past experience that high I/O results in high CPU traffic/usage on VMs, especially small VMs 😬

  • might also fit with another observation: node.js self-reports , while the

    • maybe we're filling up runtime/kernel buffers and don't cleanup?

Suggestions:

• (merge and deploy above changes ☝️ )
• bigger nodes: maybe 2 x n2-standard-16 (instead of 6 x n1-standard-4) with bigger caches
• increase the size of the node.js threadpool UV_THREADPOOL_SIZE (this is responsible for performing all I/O) from default 4 to sth higher (depending on actual # of cores/pod)

[ghuntley]

Received a page moments ago about eventloop lag (internal link) which self-healed.

[geropl]

Received a page moments ago about eventloop lag (internal link) which self-healed.

This is more of an alerting/PagerDuty artifact.

[geropl]

Closing this issue, because it represents old behavior and based on old code. It does not make sense to continue here, especially as we can always go back and read up on the history/prior investigation.