Really slow http template workflow execution

[julienteisseire]

Hi,

I would like to talk about the behavior of the http template agent.

First, this agent container is stopped after workflow execution, it would be great to keep it running in order to avoid start time at workflow submit time.

Additionally, I don't understand why, for only 2 http call in my workflow, it took 50 seconds to run ...

Name:                myworkflow-rv7dd
Namespace:           commanding
ServiceAccount:      argo-workflow
Status:              Succeeded
Conditions:
 PodRunning          False
 Completed           True
Created:             Thu Oct 31 11:17:36 +0100 (50 seconds ago)
Started:             Thu Oct 31 11:17:36 +0100 (50 seconds ago)
Finished:            Thu Oct 31 11:18:26 +0100 (now)
Duration:            50 seconds
Progress:            2/2

STEP                     TEMPLATE  PODNAME  DURATION  MESSAGE
 ✔ myworkflow-rv7dd  main
 ├───✔ call-probe       http-get
 └───✔ call-start       http-put

Here is the agent logs where we can see long delay between steps and I would like to know if it is possible to optimize all this sleep phases ... ?

time="2024-10-31T10:17:42.500Z" level=info msg="Starting Workflow Executor" version=v3.5.11
time="2024-10-31T10:17:42.502Z" level=info msg="Starting Agent" requeueTime=10s taskWorkers=16 workflow=myworkflow-rv7dd
time="2024-10-31T10:17:43.301Z" level=debug msg="Watch workflowtasksets 200"
time="2024-10-31T10:17:43.404Z" level=info msg="TaskSet Event" event_type=ADDED workflow=myworkflow-rv7dd
time="2024-10-31T10:17:43.405Z" level=info msg="Processing task" nodeID=myworkflow-rv7dd-1881501112
time="2024-10-31T10:17:43.508Z" level=info msg="Sending result" message= nodeID=myworkflow-rv7dd-1881501112 phase=Succeeded requeue=0s
time="2024-10-31T10:17:46.547Z" level=info msg="TaskSet Event" event_type=MODIFIED workflow=myworkflow-rv7dd
time="2024-10-31T10:17:46.548Z" level=info msg="Task is already considered" nodeID=myworkflow-rv7dd-1881501112
time="2024-10-31T10:17:52.748Z" level=info msg="Processing Patch" workflow=myworkflow-rv7dd
time="2024-10-31T10:17:52.755Z" level=info msg="TaskSet Event" event_type=MODIFIED workflow=myworkflow-rv7dd
time="2024-10-31T10:17:52.755Z" level=info msg="Task is already considered" nodeID=myworkflow-rv7dd-1881501112
time="2024-10-31T10:17:52.755Z" level=debug msg="Patch workflowtasksets/status 200"
time="2024-10-31T10:17:52.756Z" level=info msg="Patched TaskSet"
time="2024-10-31T10:18:06.604Z" level=info msg="TaskSet Event" event_type=MODIFIED workflow=myworkflow-rv7dd
time="2024-10-31T10:18:06.604Z" level=info msg="Processing task" nodeID=myworkflow-rv7dd-195299183
time="2024-10-31T10:18:06.604Z" level=info msg="Task is already considered" nodeID=myworkflow-rv7dd-1881501112
time="2024-10-31T10:18:06.613Z" level=info msg="Sending result" message= nodeID=myworkflow-rv7dd-195299183 phase=Succeeded requeue=0s
time="2024-10-31T10:18:12.748Z" level=info msg="Processing Patch" workflow=myworkflow-rv7dd
time="2024-10-31T10:18:12.759Z" level=debug msg="Patch workflowtasksets/status 200"
time="2024-10-31T10:18:12.759Z" level=info msg="Patched TaskSet"
time="2024-10-31T10:18:12.760Z" level=info msg="TaskSet Event" event_type=MODIFIED workflow=myworkflow-rv7dd
time="2024-10-31T10:18:12.760Z" level=info msg="Task is already considered" nodeID=myworkflow-rv7dd-195299183
time="2024-10-31T10:18:12.760Z" level=info msg="Task is already considered" nodeID=myworkflow-rv7dd-1881501112

50 seconds execution time for a workflow of 2 HTTP calls looks to be a bit disproportionate.
Could you help me to understand is it is a normal behavior or if we have some way to improve ?

[agilgur5]

First, this agent container is stopped after workflow execution, it would be great to keep it running in order to avoid start time at workflow submit time

Only one agent runs per workflow. See also #7891, but a global agent would still be started on-demand if none had been recently created ("cold start", basically). And the k8s security model means the SA and NS matter too, per the issue comments.

Here is the agent logs where we can see long delay between steps and I would like to know if it is possible to optimize all this sleep phases ... ?

This sounds partly like queue time, see also #11275.
Another part may be the time the Controller is waiting to see successful results from the k8s API server before starting the next task or that the Agent is waiting to see new tasks from the k8s API server, based on the logs. Someone would have to deep dive that to tell for sure

[julienteisseire]

After reading the provided links, I understand (question 1) permanent node per service account (and for all workflows) is not yet implemented nor really pertinent. So I have to live with one agent to be created per workflow, and deleted at workflow end . So every time I submit a workflow a dedicated agent will be created ....

For the second point, I don't understand the k8s API server dependency. Workflow agent is running the steps (curl in my case for http calls) and why k8s APi is involved in this processing ?
I also not understand how to know if reducing DEFAULT_REQUEUE_TIME from 10 to 5 for instance is a good thing ...

[julienteisseire]

I tested with DEFAULT_REQUEUE_TIME = 2s and I have best performance for my workflow execution.
I don't know what could be the problem of reducing this value regarding the default to 10s ?

[agilgur5]

I also not understand how to know if reducing DEFAULT_REQUEUE_TIME from 10 to 5 for instance is a good thing ...

I don't know what could be the problem of reducing this value regarding the default to 10s ?

It depends on the rest of your k8s environment, so it's honestly hard for anyone to say without having detailed knowledge of your cluster. In #11275 (reply in thread) I linked to a section of the Scaling docs that describes this. Ultimately, k8s is a centralized architecture, so if one tool like Argo puts too much pressure on it, it can cause problems elsewhere.
Also it may be unnecessary to requeue more frequently if you have many slower workflows, whereas it can be helpful for faster workflows like yours.
There's a careful balance to consider.

For the second point, I don't understand the k8s API server dependency. Workflow agent is running the steps (curl in my case for http calls) and why k8s APi is involved in this processing ?

The Controller and Executor, including the Agent (which you could describe as a specific variation of the Executor), communicate with each other through k8s resources: the WorkflowTaskResult and WorkflowTaskSet. That's why they need RBAC for those.
The Controller delegates tasks to the Agent via WorkflowTaskSet, which is why the Agent has list and watch RBAC for those. The Agent patches the status to report back.

It helps to think of Argo as a state machine built on top of k8s, and as with all asynchronous state machines, tracking everything and keeping things synchronized to handle race conditions is a large part of the work.

[julienteisseire]

Really clear explanation. Thank you.

[jswxstw]

Considering reducing DEFAULT_REQUEUE_TIME may increase the load of APIServer, you can reduce ARGO_AGENT_PATCH_RATE individually, as I mentioned in #13847 (comment).