Thanks Benjamin,
I looked into the logs and it seems the delay is between the master and the
scheduler:
Master log:
I0314 18:23:59.409423 39743 master.cpp:3776] Processing ACCEPT call for offers:
[ afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-O25 ] on agent
edbbafb6-4f7b-4da2-8782-8e01461906dc-S0 at slave(1)@10.201.98.16:5051
(hadoop-master) for framework afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-0000 (Mesos
BM Scheduler)
W0314 18:23:59.410166 39743 validation.cpp:1064] Executor 'MesosBMExecutorId'
for task '8' uses less CPUs (None) than the minimum required (0.01). Please
update your executor, as this will be mandatory in future releases.
W0314 18:23:59.410221 39743 validation.cpp:1076] Executor 'MesosBMExecutorId'
for task '8' uses less memory (None) than the minimum required (32MB). Please
update your executor, as this will be mandatory in future releases.
I0314 18:23:59.410292 39743 master.cpp:9053] Adding task 8 with resources
cpus(*)(allocated: *):0.01 on agent edbbafb6-4f7b-4da2-8782-8e01461906dc-S0 at
slave(1)@10.201.98.16:5051 (hadoop-master)
I0314 18:23:59.410331 39743 master.cpp:4426] Launching task 8 of framework
afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-0000 (Mesos BM Scheduler) with resources
cpus(*)(allocated: *):0.01 on agent edbbafb6-4f7b-4da2-8782-8e01461906dc-S0 at
slave(1)@10.201.98.16:5051 (hadoop-master)
I0314 18:23:59.411258 39738 hierarchical.cpp:807] Updated allocation of
framework afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-0000 on agent
edbbafb6-4f7b-4da2-8782-8e01461906dc-S0 from cpus(*)(allocated: *):0.01 to
cpus(*)(allocated: *):0.01
I0314 18:23:59.415060 39723 master.cpp:6992] Sending 1 offers to framework
afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-0000 (Mesos BM Scheduler)
I0314 18:23:59.420624 39757 master.cpp:6154] Status update TASK_FINISHED (UUID:
583ea071-de66-4050-9513-8ff432da605f) for task 8 of framework
afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-0000 from agent
edbbafb6-4f7b-4da2-8782-8e01461906dc-S0 at slave(1)@10.201.98.16:5051
(hadoop-master)
I0314 18:23:59.420671 39757 master.cpp:6222] Forwarding status update
TASK_FINISHED (UUID: 583ea071-de66-4050-9513-8ff432da605f) for task 8 of
framework afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-0000
I0314 18:23:59.420819 39757 master.cpp:8302] Updating the state of task 8 of
framework afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-0000 (latest state:
TASK_FINISHED, status update state: TASK_FINISHED)
I0314 18:23:59.425354 39742 master.cpp:6992] Sending 1 offers to framework
afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-0000 (Mesos BM Scheduler)
I0314 18:23:59.459801 39741 http.cpp:420] HTTP POST for
/master/api/v1/scheduler from 127.0.0.1:36100
W0314 18:23:59.459889 39741 master.cpp:3634] Implicitly declining offers: [
afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-O26 ] in ACCEPT call for framework
afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-0000 as the launch operation specified no
tasks
I0314 18:23:59.460055 39741 master.cpp:3776] Processing ACCEPT call for offers:
[ afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-O26 ] on agent
edbbafb6-4f7b-4da2-8782-8e01461906dc-S0 at slave(1)@10.201.98.16:5051
(hadoop-master) for framework afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-0000 (Mesos
BM Scheduler)
I0314 18:23:59.460435 39741 http.cpp:420] HTTP POST for
/master/api/v1/scheduler from 127.0.0.1:36100
I0314 18:23:59.460484 39741 master.cpp:5092] Processing ACKNOWLEDGE call
583ea071-de66-4050-9513-8ff432da605f for task 8 of framework
afd6b67b-cac0-4b9f-baf6-2a456f4e84fa-0000 (Mesos BM Scheduler) on agent
edbbafb6-4f7b-4da2-8782-8e01461906dc-S0
From master log you can see that the time between the master received the offer
accept, until forwarding task_finished status to scheduler is ~11ms.
For some reason the scheduler acknowledge came after ~40ms although I’m sending
it immediately upon status update. Moreover I can’t explain why the time
between receiving an offer until accepting it (even on empty accept) take
~40ms. I think this might be related to the problem.
My scheduler is written in Java, inheriting
org.apache.mesos.v1.scheduler.Scheduler and passing it to
org.apache.mesos.v1.scheduler.V1Mesos.
This is my scheduler impl for processUpdate and processOffers (called upon
‘received’ with Protos.Event.UPDATE/OFFERS respectively):
private void processOffers(Mesos mesos, List<Offer> offers) {
for (Offer offer : offers) {
Offer.Operation.Launch.Builder launch =
Offer.Operation.Launch.newBuilder();
double offerCpus = 0;
for (Resource resource : offer.getResourcesList()){
if (resource.getName().equals("cpus")){
offerCpus += resource.getScalar().getValue();
}
}
LOGGER.info("Received offer " + offer.getId().getValue() + " from
agent: " + offer.getHostname() + " [cpus: " + offerCpus + "]");
while (!pendingTasks.isEmpty())
{
Task task = pendingTasks.peek();
if (task.requiredCpus <= offerCpus){
TaskID taskId = TaskID.newBuilder()
.setValue(Integer.toString(launchedTasks++)).build();
LOGGER.info("Launching task " + taskId.getValue() +
" using offer " + offer.getId().getValue());
TaskInfo taskInfo = TaskInfo.newBuilder()
.setName("task " + taskId.getValue())
.setTaskId(taskId)
.setAgentId(offer.getAgentId())
.addResources(Resource.newBuilder()
.setName("cpus")
.setType(Value.Type.SCALAR)
.setScalar(Value.Scalar.newBuilder()
.setValue(task.requiredCpus)
.build()))
.setExecutor(executorInfo)
.build();
launch.addTaskInfos(taskInfo);
offerCpus -= task.requiredCpus;
submittedTasks.put(taskId, pendingTasks.poll());
}
else {
break;
}
}
mesos.send(Call.newBuilder()
.setType(Call.Type.ACCEPT)
.setFrameworkId(frameworkId)
.setAccept(Call.Accept.newBuilder()
.addOfferIds(offer.getId())
.addOperations(Offer.Operation.newBuilder()
.setType(Offer.Operation.Type.LAUNCH)
.setLaunch(launch)
.build())
.setFilters(Filters.newBuilder()
.setRefuseSeconds(0)
.build()))
.build());
}
LOGGER.info("Completed handling offers");
}
private void processUpdate(Mesos mesos, TaskStatus taskStatus)
{
LOGGER.info("Task " + taskStatus.getTaskId().getValue() + " status " +
taskStatus.getState().name());
if (taskStatus.hasUuid()) {
mesos.send(Call.newBuilder()
.setType(Call.Type.ACKNOWLEDGE)
.setFrameworkId(frameworkId)
.setAcknowledge(Call.Acknowledge.newBuilder()
.setAgentId(taskStatus.getAgentId())
.setTaskId(taskStatus.getTaskId())
.setUuid(taskStatus.getUuid())
.build())
.build());
}
}
From: Benjamin Mahler [mailto:[email protected]]
Sent: Friday, March 10, 2017 12:52 AM
To: user
Subject: Re: High performance, low latency framework over mesos
Have you taken a look at the logs across your scheduler / master / agent to see
where the latency is introduced? We can then discuss options to reduce the
latency.
Ben
On Tue, Mar 7, 2017 at 5:03 AM,
<[email protected]<mailto:[email protected]>> wrote:
Hi,
I’m implementing my own framework (scheduler + executor) over mesos. The
framework is oriented for low latency, short running tasks (i.e. task time is
hundreds of ms).
I wrote a simple scheduler and executor and measured the time of task
submission RTT (round trip) – that is the elapsed time from submitting the task
at scheduler (by accepting and offer) and until the scheduler received
TASK_FINISHED status.
The task on executor side does nothing but to immediately sending TASK_FINISHED
status.
I see that the RTT is ~50ms which is quite a lot for my scenario, I was
wondering if this is controllable and why does it take so long to receive
status update.
Thanks
Assaf.
________________________________
________________________________
