tez-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Jonathan Turner Eagles (Jira)" <j...@apache.org>
Subject [jira] [Created] (TEZ-4108) NullPointerException during speculative execution race condition
Date Fri, 13 Dec 2019 20:03:00 GMT
Jonathan Turner Eagles created TEZ-4108:
-------------------------------------------

             Summary: NullPointerException during speculative execution race condition
                 Key: TEZ-4108
                 URL: https://issues.apache.org/jira/browse/TEZ-4108
             Project: Apache Tez
          Issue Type: Bug
            Reporter: Jonathan Turner Eagles
            Assignee: Jonathan Turner Eagles


What is happening is a race condition between speculative execution task launch and failure.
Such that when the speculative attempt begins to launch, the earlier attempt is no longer
running. Somehow the containerNodeId is becoming null. From the log line we can see that at
least when the original task attempt starts, the container node id is not null.

This points to a bug in Tez.

Posting AM log context and full stack trace.
{noformat}
2019-11-18 12:58:13,261 [INFO] [Dispatcher thread {Central}] |HistoryEventHandler.criticalEvents|:
[HISTORY][DAG:dag_1571959303156_328042_1][Event:TASK_ATTEMPT_STARTED]: vertexName=Map 1, taskAttemptId=attempt_1571959303156_328042_1_00_091618_0,
startTime=1574081893261, containerId=container_e20_1571959303156_328042_01_006583, nodeId=node1.example.com:8041
2019-11-18 12:58:25,001 [INFO] [Dispatcher thread {Central}] |HistoryEventHandler.criticalEvents|:
[HISTORY][DAG:dag_1571959303156_328042_1][Event:TASK_STARTED]: vertexName=Map 1, taskId=task_1571959303156_328042_1_00_091618,
scheduledTime=1574081308038, launchTime=1574081893261
2019-11-18 12:58:26,916 [INFO] [Dispatcher thread {Central}] |HistoryEventHandler.criticalEvents|:
[HISTORY][DAG:dag_1571959303156_328042_1][Event:TASK_ATTEMPT_FINISHED]: vertexName=Map 1,
taskAttemptId=attempt_1571959303156_328042_1_00_091618_0, creationTime=1574081308038, allocationTime=1574081880179,
startTime=1574081893261, finishTime=1574081906915, timeTaken=13654, status=KILLED, errorEnum=EXTERNAL_PREEMPTION,
diagnostics=Container container_e20_1571959303156_328042_01_006583 finished with diagnostics
set to [Container preempted externally. Container Preempted due to node overcommit
2019-11-18 12:58:27,264 [INFO] [Dispatcher thread {Speculator}] |legacy.LegacySpeculator|:
DefaultSpeculator.addSpeculativeAttempt -- we are speculating task_1571959303156_328042_1_00_091618
2019-11-18 12:58:34,633 [INFO] [TaskSchedulerEventHandlerThread] |rm.TaskSchedulerManager|:
Task: attempt_1571959303156_328042_1_00_091618_0 has no container assignment in the scheduler
2019-11-18 12:58:34,636 [ERROR] [TaskSchedulerEventHandlerThread] |rm.TaskSchedulerManager|:
No container allocated to task: attempt_1571959303156_328042_1_00_091618_0 according to scheduler.
Task reported container id: container_e20_1571959303156_328042_01_006583
2019-11-18 12:58:34,866 [INFO] [Dispatcher thread {Central}] |impl.TaskImpl|: Scheduling a
redundant attempt for task task_1571959303156_328042_1_00_091618
2019-11-18 12:58:34,866 [ERROR] [Dispatcher thread {Central}] |impl.TaskImpl|: Uncaught exception
when trying handle event T_ADD_SPEC_ATTEMPT at current state RUNNING for task task_1571959303156_328042_1_00_091618
java.lang.NullPointerException
        at java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1011)
        at java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:1006)
        at java.util.Collections$SetFromMap.add(Collections.java:5461)
        at org.apache.tez.dag.app.dag.impl.TaskImpl$RedundantScheduleTransition.transition(TaskImpl.java:1044)
        at org.apache.tez.dag.app.dag.impl.TaskImpl$RedundantScheduleTransition.transition(TaskImpl.java:1032)
        at org.apache.hadoop.yarn.state.StateMachineFactory$SingleInternalArc.doTransition(StateMachineFactory.java:362)
        at org.apache.hadoop.yarn.state.StateMachineFactory.doTransition(StateMachineFactory.java:302)
        at org.apache.hadoop.yarn.state.StateMachineFactory.access$300(StateMachineFactory.java:46)
        at org.apache.hadoop.yarn.state.StateMachineFactory$InternalStateMachine.doTransition(StateMachineFactory.java:448)
        at org.apache.tez.state.StateMachineTez.doTransition(StateMachineTez.java:59)
        at org.apache.tez.dag.app.dag.impl.TaskImpl.handle(TaskImpl.java:841)
        at org.apache.tez.dag.app.dag.impl.TaskImpl.handle(TaskImpl.java:115)
        at org.apache.tez.dag.app.DAGAppMaster$TaskEventDispatcher.handle(DAGAppMaster.java:2311)
        at org.apache.tez.dag.app.DAGAppMaster$TaskEventDispatcher.handle(DAGAppMaster.java:2298)
        at org.apache.tez.common.AsyncDispatcher.dispatch(AsyncDispatcher.java:180)
        at org.apache.tez.common.AsyncDispatcher$1.run(AsyncDispatcher.java:115)
        at java.lang.Thread.run(Thread.java:748)
{noformat}

{code:title=TaskImpl.java}
1032   private static class RedundantScheduleTransition
1033     implements SingleArcTransition<TaskImpl, TaskEvent> {
1034
1035     @Override
1036     public void transition(TaskImpl task, TaskEvent event) {
1037       LOG.info("Scheduling a redundant attempt for task " + task.taskId);
1038       task.counters.findCounter(TaskCounter.NUM_SPECULATIONS).increment(1);
1039       TaskAttempt earliestUnfinishedAttempt = null;
1040       for (TaskAttempt ta : task.attempts.values()) {
1041         // find the oldest running attempt
1042         if (!ta.isFinished()) {
1043           earliestUnfinishedAttempt = ta;
1044           task.nodesWithRunningAttempts.add(ta.getNodeId());
1045         } else {
1046           if (TaskAttemptState.SUCCEEDED.equals(ta.getState())) {
1047             LOG.info("Ignore speculation scheduling for task {} since it has succeeded
with attempt {}.",
1048                 task.getTaskId(), ta.getID());
1049             return;
1050           }
1051         }
1052       }
1053       if (earliestUnfinishedAttempt == null) {
1054         // no running (or SUCCEEDED) task attempt at this moment, no need to schedule
speculative attempt either
1055         LOG.info("Ignore speculation scheduling since there is no running attempt on
task {}.", task.getTaskId());
1056         return;
1057       }
1058       if (task.commitAttempt != null) {
1059         LOG.info("Ignore speculation scheduling for task {} since commit has started
with commitAttempt {}.",
1060             task.getTaskId(), task.commitAttempt);
1061         return;
1062       }
1063       task.addAndScheduleAttempt(earliestUnfinishedAttempt.getID());
1064     }
1065   }
{code}



--
This message was sent by Atlassian Jira
(v8.3.4#803005)

Mime
View raw message