https://outerbounds.com/ logo
Join Slack
Powered by
We are noticing some intermittently excessive time...
# ask-metaflow
e
We are noticing some intermittently excessive times between steps in a flow. It seems to be partially caused by some odd behavior with completion times on kubernetes For example, the last print statement from the python file is a memory printout at 
16:07:56
. One second later at 
16:07:57
the task is marked as finished. Then 4 minutes later at 
16:11:59
we get the standard output 
Task finished with exit code 0.
In flows where the parallelism is limited, this is causing the entire flow to hang until these stuck tasks get cleared out. Attached is the effect on the task graph Any thoughts on potential causes? This is running on metaflow version 
2.9.9
✅ 1
a
can you check if the kubernetes pod finished at 
16:07:57
or 
16:11:59
?
e
I can't unfortunately, because this was a few days ago and the completed pod has cleared out
a
hard to debug the reason without having access to pod events unfortunately 😞 if you are seeing this happen consistently, then there might be a zombie process in the user code that is preventing the container from terminating sooner.
can you confirm that 
Task finished with exit code 0.
at 
16:11:59
was for the same task_id which printed to stdout at 
16:07:56
?
the pathspec prefix for the logline should be the same for both the cases
e
Yea that makes sense. I'll keep an eye out for the next time this happens and look at those
👍🏼 1
m
Perhaps it is a scheduling issue on your Kubernetes cluster?
e
@mammoth-rainbow-82717 Thanks for the reply. Not in this case, because the problem is occurring after the pod is already scheduled
@User Some more research was done by @aloof-butcher-73366, here's what he found:
I heavily instrumented my fork of metaflow and tracked down the cause of the delay. The code is getting stuck in 
tail_logs
here: https://github.com/Netflix/metaflow/blob/ec8fd6c4a161b13a0f3765efb1e7fea92cdc2baa/metaflow/plugins/kubernetes/kubernetes.py#L357C9-L357C9
Digging deeper, the reason is that 
has_log_updates
(which is calling 
self._job.is_running
) continues to be true after the task has finished.
Digging deeper, both 
is_done
and 
_are_pod_containers_done
continue to be false (once either one is true, the job will finish)
Digging deeper, the fields checked by 
is_done
never seem to indicate that the job is done. So the cause is with 
_are_pod_containers_done
Checking 
_are_pod_containers_done
, the cause is that the container status continues to be “running” long after it’s printed the last statement of the function: https://github.com/Netflix/metaflow/blob/ec8fd6c4a161b13a0f3765efb1e7fea92cdc2baa/metaflow/plugins/kubernetes/kubernetes_job.py#L598
The container status seems to be set outside of metaflow so not sure what can be done to reduce the time from the job completing to when that status gets set to terminated. Usually it gets set within 1-2 seconds, but in my testing I had multiple instances where it took much longer
Here's his fork, which is based on the latest release with a few added debugging print statements: https://github.com/chadaeschliman/metaflow/tree/instrument_delays I've also recreated the issue a few minutes ago. For this latest particular job (gist here) the job is reported in the UI as completed at 
07-25-2023 16:33:26
. In the standard out the "Task finished with exit code 0" printout at 
16:39:17
. In Kubernetes that same pod says it completed at 
Finished:     Tue, 25 Jul 2023 11:33:28 -0500
. For whatever reason there's a ~6 min delay from when the pod is finished in kubernetes and when that task is reported as complete to Metaflow.
a
thanks! @User ^^
u
Thanks for sharing this! We had also seen some behavior like this earlier. Earlier, Metaflow would wait for the 
job
to be completed. But, it was noticed that in K8s, the 
job
gets marked as completed after the pod is marked completed and pods get marked as completed when the container is marked completed. Therefore, we had made these changes to look at container status instead of job status. Metaflow relies on K8s to mark the container as completed correctly and swiftly when the process inside the container completes. It's unclear in what cases and why does K8s sometimes take time to mark the container as compeleted. AFAICT, there are no K8s level config options either to influence this. I believe kubelet polls periodically whether the container it started completed or not. And this polling interval influences when the container is marked completed. With the changes above, things got better. But there might be something even more optimal. Let me know if there are more ideas/suggestions about what could be done here to make this faster.
e
@User Thanks for the reply Were you seeing behavior as severe as 5-10 minutes for the job to actually be marked as complete once the user code had finished executing? I'm also not sure the root cause in this case is the same as what you described. In the example above the container was marked as completed at 
11:33:28 -0500
but it took 6 minutes for Metaflow to print the final "Task finished with exit code 0" at 
16:39:17
and allow other tasks in the flow to run. I did realize that our job count was around 3300 completed jobs. Based on some research, it seems some clusters can have issues when surpassing 3000 jobs It's also odd that completed jobs stick around since the codebase sets a TTL here
I have yet to confirm whether removing old jobs has made a difference. I'll keep an eye on our flows and report back
u
That's a good point. I hadn't found any case where the delay was in minutes , let alone 5-10 minutes. It was always of the order of a few seconds. Just to confirm some basics: • Is it correct that the flow was started locally on a user machine? Or was it run as Argo workflow? • Can you confirm that there is no time difference between the user machine and k8s nodes? • Also, can you confirm that the user machine from where the flow was started had good connectivity with K8s? We've heard of some cases when VPNs can be a little flaky resulting in increased latencies. Great find about K8s performance issues when there are too many job objects in the cluster. • Can you check if those job objects are all from within the last 7 days? That's the TTL set in metaflow. Do you have some metrics enabled on the K8s api server to see response times? One metric that we could check is 
apiserver_request_duration_seconds
. With this, it would be possible to check if the problem was on the K8s side or on the client side.
e
• Is it correct that the flow was started locally on a user machine? Or was it run as Argo workflow?
Both. We began noticing it with scheduled jobs on argo, and had the same issue when ran from our version of "local" which is a users jupyterhub server
• Can you confirm that there is no time difference between the user machine and k8s nodes?
yes, shelling into one of the running containers on k8s and running 
date
matches up with running 
date
on local
• Also, can you confirm that the user machine from where the flow was started had good connectivity with K8s? We've heard of some cases when VPNs can be a little flaky resulting in increased latencies.
I'm confident the connection is good because both the Ec2 (where our jupyterhub runs) and k8s are both within AWS infrastructure.
• Can you check if those job objects are all from within the last 7 days? That's the TTL set in metaflow.
They are not. Some of them were over a month old. In k9s when I look at the yaml for a job, it shows 
f:ttlSecondsAfterFinished: {}
Do you have some metrics enabled on the K8s api server to see response times?
Not currently that's something I can work on adding I'll do some more testing to see if I can recreate the issue with a testing cluster by manually creating tons of jobs and see if that impacts metaflow in the same way. Also I'll investigate why TTL isn't working. It's somewhat odd because others at the company are also using python to deploy jobs and their ttl values are working fine
u
Just to confirm, are all the jobs in K8s created by metaflow?
e
yes. This cluster is only used by our datascience group
6 Views
Open in Slack
PreviousNext
Powered by