You are viewing a plain text version of this content. The canonical link for it is here.
Posted to hdfs-dev@hadoop.apache.org by "Namit Maheshwari (JIRA)" <ji...@apache.org> on 2018/10/18 02:55:00 UTC
[jira] [Created] (HDDS-688) Hive Query hangs, if DN's are restarted
before the query is submitted
Namit Maheshwari created HDDS-688:
-------------------------------------
Summary: Hive Query hangs, if DN's are restarted before the query is submitted
Key: HDDS-688
URL: https://issues.apache.org/jira/browse/HDDS-688
Project: Hadoop Distributed Data Store
Issue Type: Bug
Reporter: Namit Maheshwari
Run a Hive Insert Query. It runs fine as below:
{code:java}
0: jdbc:hive2://ctr-e138-1518143905142-510793> insert into testo3 values(1, "aa", 3.0);
INFO : Compiling command(queryId=hive_20181018005729_fe644ab2-f8cc-41c3-b2d8-ffe1022de607): insert into testo3 values(1, "aa", 3.0)
INFO : Semantic Analysis Completed (retrial = false)
INFO : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:_col0, type:int, comment:null), FieldSchema(name:_col1, type:string, comment:null), FieldSchema(name:_col2, type:float, comment:null)], properties:null)
INFO : Completed compiling command(queryId=hive_20181018005729_fe644ab2-f8cc-41c3-b2d8-ffe1022de607); Time taken: 0.52 seconds
INFO : Executing command(queryId=hive_20181018005729_fe644ab2-f8cc-41c3-b2d8-ffe1022de607): insert into testo3 values(1, "aa", 3.0)
INFO : Query ID = hive_20181018005729_fe644ab2-f8cc-41c3-b2d8-ffe1022de607
INFO : Total jobs = 1
INFO : Launching Job 1 out of 1
INFO : Starting task [Stage-1:MAPRED] in serial mode
INFO : Subscribed to counters: [] for queryId: hive_20181018005729_fe644ab2-f8cc-41c3-b2d8-ffe1022de607
INFO : Session is already open
INFO : Dag name: insert into testo3 values(1, "aa", 3.0) (Stage-1)
INFO : Status: Running (Executing on YARN cluster with App id application_1539383731490_0073)
----------------------------------------------------------------------------------------------
VERTICES MODE STATUS TOTAL COMPLETED RUNNING PENDING FAILED KILLED
----------------------------------------------------------------------------------------------
Map 1 .......... container SUCCEEDED 1 1 0 0 0 0
Reducer 2 ...... container SUCCEEDED 1 1 0 0 0 0
----------------------------------------------------------------------------------------------
VERTICES: 02/02 [==========================>>] 100% ELAPSED TIME: 11.95 s
----------------------------------------------------------------------------------------------
INFO : Status: DAG finished successfully in 10.68 seconds
INFO :
INFO : Query Execution Summary
INFO : ----------------------------------------------------------------------------------------------
INFO : OPERATION DURATION
INFO : ----------------------------------------------------------------------------------------------
INFO : Compile Query 0.52s
INFO : Prepare Plan 0.23s
INFO : Get Query Coordinator (AM) 0.00s
INFO : Submit Plan 0.11s
INFO : Start DAG 0.57s
INFO : Run DAG 10.68s
INFO : ----------------------------------------------------------------------------------------------
INFO :
INFO : Task Execution Summary
INFO : ----------------------------------------------------------------------------------------------
INFO : VERTICES DURATION(ms) CPU_TIME(ms) GC_TIME(ms) INPUT_RECORDS OUTPUT_RECORDS
INFO : ----------------------------------------------------------------------------------------------
INFO : Map 1 7074.00 11,280 276 3 1
INFO : Reducer 2 1074.00 2,040 0 1 0
INFO : ----------------------------------------------------------------------------------------------
INFO :
INFO : org.apache.tez.common.counters.DAGCounter:
INFO : NUM_SUCCEEDED_TASKS: 2
INFO : TOTAL_LAUNCHED_TASKS: 2
INFO : AM_CPU_MILLISECONDS: 1390
INFO : AM_GC_TIME_MILLIS: 0
INFO : File System Counters:
INFO : FILE_BYTES_READ: 135
INFO : FILE_BYTES_WRITTEN: 135
INFO : HDFS_BYTES_WRITTEN: 199
INFO : HDFS_READ_OPS: 3
INFO : HDFS_WRITE_OPS: 2
INFO : HDFS_OP_CREATE: 1
INFO : HDFS_OP_GET_FILE_STATUS: 3
INFO : HDFS_OP_RENAME: 1
INFO : org.apache.tez.common.counters.TaskCounter:
INFO : SPILLED_RECORDS: 0
INFO : NUM_SHUFFLED_INPUTS: 1
INFO : NUM_FAILED_SHUFFLE_INPUTS: 0
INFO : GC_TIME_MILLIS: 276
INFO : TASK_DURATION_MILLIS: 8474
INFO : CPU_MILLISECONDS: 13320
INFO : PHYSICAL_MEMORY_BYTES: 4294967296
INFO : VIRTUAL_MEMORY_BYTES: 11205029888
INFO : COMMITTED_HEAP_BYTES: 4294967296
INFO : INPUT_RECORDS_PROCESSED: 5
INFO : INPUT_SPLIT_LENGTH_BYTES: 1
INFO : OUTPUT_RECORDS: 1
INFO : OUTPUT_LARGE_RECORDS: 0
INFO : OUTPUT_BYTES: 94
INFO : OUTPUT_BYTES_WITH_OVERHEAD: 102
INFO : OUTPUT_BYTES_PHYSICAL: 127
INFO : ADDITIONAL_SPILLS_BYTES_WRITTEN: 0
INFO : ADDITIONAL_SPILLS_BYTES_READ: 0
INFO : ADDITIONAL_SPILL_COUNT: 0
INFO : SHUFFLE_BYTES: 103
INFO : SHUFFLE_BYTES_DECOMPRESSED: 102
INFO : SHUFFLE_BYTES_TO_MEM: 0
INFO : SHUFFLE_BYTES_TO_DISK: 0
INFO : SHUFFLE_BYTES_DISK_DIRECT: 103
INFO : SHUFFLE_PHASE_TIME: 154
INFO : FIRST_EVENT_RECEIVED: 108
INFO : LAST_EVENT_RECEIVED: 108
INFO : HIVE:
INFO : CREATED_FILES: 2
INFO : DESERIALIZE_ERRORS: 0
INFO : RECORDS_IN_Map_1: 3
INFO : RECORDS_OUT_0: 1
INFO : RECORDS_OUT_1_default.testo3: 1
INFO : RECORDS_OUT_INTERMEDIATE_Map_1: 1
INFO : RECORDS_OUT_INTERMEDIATE_Reducer_2: 0
INFO : RECORDS_OUT_OPERATOR_FS_12: 1
INFO : RECORDS_OUT_OPERATOR_FS_5: 1
INFO : RECORDS_OUT_OPERATOR_GBY_10: 1
INFO : RECORDS_OUT_OPERATOR_GBY_8: 1
INFO : RECORDS_OUT_OPERATOR_MAP_0: 0
INFO : RECORDS_OUT_OPERATOR_RS_9: 1
INFO : RECORDS_OUT_OPERATOR_SEL_1: 1
INFO : RECORDS_OUT_OPERATOR_SEL_3: 1
INFO : RECORDS_OUT_OPERATOR_SEL_7: 1
INFO : RECORDS_OUT_OPERATOR_TS_0: 1
INFO : RECORDS_OUT_OPERATOR_UDTF_2: 1
INFO : TaskCounter_Map_1_INPUT__dummy_table:
INFO : INPUT_RECORDS_PROCESSED: 4
INFO : INPUT_SPLIT_LENGTH_BYTES: 1
INFO : TaskCounter_Map_1_OUTPUT_Reducer_2:
INFO : ADDITIONAL_SPILLS_BYTES_READ: 0
INFO : ADDITIONAL_SPILLS_BYTES_WRITTEN: 0
INFO : ADDITIONAL_SPILL_COUNT: 0
INFO : OUTPUT_BYTES: 94
INFO : OUTPUT_BYTES_PHYSICAL: 127
INFO : OUTPUT_BYTES_WITH_OVERHEAD: 102
INFO : OUTPUT_LARGE_RECORDS: 0
INFO : OUTPUT_RECORDS: 1
INFO : SPILLED_RECORDS: 0
INFO : TaskCounter_Reducer_2_INPUT_Map_1:
INFO : FIRST_EVENT_RECEIVED: 108
INFO : INPUT_RECORDS_PROCESSED: 1
INFO : LAST_EVENT_RECEIVED: 108
INFO : NUM_FAILED_SHUFFLE_INPUTS: 0
INFO : NUM_SHUFFLED_INPUTS: 1
INFO : SHUFFLE_BYTES: 103
INFO : SHUFFLE_BYTES_DECOMPRESSED: 102
INFO : SHUFFLE_BYTES_DISK_DIRECT: 103
INFO : SHUFFLE_BYTES_TO_DISK: 0
INFO : SHUFFLE_BYTES_TO_MEM: 0
INFO : SHUFFLE_PHASE_TIME: 154
INFO : TaskCounter_Reducer_2_OUTPUT_out_Reducer_2:
INFO : OUTPUT_RECORDS: 0
INFO : Starting task [Stage-2:DEPENDENCY_COLLECTION] in serial mode
INFO : Starting task [Stage-0:MOVE] in serial mode
INFO : Loading data to table default.testo3 from o3fs://bucket2.volume2/testo3/.hive-staging_hive_2018-10-18_00-57-29_750_2488867853984287387-1/-ext-10000
INFO : Starting task [Stage-3:STATS] in serial mode
INFO : Completed executing command(queryId=hive_20181018005729_fe644ab2-f8cc-41c3-b2d8-ffe1022de607); Time taken: 12.797 seconds
INFO : OK
No rows affected (13.366 seconds)
0: jdbc:hive2://ctr-e138-1518143905142-510793> select * from testo3;
INFO : Compiling command(queryId=hive_20181018005748_377d67c0-cfec-431f-af03-a93f443be5f4): select * from testo3
INFO : Semantic Analysis Completed (retrial = false)
INFO : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:testo3.i, type:int, comment:null), FieldSchema(name:testo3.s, type:string, comment:null), FieldSchema(name:testo3.d, type:float, comment:null)], properties:null)
INFO : Completed compiling command(queryId=hive_20181018005748_377d67c0-cfec-431f-af03-a93f443be5f4); Time taken: 0.244 seconds
INFO : Executing command(queryId=hive_20181018005748_377d67c0-cfec-431f-af03-a93f443be5f4): select * from testo3
INFO : Completed executing command(queryId=hive_20181018005748_377d67c0-cfec-431f-af03-a93f443be5f4); Time taken: 0.013 seconds
INFO : OK
+--------------+--------------+--------------+
| testo3.i | testo3.s | testo3.d |
+--------------+--------------+--------------+
| 2 | aa | 3.0 |
| 2 | aa | 3.0 |
| 1 | aa | 3.0 |
+--------------+--------------+--------------+
3 rows selected (0.404 seconds)
{code}
Now shutdown the DN's on all the hosts.
Wait for three minutes. Start the DN's back. And submit the insert query again. It hangs forever:
{code:java}
0: jdbc:hive2://ctr-e138-1518143905142-510793> insert into testo3 values(5, "aa", 3.0);
INFO : Compiling command(queryId=hive_20181018011035_f474bd97-b06a-41f4-86da-84572a3e5892): insert into testo3 values(5, "aa", 3.0)
INFO : Semantic Analysis Completed (retrial = false)
INFO : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:_col0, type:int, comment:null), FieldSchema(name:_col1, type:string, comment:null), FieldSchema(name:_col2, type:float, comment:null)], properties:null)
INFO : Completed compiling command(queryId=hive_20181018011035_f474bd97-b06a-41f4-86da-84572a3e5892); Time taken: 0.67 seconds
INFO : Executing command(queryId=hive_20181018011035_f474bd97-b06a-41f4-86da-84572a3e5892): insert into testo3 values(5, "aa", 3.0)
INFO : Query ID = hive_20181018011035_f474bd97-b06a-41f4-86da-84572a3e5892
INFO : Total jobs = 1
INFO : Launching Job 1 out of 1
INFO : Starting task [Stage-1:MAPRED] in serial mode
INFO : Subscribed to counters: [] for queryId: hive_20181018011035_f474bd97-b06a-41f4-86da-84572a3e5892
INFO : Session is already open
INFO : Dag name: insert into testo3 values(5, "aa", 3.0) (Stage-1)
INFO : Tez session was closed. Reopening...
INFO : Session re-established.
INFO : Session re-established.
INFO : Status: Running (Executing on YARN cluster with App id application_1539383731490_0074)
----------------------------------------------------------------------------------------------
VERTICES MODE STATUS TOTAL COMPLETED RUNNING PENDING FAILED KILLED
----------------------------------------------------------------------------------------------
Map 1 container RUNNING 1 0 1 0 0 0
Reducer 2 container INITED 1 0 0 1 0 0
----------------------------------------------------------------------------------------------
VERTICES: 00/02 [>>--------------------------] 0% ELAPSED TIME: 879.84 s
----------------------------------------------------------------------------------------------
{code}
SCM logs:
{code:java}
2018-10-18 01:05:11,589 INFO org.apache.hadoop.ozone.protocol.commands.RetriableDatanodeEventWatcher: RetriableDatanodeCommand type=deleteBlocksCommand with id=1539822251724 timed out. Retrying. 2018-10-18 01:06:09,757 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74. 2018-10-18 01:06:09,757 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: Finalizing pipeline. pipelineID: pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 2018-10-18 01:06:09,757 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 6 2018-10-18 01:06:09,758 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 8 2018-10-18 01:06:09,759 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 10 2018-10-18 01:06:09,759 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 12 2018-10-18 01:06:09,760 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 14 2018-10-18 01:06:09,761 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 16 2018-10-18 01:06:09,761 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 1 2018-10-18 01:06:09,762 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 18 2018-10-18 01:06:09,762 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 4 2018-10-18 01:06:09,762 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 20 2018-10-18 01:06:11,591 INFO org.apache.hadoop.ozone.protocol.commands.RetriableDatanodeEventWatcher: RetriableDatanodeCommand type=deleteBlocksCommand with id=1539822251725 timed out. Retrying. 2018-10-18 01:06:12,757 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74. 2018-10-18 01:06:12,757 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74. 2018-10-18 01:07:11,593 INFO org.apache.hadoop.ozone.protocol.commands.RetriableDatanodeEventWatcher: RetriableDatanodeCommand type=deleteBlocksCommand with id=1539822251726 timed out. Retrying. 2018-10-18 01:08:11,596 INFO org.apache.hadoop.ozone.protocol.commands.RetriableDatanodeEventWatcher: RetriableDatanodeCommand type=deleteBlocksCommand with id=1539822251727 timed out. Retrying. 2018-10-18 01:09:41,597 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID mismatch in datanode 77e36898-91b2-4a81-92ec-a285781b5235 for containerID 3. Datanode delete txnID: 0, SCM txnID: 1 2018-10-18 01:09:43,500 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,501 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,501 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,501 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,501 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,501 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,501 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,501 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,501 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,502 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,502 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,502 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,502 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:43,502 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Delete txID 1 not found 2018-10-18 01:09:48,073 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: Closing pipeline. pipelineID: pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 2018-10-18 01:10:11,608 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Totally added 6 delete blocks command for 3 datanodes, task elapsed time: 2ms 2018-10-18 01:10:13,652 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed. Corresponding entry not found. 2018-10-18 01:10:13,652 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed. Corresponding entry not found. 2018-10-18 01:10:13,652 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed. Corresponding entry not found. 2018-10-18 01:10:13,652 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed. Corresponding entry not found. 2018-10-18 01:10:13,653 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed. Corresponding entry not found. 2018-10-18 01:10:13,653 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed. Corresponding entry not found. 2018-10-18 01:10:13,653 WARN org.apache.hadoop.hdds.scm.block.DeletedBlockLogImpl: Transaction txId=1 commit by dnId=77e36898-91b2-4a81-92ec-a285781b5235 for containerID=3 failed. Corresponding entry not found. 2018-10-18 01:10:19,824 WARN org.apache.hadoop.hdds.server.events.EventWatcher: Completion event without active lease. Id=4 2018-10-18 01:10:19,824 WARN org.apache.hadoop.hdds.server.events.EventWatcher: Completion event without active lease. Id=6 2018-10-18 01:10:19,824 WARN org.apache.hadoop.hdds.server.events.EventWatcher: Completion event without active lease. Id=8 2018-10-18 01:10:19,824 WARN org.apache.hadoop.hdds.server.events.EventWatcher: Completion event without active lease. Id=10 2018-10-18 01:10:52,281 INFO org.apache.hadoop.hdds.scm.pipelines.ratis.RatisManagerImpl: Allocating a new ratis pipeline of size: 3 id: pipelineId=bc3e8eb4-a680-40fb-b85b-5382a2b56560 2018-10-18 01:10:52,390 INFO org.apache.hadoop.hdds.scm.pipelines.ratis.RatisManagerImpl: Allocating a new ratis pipeline of size: 3 id: pipelineId=7c393f6d-2c31-448d-9f40-0eb4f0c628b4 2018-10-18 01:11:43,494 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 120899ms 2018-10-18 01:11:58,403 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 120187ms 2018-10-18 01:12:13,486 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 129851ms 2018-10-18 01:12:18,792 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: closing pipeline pipelineId=bc3e8eb4-a680-40fb-b85b-5382a2b56560. 2018-10-18 01:12:18,793 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: Finalizing pipeline. pipelineID: pipelineId=bc3e8eb4-a680-40fb-b85b-5382a2b56560 2018-10-18 01:12:18,793 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 38 2018-10-18 01:12:18,794 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 24 2018-10-18 01:12:18,794 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 40 2018-10-18 01:12:18,794 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 26 2018-10-18 01:12:18,795 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 28 2018-10-18 01:12:18,795 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 30 2018-10-18 01:12:18,795 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 32 2018-10-18 01:12:18,795 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 34 2018-10-18 01:12:18,796 INFO org.apache.hadoop.hdds.scm.container.CloseContainerEventHandler: Close container Event triggered for container : 36 2018-10-18 01:12:21,793 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: closing pipeline pipelineId=bc3e8eb4-a680-40fb-b85b-5382a2b56560. 2018-10-18 01:12:28,399 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 129066ms 2018-10-18 01:12:43,483 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 160331ms 2018-10-18 01:12:58,398 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 158856ms 2018-10-18 01:13:13,481 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 190378ms 2018-10-18 01:13:18,877 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineSelector: Closing pipeline. pipelineID: pipelineId=bc3e8eb4-a680-40fb-b85b-5382a2b56560 2018-10-18 01:13:28,406 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 189518ms 2018-10-18 01:13:28,407 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=bc3e8eb4-a680-40fb-b85b-5382a2b56560 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 121129ms 2018-10-18 01:13:43,479 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 219451ms 2018-10-18 01:13:58,399 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 219784ms 2018-10-18 01:14:13,476 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 249410ms 2018-10-18 01:14:28,401 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 249460ms 2018-10-18 01:14:43,497 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 279759ms 2018-10-18 01:14:58,403 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 279756ms 2018-10-18 01:15:13,473 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 310306ms 2018-10-18 01:15:28,401 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 308983ms 2018-10-18 01:15:43,481 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 339323ms 2018-10-18 01:15:58,399 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 339037ms 2018-10-18 01:16:13,486 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 369335ms 2018-10-18 01:16:28,409 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 368800ms 2018-10-18 01:16:43,489 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 400142ms 2018-10-18 01:16:58,400 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 399306ms 2018-10-18 01:17:13,496 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 429758ms 2018-10-18 01:17:28,399 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 429533ms 2018-10-18 01:17:43,495 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 460167ms 2018-10-18 01:17:58,399 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 459247ms 2018-10-18 01:18:13,495 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 490224ms 2018-10-18 01:18:28,403 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 489329ms 2018-10-18 01:18:43,500 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 519788ms 2018-10-18 01:18:58,400 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 519200ms 2018-10-18 01:19:13,499 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 550393ms 2018-10-18 01:19:28,404 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 549081ms 2018-10-18 01:19:43,501 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 579560ms 2018-10-18 01:19:58,401 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 579204ms 2018-10-18 01:20:13,499 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 610467ms 2018-10-18 01:20:28,400 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 609169ms 2018-10-18 01:20:43,498 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 639947ms 2018-10-18 01:20:48,819 INFO org.apache.hadoop.hdds.scm.node.DeadNodeHandler: Datanode 41636d6e-31cc-419b-bd8d-1a7e5e7d7edd is dead. Removing replications from the in-memory state. 2018-10-18 01:20:51,819 INFO org.apache.hadoop.hdds.scm.node.DeadNodeHandler: Datanode 69d15283-4e2e-4c30-a028-f2bad0f83cc1 is dead. Removing replications from the in-memory state. 2018-10-18 01:20:58,401 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 639148ms 2018-10-18 01:21:13,498 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 670081ms 2018-10-18 01:21:27,978 WARN org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered for event TypedEvent{payloadType=ReplicationStatus, name='Replicate_Command_Status'} 2018-10-18 01:21:28,402 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 669044ms 2018-10-18 01:21:28,594 WARN org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered for event TypedEvent{payloadType=ReplicationStatus, name='Replicate_Command_Status'} 2018-10-18 01:21:28,594 WARN org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered for event TypedEvent{payloadType=ReplicationStatus, name='Replicate_Command_Status'} 2018-10-18 01:21:28,594 WARN org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered for event TypedEvent{payloadType=ReplicationStatus, name='Replicate_Command_Status'} 2018-10-18 01:21:43,498 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 700237ms 2018-10-18 01:21:43,498 WARN org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered for event TypedEvent{payloadType=ReplicationStatus, name='Replicate_Command_Status'} 2018-10-18 01:21:43,498 WARN org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered for event TypedEvent{payloadType=ReplicationStatus, name='Replicate_Command_Status'} 2018-10-18 01:21:44,737 WARN org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered for event TypedEvent{payloadType=ReplicationStatus, name='Replicate_Command_Status'} 2018-10-18 01:21:46,602 WARN org.apache.hadoop.hdds.server.events.EventQueue: No event handler registered for event TypedEvent{payloadType=ReplicationStatus, name='Replicate_Command_Status'} 2018-10-18 01:21:46,603 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID mismatch in datanode 9643667a-b951-416c-a934-7bec1972651e for containerID 10. Datanode delete txnID: 0, SCM txnID: 3 2018-10-18 01:21:57,972 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID mismatch in datanode f3ffc98c-f7d1-4831-be64-bf44a602019a for containerID 6. Datanode delete txnID: 0, SCM txnID: 2 2018-10-18 01:21:58,404 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 699691ms 2018-10-18 01:21:58,589 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID mismatch in datanode 11bbe903-0434-4827-9d2a-3f13fd9d3799 for containerID 10. Datanode delete txnID: 0, SCM txnID: 3 2018-10-18 01:22:13,500 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 729913ms 2018-10-18 01:22:28,403 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 729239ms ^[[B^[[B^[[A2018-10-18 01:22:43,501 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 760211ms 2018-10-18 01:22:44,733 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID mismatch in datanode 93a33804-d0b9-4adf-b39b-e1c190be9c32 for containerID 6. Datanode delete txnID: 0, SCM txnID: 2 2018-10-18 01:22:58,401 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 758951ms 2018-10-18 01:22:58,585 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID mismatch in datanode 11bbe903-0434-4827-9d2a-3f13fd9d3799 for containerID 10. Datanode delete txnID: 0, SCM txnID: 3 2018-10-18 01:23:13,503 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 790104ms 2018-10-18 01:23:16,600 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID mismatch in datanode 9643667a-b951-416c-a934-7bec1972651e for containerID 10. Datanode delete txnID: 0, SCM txnID: 3 2018-10-18 01:23:28,032 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID mismatch in datanode f3ffc98c-f7d1-4831-be64-bf44a602019a for containerID 6. Datanode delete txnID: 0, SCM txnID: 2 2018-10-18 01:23:28,401 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 789426ms 2018-10-18 01:23:43,506 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 819373ms 2018-10-18 01:23:58,401 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 819308ms 2018-10-18 01:24:13,512 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 850302ms 2018-10-18 01:24:28,400 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 849243ms 2018-10-18 01:24:28,579 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID mismatch in datanode 11bbe903-0434-4827-9d2a-3f13fd9d3799 for containerID 10. Datanode delete txnID: 0, SCM txnID: 3 2018-10-18 01:24:43,513 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 879865ms 2018-10-18 01:24:44,734 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID mismatch in datanode 93a33804-d0b9-4adf-b39b-e1c190be9c32 for containerID 6. Datanode delete txnID: 0, SCM txnID: 2 2018-10-18 01:24:46,604 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID mismatch in datanode 9643667a-b951-416c-a934-7bec1972651e for containerID 10. Datanode delete txnID: 0, SCM txnID: 3 2018-10-18 01:24:57,978 INFO org.apache.hadoop.hdds.scm.block.SCMBlockDeletingService: Block deletion txnID mismatch in datanode f3ffc98c-f7d1-4831-be64-bf44a602019a for containerID 6. Datanode delete txnID: 0, SCM txnID: 2 2018-10-18 01:24:58,400 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=ba0b9d2c-ba94-443d-a784-80012dd9fe74 for reason:a698a509-0816-4719-9a0f-36d1b503c249 is in candidate state for 879492ms 2018-10-18 01:25:13,517 INFO org.apache.hadoop.hdds.scm.pipelines.PipelineActionEventHandler: Closing pipeline pipelineId=43e3d4a3-3364-4eac-960c-154d2d974d32 for reason:77e36898-91b2-4a81-92ec-a285781b5235 is in candidate state for 910432ms{code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: hdfs-dev-unsubscribe@hadoop.apache.org
For additional commands, e-mail: hdfs-dev-help@hadoop.apache.org