Concurrent task execs take significantly longer than sequentially #8557
Description
Description
If a large enough number of exec process start requests (i.e. TaskService.Start() with ExecID set) are issued concurrently, all requests will block for seconds to minutes at a time, then all return at once.
See also:
Steps to reproduce the issue
ctr image pull docker.io/library/alpine:latest && ctr run -d docker.io/library/alpine:latest pause1 sleep infinitytime sh -c 'myjobs=""; for i in $(seq 1 30); do ctr t exec --exec-id=testing_$i pause1 true </dev/null & myjobs="$myjobs $!"; done; for pid in $myjobs; do wait $pid; done'
Describe the results you received and expected
Actual: 19s
DEBU[2023-05-23T18:17:15.608250130Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.636746192Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.643307643Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.660789796Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.675599268Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.679641133Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.682983826Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.686157242Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.687852903Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.699389580Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.705156400Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.706376528Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.714461542Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.717638195Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.718056222Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.719652747Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:15.722360904Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:15.724600352Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.729013153Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.730152655Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.733024702Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.736167030Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.739121245Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.741735122Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.742621182Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.743892422Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.744207393Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.749659225Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.751571834Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.754096872Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.762238861Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.764560423Z] event forwarded ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-05-23T18:17:15.765381302Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:15.766548440Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:15.799532429Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:15.799924942Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:15.838310096Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:15.838568423Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:15.877056023Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:15.910642048Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:15.946239151Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:15.998530594Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.040403090Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.076447546Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.111361858Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.147002057Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.182546919Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.216171189Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.252383802Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.295510435Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.333803347Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.367195902Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.406056495Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.443416422Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:16.485723552Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:17.490113925Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:20.493573798Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:21.495858359Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:23.489603115Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:26.502634368Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:28.509058648Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:30.511989264Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:31.514755526Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:34.497825962Z] event forwarded ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-05-23T18:17:34.513164501Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.513623828Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.514007583Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.514890279Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.516338632Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.517059793Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.519342611Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.521688999Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.533318522Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.534769991Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.538684144Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.540641442Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.541121952Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.542374190Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.544409000Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.545360767Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.546768705Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.549519712Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.550407208Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.551130679Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.552156136Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.552592232Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
real 0m18.978s
user 0m0.596s
sys 0m0.589s
DEBU[2023-05-23T18:17:34.553852690Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.554614606Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.555489207Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-05-23T18:17:34.556162399Z] event forwarded ns=default topic=/tasks/exit type=containerd.events.TaskExit
I expect fifty execs concurrently to take a comparable amount of time to running fifty execs sequentially, which I have measured takes 2.3s on my test environment.
What version of containerd are you using?
containerd github.com/containerd/containerd v1.7.1 1677a17
Any other relevant information
runc version 1.1.7
commit: v1.1.7-0-g860f061
spec: 1.0.2-dev
go: go1.20.4
libseccomp: 2.5.1
Show configuration if it is related to CRI plugin.
No response