Anand Mazumdar created MESOS-5349:
-------------------------------------
Summary: A large number of tasks stuck in Staging state.
Key: MESOS-5349
URL: https://issues.apache.org/jira/browse/MESOS-5349
Project: Mesos
Issue Type: Bug
Components: slave
Affects Versions: 0.29.0
Reporter: Anand Mazumdar
We saw a weird issue happening on one of our test clusters over the weekend. A
large number of tasks from the example {{long running framework}} were stuck in
staging. The executor was duly sending status updates for all the tasks and the
slave successfully received the status update as seen from the logs but for
some reason never got to checkpointing them.
>From the agent logs, it seems that it kept on retrying some backlogged status
>updates starting with the 4xxx/6xxx range while the present tasks were
>launched in the 8xxx range. (task ID)
The issue resolved itself after a few hours upon the agent (re-)registering
with the master upon loosing its ZK session.
Let's take a timeline of a particular task 8142.
Agent logs before restart
{code}
May 08 00:47:34 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:34.204941 2820
slave.cpp:1522] Got assigned task 8142 for framework
ad2ee74e-24f1-4381-be9a-1af70ba1ced0-0003
May 08 00:47:34 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:34.205142 2820
slave.cpp:1641] Launching task 8142 for framework
ad2ee74e-24f1-4381-be9a-1af70ba1ced0-0003
May 08 00:47:34 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:34.205656 2820
slave.cpp:1880] Queuing task '8142' for executor 'default' of framework
ad2ee74e-24f1-4381-be9a-1af70ba1ced0-0003 (via HTTP)
May 08 00:47:34 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:34.206092 2818
disk.cpp:169] Updating the disk resources for container
f68f137c-b101-4f9f-8de4-f50eae27e969 to cpus(*):0.101; mem(*):33
May 08 00:47:34 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:34.207093 2816
mem.cpp:353] Updated 'memory.soft_limit_in_bytes' to 33MB for container
f68f137c-b101-4f9f-8de4-f50eae27e969
May 08 00:47:34 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:34.207293 2821
cpushare.cpp:389] Updated 'cpu.shares' to 103 (cpus 0.101) for container
f68f137c-b101-4f9f-8de4-f50eae27e969
May 08 00:47:34 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:34.208742 2821
cpushare.cpp:411] Updated 'cpu.cfs_period_us' to 100ms and 'cpu.cfs_quota_us'
to 10100us (cpus 0.101) for container f68f137c-b101-4f9f-8de4-f50eae27e969
May 08 00:47:34 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:34.208902 2818
slave.cpp:2032] Sending queued task '8142' to executor 'default' of framework
ad2ee74e-24f1-4381-be9a-1af70ba1ced0-0003 (via HTTP)
May 08 00:47:34 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:34.210290 2821
http.cpp:188] HTTP POST for /slave(1)/api/v1/executor from 10.10.0.6:60921
May 08 00:47:34 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:34.210357 2821
slave.cpp:3221] Handling status update TASK_RUNNING (UUID:
85323c4f-e523-495e-9b49-39b0a7792303) for task 8142 of framework
ad2ee74e-24f1-4381-be9a-1af70ba1ced0-0003
May 08 00:47:40 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:40.213770 2817
http.cpp:188] HTTP POST for /slave(1)/api/v1/executor from 10.10.0.6:60921
May 08 00:47:40 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:40.213882 2817
slave.cpp:3221] Handling status update TASK_FINISHED (UUID:
285b73e1-7f5a-43e5-8385-7b76e0fbdad4) for task 8142 of framework
ad2ee74e-24f1-4381-be9a-1af70ba1ced0-0003
May 08 00:47:40 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:40.214787 2821
disk.cpp:169] Updating the disk resources for container
f68f137c-b101-4f9f-8de4-f50eae27e969 to cpus(*):0.1; mem(*):32
May 08 00:47:40 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:40.215365 2823
cpushare.cpp:389] Updated 'cpu.shares' to 102 (cpus 0.1) for container
f68f137c-b101-4f9f-8de4-f50eae27e969
May 08 00:47:40 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:40.215641 2820
mem.cpp:353] Updated 'memory.soft_limit_in_bytes' to 32MB for container
f68f137c-b101-4f9f-8de4-f50eae27e969
May 08 00:47:40 ip-10-10-0-6 mesos-slave[2779]: I0508 00:47:40.216878 2823
cpushare.cpp:411] Updated 'cpu.cfs_period_us' to 100ms and 'cpu.cfs_quota_us'
to 10ms (cpus 0.1) for container f68f137c-b101-4f9f-8de4-f50eae27e969
{code}
Agent logs for this task upon restart:
{code}
May 09 15:22:14 ip-10-10-0-6 mesos-slave[14314]: W0509 15:22:14.083993 14318
state.cpp:606] Failed to find status updates file
'/var/lib/mesos/slave/meta/slaves/ad2ee74e-24f1-4381-be9a-1af70ba1ced0-S1/frameworks/ad2ee74e-24f1-4381-be9a-1af70ba1ced0-0003/executors/default/runs/f68f137c-b101-4f9f-8de4-f50eae27e969/tasks/8142/task.updates'
{code}
Things that need to be investigated:
- Why couldn't the agent get around to handling the status updates from the
executor i.e. even checkpointing them?
- What made the agent get _so_ backlogged on the status updates i.e. why it
kept resending the old status updates for the 4xxxx/6xxxx tasks without getting
around to the newer tasks.
PFA the agent/master logs. This is running against Mesos HEAD ->
557cab591f35a6c3d2248d7af7f06cdf99726e92
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
