You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hive.apache.org by "Denys Kuzmenko (Jira)" <ji...@apache.org> on 2025/05/21 17:15:00 UTC
[jira] [Updated] (HIVE-28962) Killed Tez task should be aborted
[ https://issues.apache.org/jira/browse/HIVE-28962?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Denys Kuzmenko updated HIVE-28962:
----------------------------------
Description:
Communication failure between coordinator and executor lead to a task kill (06:04:18.328Z)
d2/app=query-coordinator-0/2025-05-16-06-00_query-coordinator_query-coordinator-0-7_638e93f4-c948-4fc0-ad05-1451fc4b7c53_0.log:<14>1 2025-05-16T06:04:18.328Z query-coordinator-0-7 query-coordinator 1 638e93f4-c948-4fc0-ad05-1451fc4b7c53 [mdc@38374 class="HistoryEventHandler.criticalEvents" level="INFO" thread="Dispatcher thread \{Central}"] [HISTORY][DAG:dag_1746256596566_0014_1634][Event:TASK_ATTEMPT_FINISHED]: vertexName=Reducer 3, taskAttemptId=attempt_1746256596566_0014_1634_07_000070_13, creationTime=1747375458134, allocationTime=1747375458277, startTime=1747375458294, finishTime=1747375458328, timeTaken=34, status=KILLED, errorEnum=NODE_FAILED, diagnostics=Node with same host and port but with new unique ID pinged, nodeHttpAddress=[http://query-executor-0-16.query-executor-0-service.compute-1729926174-gnrw.svc.cluster.local:25002|http://query-executor-0-16.query-executor-0-service.compute-1729926174-gnrw.svc.cluster.local:25002/], counters=Counters: 1, org.apache.tez.common.counters.TaskCounter, TASK_DURATION_MILLIS=34
in the meantime, the executor kept on running the task attempt (06:04:27.340Z)
<14>1 2025-05-16T06:04:27.340Z query-executor-0-16 query-executor 1 71c82503-aeaa-4ca8-ad1c-c01db6df4f9d [mdc@38374 class="task.TaskRunner2Callable" dagId="dag_1746256596566_0014_1634" fragmentId="1746256596566_0014_1634_07_000070_13" level="INFO" queryId="hive_20250516055906_b7f7cff1-fc84-44d2-a7c5-30bd9aa428c5" thread="TezTR-596566_14_1634_7_70_13"] Initializing task, taskAttemptId=attempt_1746256596566_0014_1634_07_000070_13
but attempt=28 was started by the coordinator right after it noticed that attempt=13 failed (06:04:20.153Z)
d2/app=query-coordinator-0/2025-05-16-06-00_query-coordinator_query-coordinator-0-7_638e93f4-c948-4fc0-ad05-1451fc4b7c53_0.log:<14>1 2025-05-16T06:04:20.153Z query-coordinator-0-7 query-coordinator 1 638e93f4-c948-4fc0-ad05-1451fc4b7c53 [mdc@38374 class="tezplugins.LlapTaskSchedulerService" level="INFO" thread="LlapScheduler"] Assigned #16318391, task=TaskInfo\{task=attempt_1746256596566_0014_1634_07_000070_28, priority=140, startTime=0, containerId=null, uniqueId=16318390, localityDelayTimeout=1119114761} on node=\{query-executor-0-1.query-executor-0-service.compute-1729926174-gnrw.svc.cluster.local:25000, id=2c29ab22-c544-438e-bddf-dfbaebaa29fb, canAcceptTask=true, st=17, ac=5, commF=false, disabled=false}, to container=container_111101111_0014_01_32636783
and even if it was successfully killed, InterruptedException is typically because of task attempt kill in this scenario (06:04:27.442Z)
<11>1 2025-05-16T06:04:27.442Z query-executor-0-16 query-executor 1 71c82503-aeaa-4ca8-ad1c-c01db6df4f9d [mdc@38374 class="tez.TezProcessor" dagId="dag_1746256596566_0014_1634" fragmentId="1746256596566_0014_1634_07_000070_13" level="ERROR" queryId="hive_20250516055906_b7f7cff1-fc84-44d2-a7c5-30bd9aa428c5" thread="TezTR-596566_14_1634_7_70_13"] java.lang.InterruptedException\r at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056)\r at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2090)\r at org.apache.tez.runtime.InputReadyTracker$InputReadyMonitor.awaitCondition(InputReadyTracker.java:147)\r at org.apache.tez.runtime.InputReadyTracker.waitForAllInputsReady(InputReadyTracker.java:107)\r at org.apache.tez.runtime.api.impl.TezProcessorContextImpl.waitForAllInputsReady(TezProcessorContextImpl.java:138)\r at org.apache.tez.runtime.api.impl.TezProcessorContextImpl.waitForAllInputsReady(TezProcessorContextImpl.java:133)\r at org.apache.hadoop.hive.ql.exec.tez.ReduceRecordProcessor.init(ReduceRecordProcessor.java:122)\r at org.apache.hadoop.hive.ql.exec.tez.TezProcessor.initializeAndRunProcessor(TezProcessor.java:296)\r at org.apache.hadoop.hive.ql.exec.tez.TezProcessor.run(TezProcessor.java:280)\r at org.apache.tez.runtime.LogicalIOProcessorRuntimeTask.run(LogicalIOProcessorRuntimeTask.java:374)\r at org.apache.tez.runtime.task.TaskRunner2Callable$1.run(TaskRunner2Callable.java:86)\r at org.apache.tez.runtime.task.TaskRunner2Callable$1.run(TaskRunner2Callable.java:72)\r at java.base/java.security.AccessController.doPrivileged(Native Method)\r at java.base/javax.security.auth.Subject.doAs(Subject.java:423)\r at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1899)\r at org.apache.tez.runtime.task.TaskRunner2Callable.callInternal(TaskRunner2Callable.java:72)\r at org.apache.tez.runtime.task.TaskRunner2Callable.callInternal(TaskRunner2Callable.java:42)\r at org.apache.tez.common.CallableWithNdc.call(CallableWithNdc.java:36)\r at org.apache.hadoop.hive.llap.daemon.impl.StatsRecordingThreadPool$WrappedCallable.call(StatsRecordingThreadPool.java:118)\r at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)\r at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\r at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\r at java.base/java.lang.Thread.run(Thread.java:829)\r
it already written a commit manifest before (06:04:27.442Z) <-- same timestamp, but before
<14>1 2025-05-16T06:04:27.442Z query-executor-0-16 query-executor 1 71c82503-aeaa-4ca8-ad1c-c01db6df4f9d [mdc@38374 class="hive.HiveIcebergOutputCommitter" dagId="dag_1746256596566_0014_1634" fragmentId="1746256596566_0014_1634_07_000070_13" level="INFO" queryId="hive_20250516055906_b7f7cff1-fc84-44d2-a7c5-30bd9aa428c5" thread="TezTR-596566_14_1634_7_70_13"] Created Iceberg commitTask manifest file: [s3a://s3-cdp-dub-prd-int-prd-464373096835/data/warehouse/tablespace/external/hive/adp_staging.db/fct_position_security_level_ext_2/temp/hive_20250516055906_b7f7cff1-fc84-44d2-a7c5-30bd9aa428c5-job_17462565965667_0014/task-70.forCommit]\rFilesForCommit\{dataFiles=[], deleteFiles=[], replacedDataFiles=[], referencedDataFiles=[]}
> Killed Tez task should be aborted
> ---------------------------------
>
> Key: HIVE-28962
> URL: https://issues.apache.org/jira/browse/HIVE-28962
> Project: Hive
> Issue Type: Bug
> Components: Iceberg integration
> Reporter: Denys Kuzmenko
> Priority: Major
>
> Communication failure between coordinator and executor lead to a task kill (06:04:18.328Z)
>
> d2/app=query-coordinator-0/2025-05-16-06-00_query-coordinator_query-coordinator-0-7_638e93f4-c948-4fc0-ad05-1451fc4b7c53_0.log:<14>1 2025-05-16T06:04:18.328Z query-coordinator-0-7 query-coordinator 1 638e93f4-c948-4fc0-ad05-1451fc4b7c53 [mdc@38374 class="HistoryEventHandler.criticalEvents" level="INFO" thread="Dispatcher thread \{Central}"] [HISTORY][DAG:dag_1746256596566_0014_1634][Event:TASK_ATTEMPT_FINISHED]: vertexName=Reducer 3, taskAttemptId=attempt_1746256596566_0014_1634_07_000070_13, creationTime=1747375458134, allocationTime=1747375458277, startTime=1747375458294, finishTime=1747375458328, timeTaken=34, status=KILLED, errorEnum=NODE_FAILED, diagnostics=Node with same host and port but with new unique ID pinged, nodeHttpAddress=[http://query-executor-0-16.query-executor-0-service.compute-1729926174-gnrw.svc.cluster.local:25002|http://query-executor-0-16.query-executor-0-service.compute-1729926174-gnrw.svc.cluster.local:25002/], counters=Counters: 1, org.apache.tez.common.counters.TaskCounter, TASK_DURATION_MILLIS=34
> in the meantime, the executor kept on running the task attempt (06:04:27.340Z)
>
> <14>1 2025-05-16T06:04:27.340Z query-executor-0-16 query-executor 1 71c82503-aeaa-4ca8-ad1c-c01db6df4f9d [mdc@38374 class="task.TaskRunner2Callable" dagId="dag_1746256596566_0014_1634" fragmentId="1746256596566_0014_1634_07_000070_13" level="INFO" queryId="hive_20250516055906_b7f7cff1-fc84-44d2-a7c5-30bd9aa428c5" thread="TezTR-596566_14_1634_7_70_13"] Initializing task, taskAttemptId=attempt_1746256596566_0014_1634_07_000070_13
> but attempt=28 was started by the coordinator right after it noticed that attempt=13 failed (06:04:20.153Z)
>
> d2/app=query-coordinator-0/2025-05-16-06-00_query-coordinator_query-coordinator-0-7_638e93f4-c948-4fc0-ad05-1451fc4b7c53_0.log:<14>1 2025-05-16T06:04:20.153Z query-coordinator-0-7 query-coordinator 1 638e93f4-c948-4fc0-ad05-1451fc4b7c53 [mdc@38374 class="tezplugins.LlapTaskSchedulerService" level="INFO" thread="LlapScheduler"] Assigned #16318391, task=TaskInfo\{task=attempt_1746256596566_0014_1634_07_000070_28, priority=140, startTime=0, containerId=null, uniqueId=16318390, localityDelayTimeout=1119114761} on node=\{query-executor-0-1.query-executor-0-service.compute-1729926174-gnrw.svc.cluster.local:25000, id=2c29ab22-c544-438e-bddf-dfbaebaa29fb, canAcceptTask=true, st=17, ac=5, commF=false, disabled=false}, to container=container_111101111_0014_01_32636783
> and even if it was successfully killed, InterruptedException is typically because of task attempt kill in this scenario (06:04:27.442Z)
>
> <11>1 2025-05-16T06:04:27.442Z query-executor-0-16 query-executor 1 71c82503-aeaa-4ca8-ad1c-c01db6df4f9d [mdc@38374 class="tez.TezProcessor" dagId="dag_1746256596566_0014_1634" fragmentId="1746256596566_0014_1634_07_000070_13" level="ERROR" queryId="hive_20250516055906_b7f7cff1-fc84-44d2-a7c5-30bd9aa428c5" thread="TezTR-596566_14_1634_7_70_13"] java.lang.InterruptedException\r at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056)\r at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2090)\r at org.apache.tez.runtime.InputReadyTracker$InputReadyMonitor.awaitCondition(InputReadyTracker.java:147)\r at org.apache.tez.runtime.InputReadyTracker.waitForAllInputsReady(InputReadyTracker.java:107)\r at org.apache.tez.runtime.api.impl.TezProcessorContextImpl.waitForAllInputsReady(TezProcessorContextImpl.java:138)\r at org.apache.tez.runtime.api.impl.TezProcessorContextImpl.waitForAllInputsReady(TezProcessorContextImpl.java:133)\r at org.apache.hadoop.hive.ql.exec.tez.ReduceRecordProcessor.init(ReduceRecordProcessor.java:122)\r at org.apache.hadoop.hive.ql.exec.tez.TezProcessor.initializeAndRunProcessor(TezProcessor.java:296)\r at org.apache.hadoop.hive.ql.exec.tez.TezProcessor.run(TezProcessor.java:280)\r at org.apache.tez.runtime.LogicalIOProcessorRuntimeTask.run(LogicalIOProcessorRuntimeTask.java:374)\r at org.apache.tez.runtime.task.TaskRunner2Callable$1.run(TaskRunner2Callable.java:86)\r at org.apache.tez.runtime.task.TaskRunner2Callable$1.run(TaskRunner2Callable.java:72)\r at java.base/java.security.AccessController.doPrivileged(Native Method)\r at java.base/javax.security.auth.Subject.doAs(Subject.java:423)\r at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1899)\r at org.apache.tez.runtime.task.TaskRunner2Callable.callInternal(TaskRunner2Callable.java:72)\r at org.apache.tez.runtime.task.TaskRunner2Callable.callInternal(TaskRunner2Callable.java:42)\r at org.apache.tez.common.CallableWithNdc.call(CallableWithNdc.java:36)\r at org.apache.hadoop.hive.llap.daemon.impl.StatsRecordingThreadPool$WrappedCallable.call(StatsRecordingThreadPool.java:118)\r at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)\r at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\r at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\r at java.base/java.lang.Thread.run(Thread.java:829)\r
> it already written a commit manifest before (06:04:27.442Z) <-- same timestamp, but before
>
> <14>1 2025-05-16T06:04:27.442Z query-executor-0-16 query-executor 1 71c82503-aeaa-4ca8-ad1c-c01db6df4f9d [mdc@38374 class="hive.HiveIcebergOutputCommitter" dagId="dag_1746256596566_0014_1634" fragmentId="1746256596566_0014_1634_07_000070_13" level="INFO" queryId="hive_20250516055906_b7f7cff1-fc84-44d2-a7c5-30bd9aa428c5" thread="TezTR-596566_14_1634_7_70_13"] Created Iceberg commitTask manifest file: [s3a://s3-cdp-dub-prd-int-prd-464373096835/data/warehouse/tablespace/external/hive/adp_staging.db/fct_position_security_level_ext_2/temp/hive_20250516055906_b7f7cff1-fc84-44d2-a7c5-30bd9aa428c5-job_17462565965667_0014/task-70.forCommit]\rFilesForCommit\{dataFiles=[], deleteFiles=[], replacedDataFiles=[], referencedDataFiles=[]}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)