dobrovolskiy created TEZ-4121:
---------------------------------
Summary: Tez task infinitely hanging on [TezChild]
|exec.FileSinkOperator|: FS[2]: records written -
Key: TEZ-4121
URL: https://issues.apache.org/jira/browse/TEZ-4121
Project: Apache Tez
Issue Type: Bug
Reporter: dobrovolskiy
Attachments: dag_details.png, grafical_view.png, task_attempts.png,
vertex_details_reducer_2.png
On tez 0.7.0.2.6.4.0-91 we've got an infinetly hang task without PID on the
datanode host
This task was successfully executed on the second attempt only after container
killed.
The cluster was free of resources for this application.
Could you suggest how to fix this issue?
The search of bugs for this strange behaviour in Jira doesn't get something.
See screenshots from TEZ UI:
timing of task_attempts.png
vertex_details_reducer_2.png
dag_details.png
grafical_view.png
Log of hanging task:
{code:java}
2020-02-04 03:28:58,502 [INFO] [TezChild] |tez.ReduceRecordProcessor|:
<MERGEJOIN>Id =5
<Children>
<SEL>Id =6
<Children>
<FS>Id =7
<Children>
<\Children>
<Parent>Id = 6 null<\Parent>
<\FS>
<\Children>
<Parent>Id = 5 null<\Parent>
<\SEL>
<\Children>
<Parent><\Parent>
<\MERGEJOIN>
2020-02-04 03:28:58,502 [INFO] [TezChild] |log.PerfLogger|: </PERFLOG
method=TezInitializeOperators start=1580775588151 end=1580776138502
duration=550351 from=org.apache.hadoop.hive.ql.exec.tez.RecordProcessor>
2020-02-04 03:28:58,502 [INFO] [TezChild] |tez.ReduceRecordProcessor|: Starting
Output: out_Reducer 2
2020-02-04 03:28:58,504 [WARN] [TezChild]
|objectinspector.StandardStructObjectInspector|: Trying to access 2 fields
inside a list of 1 elements: [[06640113161911]]
2020-02-04 03:28:58,504 [WARN] [TezChild]
|objectinspector.StandardStructObjectInspector|: ignoring similar errors.
2020-02-04 03:28:58,514 [INFO] [TezChild] |exec.FileSinkOperator|: Final Path:
FS
hdfs://cluster/apps/hive/warehouse/sample.db/.hive-staging_hive_2020-02-04_03-10-36_142_570908369342623638-1/_tmp.-ext-10001/001098_0
2020-02-04 03:28:58,514 [INFO] [TezChild] |exec.FileSinkOperator|: Writing to
temp file: FS
hdfs://cluster/apps/hive/warehouse/sample.db/.hive-staging_hive_2020-02-04_03-10-36_142_570908369342623638-1/_task_tmp.-ext-10001/_tmp.001098_0
2020-02-04 03:28:58,514 [INFO] [TezChild] |exec.FileSinkOperator|: New Final
Path: FS
hdfs://cluster/apps/hive/warehouse/sample.db/.hive-staging_hive_2020-02-04_03-10-36_142_570908369342623638-1/_tmp.-ext-10001/001098_0
2020-02-04 03:28:58,533 [INFO] [TezChild] |exec.FileSinkOperator|: FS[7]:
records written - 1
2020-02-04 03:28:58,535 [INFO] [TezChild] |orc.WriterImpl|: WIDE TABLE - Number
of columns: 176 Chosen compression buffer size: 32768
2020-02-04 03:28:58,573 [INFO] [TezChild] |orc.WriterImpl|: ORC writer created
for path:
hdfs://cluster/apps/hive/warehouse/sample.db/.hive-staging_hive_2020-02-04_03-10-36_142_570908369342623638-1/_task_tmp.-ext-10001/_tmp.001098_0
with stripeSize: 67108864 blockSize: 268435456 compression: ZLIB bufferSize:
262144
2020-02-04 03:28:58,599 [INFO] [TezChild] |exec.FileSinkOperator|: FS[7]:
records written - 10
2020-02-04 03:28:58,775 [INFO] [TezChild] |exec.FileSinkOperator|: FS[7]:
records written - 100
2020-02-04 03:28:59,396 [INFO] [TezChild] |exec.FileSinkOperator|: FS[7]:
records written - 1000
{code}
{code:java}
Log of succesfully second attempt
2020-02-04 07:56:51,488 [INFO] [TezChild] |tez.ReduceRecordProcessor|:
<MERGEJOIN>Id =0
<Children>
<SEL>Id =1
<Children>
<FS>Id =2
<Children>
<\Children>
<Parent>Id = 1 null<\Parent>
<\FS>
<\Children>
<Parent>Id = 0 null<\Parent>
<\SEL>
<\Children>
<Parent><\Parent>
<\MERGEJOIN>
2020-02-04 07:56:51,504 [INFO] [TezChild] |log.PerfLogger|: </PERFLOG
method=TezInitializeOperators start=1580792209194 end=1580792211504
duration=2310 from=org.apache.hadoop.hive.ql.exec.tez.RecordProcessor>
2020-02-04 07:56:51,504 [INFO] [TezChild] |tez.ReduceRecordProcessor|: Starting
Output: out_Reducer 2
2020-02-04 07:56:51,506 [WARN] [TezChild]
|objectinspector.StandardStructObjectInspector|: Trying to access 2 fields
inside a list of 1 elements: [[06640113161911]]
2020-02-04 07:56:51,506 [WARN] [TezChild]
|objectinspector.StandardStructObjectInspector|: ignoring similar errors.
2020-02-04 07:56:51,511 [INFO] [TezChild] |exec.FileSinkOperator|: Final Path:
FS
hdfs://cluster/apps/hive/warehouse/sample.db/.hive-staging_hive_2020-02-04_03-10-36_142_570908369342623638-1/_tmp.-ext-10001/001098_1
2020-02-04 07:56:51,511 [INFO] [TezChild] |exec.FileSinkOperator|: Writing to
temp file: FS
hdfs://cluster/apps/hive/warehouse/sample.db/.hive-staging_hive_2020-02-04_03-10-36_142_570908369342623638-1/_task_tmp.-ext-10001/_tmp.001098_1
2020-02-04 07:56:51,511 [INFO] [TezChild] |exec.FileSinkOperator|: New Final
Path: FS
hdfs://cluster/apps/hive/warehouse/sample.db/.hive-staging_hive_2020-02-04_03-10-36_142_570908369342623638-1/_tmp.-ext-10001/001098_1
2020-02-04 07:56:51,542 [INFO] [TezChild] |exec.FileSinkOperator|: FS[2]:
records written - 1
2020-02-04 07:56:51,552 [INFO] [TezChild] |orc.WriterImpl|: WIDE TABLE - Number
of columns: 176 Chosen compression buffer size: 32768
2020-02-04 07:56:51,598 [INFO] [TezChild] |orc.WriterImpl|: ORC writer created
for path:
hdfs://cluster/apps/hive/warehouse/sample.db/.hive-staging_hive_2020-02-04_03-10-36_142_570908369342623638-1/_task_tmp.-ext-10001/_tmp.001098_1
with stripeSize: 67108864 blockSize: 268435456 compression: ZLIB bufferSize:
262144
2020-02-04 07:56:51,611 [INFO] [TezChild] |exec.FileSinkOperator|: FS[2]:
records written - 10
2020-02-04 07:56:51,653 [INFO] [TezChild] |exec.FileSinkOperator|: FS[2]:
records written - 100
2020-02-04 07:56:51,853 [INFO] [TezChild] |exec.FileSinkOperator|: FS[2]:
records written - 1000
2020-02-04 07:56:53,393 [INFO] [TezChild] |exec.FileSinkOperator|: FS[2]:
records written - 10000
2020-02-04 07:57:04,770 [INFO] [TezChild] |exec.FileSinkOperator|: FS[2]:
records written - 100000
2020-02-04 07:58:51,014 [INFO] [TezChild] |exec.FileSinkOperator|: FS[2]:
records written - 1000000
2020-02-04 07:58:56,286 [INFO] [TezChild] |log.PerfLogger|: </PERFLOG
method=TezRunProcessor start=1580792208921 end=1580792336286 duration=127365
from=org.apache.hadoop.hive.ql.exec.tez.TezProcessor>
2020-02-04 07:58:56,286 [INFO] [TezChild] |exec.CommonMergeJoinOperator|:
Closing operator MERGEJOIN[0]
2020-02-04 07:58:56,286 [INFO] [TezChild] |exec.SelectOperator|: Closing
operator SEL[1]
2020-02-04 07:58:56,286 [INFO] [TezChild] |exec.FileSinkOperator|: Closing
operator FS[2]
2020-02-04 07:58:56,286 [INFO] [TezChild] |exec.FileSinkOperator|: FS[2]:
records written - 1040870
2020-02-04 07:58:56,517 [INFO] [TezChild] |exec.FileSinkOperator|:
RECORDS_OUT_1_sample.rpo_current_info_new:1040870,
2020-02-04 07:58:56,517 [INFO] [TezChild] |task.TezTaskRunner|: Closing task,
taskAttemptId=attempt_1579977836338_6440_2_02_001098_1
2020-02-04 07:58:56,517 [INFO] [TezChild] |orderedgrouped.Shuffle|: Shutting
down Shuffle for source: Map_1
2020-02-04 07:58:56,517 [INFO] [TezChild]
|orderedgrouped.ShuffleInputEventHandlerOrderedGrouped|: Map 1:
numDmeEventsSeen=3337, numDmeEventsSeenWithNoData=3336,
numObsoletionEventsSeen=0, updateOnClose
2020-02-04 07:58:56,518 [INFO] [TezChild] |orderedgrouped.Shuffle|: Shutting
down Shuffle for source: Map_3
2020-02-04 07:58:56,518 [INFO] [TezChild]
|orderedgrouped.ShuffleInputEventHandlerOrderedGrouped|: Map 3:
numDmeEventsSeen=194, numDmeEventsSeenWithNoData=193,
numObsoletionEventsSeen=0, updateOnClose
2020-02-04 07:58:56,518 [INFO] [TezChild] |output.MROutput|: out_Reducer 2
closed
2020-02-04 07:58:56,518 [INFO] [TezChild]
|runtime.LogicalIOProcessorRuntimeTask|: Joining on EventRouter
2020-02-04 07:58:56,522 [INFO] [TezChild] |task.TezTaskRunner|: Task completed,
taskAttemptId=attempt_1579977836338_6440_2_02_001098_1, fatalErrorOccurred=false
2020-02-04 07:58:56,528 [INFO] [TezChild]
|runtime.LogicalIOProcessorRuntimeTask|: Final Counters for
attempt_1579977836338_6440_2_02_001098_1: Counters: 98 [[File System Counters
FILE_BYTES_READ=383172873, FILE_BYTES_WRITTEN=386154953,
HDFS_BYTES_WRITTEN=252446634, HDFS_READ_OPS=3, HDFS_WRITE_OPS=3,
HDFS_OP_CREATE=2, HDFS_OP_GET_FILE_STATUS=3,
HDFS_OP_RENAME=1][org.apache.tez.common.counters.TaskCounter
REDUCE_INPUT_GROUPS=1043992, REDUCE_INPUT_RECORDS=1043992,
COMBINE_INPUT_RECORDS=0, SPILLED_RECORDS=1043992, NUM_SHUFFLED_INPUTS=2,
NUM_SKIPPED_INPUTS=3529, NUM_FAILED_SHUFFLE_INPUTS=0, MERGED_MAP_OUTPUTS=2,
GC_TIME_MILLIS=686, CPU_MILLISECONDS=156620, PHYSICAL_MEMORY_BYTES=2147483648,
VIRTUAL_MEMORY_BYTES=5494951936, COMMITTED_HEAP_BYTES=2147483648,
OUTPUT_RECORDS=0, ADDITIONAL_SPILLS_BYTES_WRITTEN=1468064,
ADDITIONAL_SPILLS_BYTES_READ=383172873, SHUFFLE_BYTES=383172873,
SHUFFLE_BYTES_DECOMPRESSED=1487594202, SHUFFLE_BYTES_TO_MEM=1468064,
SHUFFLE_BYTES_TO_DISK=381704809, SHUFFLE_BYTES_DISK_DIRECT=0,
NUM_MEM_TO_DISK_MERGES=0, NUM_DISK_TO_DISK_MERGES=0, SHUFFLE_PHASE_TIME=2574,
MERGE_PHASE_TIME=2649, FIRST_EVENT_RECEIVED=49, LAST_EVENT_RECEIVED=318][HIVE
CREATED_FILES=1, RECORDS_OUT_1_sample.rpo_current_info_new=1040870][Shuffle
Errors BAD_ID=0, CONNECTION=0, IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0,
WRONG_REDUCE=0][Shuffle Errors_Reducer_2_INPUT_Map_1 BAD_ID=0, CONNECTION=0,
IO_ERROR=0, WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0][Shuffle
Errors_Reducer_2_INPUT_Map_3 BAD_ID=0, CONNECTION=0, IO_ERROR=0,
WRONG_LENGTH=0, WRONG_MAP=0, WRONG_REDUCE=0][TaskCounter_Reducer_2_INPUT_Map_1
ADDITIONAL_SPILLS_BYTES_READ=381704809, ADDITIONAL_SPILLS_BYTES_WRITTEN=0,
COMBINE_INPUT_RECORDS=0, FIRST_EVENT_RECEIVED=28, LAST_EVENT_RECEIVED=185,
MERGED_MAP_OUTPUTS=1, MERGE_PHASE_TIME=2348, NUM_DISK_TO_DISK_MERGES=0,
NUM_FAILED_SHUFFLE_INPUTS=0, NUM_MEM_TO_DISK_MERGES=0, NUM_SHUFFLED_INPUTS=1,
NUM_SKIPPED_INPUTS=3336, REDUCE_INPUT_GROUPS=1040125,
REDUCE_INPUT_RECORDS=1040125, SHUFFLE_BYTES=381704809,
SHUFFLE_BYTES_DECOMPRESSED=1481826651, SHUFFLE_BYTES_DISK_DIRECT=0,
SHUFFLE_BYTES_TO_DISK=381704809, SHUFFLE_BYTES_TO_MEM=0,
SHUFFLE_PHASE_TIME=2343,
SPILLED_RECORDS=1040125][TaskCounter_Reducer_2_INPUT_Map_3
ADDITIONAL_SPILLS_BYTES_READ=1468064, ADDITIONAL_SPILLS_BYTES_WRITTEN=1468064,
COMBINE_INPUT_RECORDS=0, FIRST_EVENT_RECEIVED=21, LAST_EVENT_RECEIVED=133,
MERGED_MAP_OUTPUTS=1, MERGE_PHASE_TIME=301, NUM_DISK_TO_DISK_MERGES=0,
NUM_FAILED_SHUFFLE_INPUTS=0, NUM_MEM_TO_DISK_MERGES=0, NUM_SHUFFLED_INPUTS=1,
NUM_SKIPPED_INPUTS=193, REDUCE_INPUT_GROUPS=3867, REDUCE_INPUT_RECORDS=3867,
SHUFFLE_BYTES=1468064, SHUFFLE_BYTES_DECOMPRESSED=5767551,
SHUFFLE_BYTES_DISK_DIRECT=0, SHUFFLE_BYTES_TO_DISK=0,
SHUFFLE_BYTES_TO_MEM=1468064, SHUFFLE_PHASE_TIME=231,
SPILLED_RECORDS=3867][TaskCounter_Reducer_2_OUTPUT_out_Reducer_2
OUTPUT_RECORDS=0]]
2020-02-04 07:58:56,630 [INFO] [main] |common.TezUtilsInternal|: Redirecting
log file based on addend:
{code}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
